tea --magic is slow 🐢 when run in shell startup

[vegerot]

tea --magic adds about 100ms of extra latency to my shell startup, which is a lot to me c:

❯ hyperfine --warmup=3 "~/.tea/tea.xyz/v0.21.0/bin/tea --magic"
Benchmark 1: ~/.tea/tea.xyz/v0.21.0/bin/tea --magic
  Time (mean ± σ):     157.7 ms ±  60.6 ms    [User: 97.5 ms, System: 22.9 ms]
  Range (min … max):   103.6 ms … 345.7 ms    25 runs

If I may give my 2¢, while I'm as big a Deno lover as the next guy it's just not suitable for the sub-100ms startup times maniacs like myself crave for our terminal.

As a best-case scenario I measured the fastest possible time the magic could run

#!/usr/bin/env deno run
// magic.ts
console.log(`add-zsh-hook -Uz chpwd() {
  if [ "\${TEA_MAGIC:-}" != 0 -a -x "/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea ]; then
    source <("/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea +tea.xyz/magic -Esk --chaste env)
  fi
}

# if the user put tea in eg. /usr/local/bin then don’t pollute their PATH
if ! tea --prefix 2>&1 >/dev/null; then
  export PATH="/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin:$PATH"
fi

function command_not_found_handler {
  if [ "\${TEA_MAGIC:-}" != 0 -a -x "/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea ]; then
    "/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea -- $*
  fi
}
`)

❯ hyperfine --warmup=3 ./magic.ts
Benchmark 1: ./magic.ts
  Time (mean ± σ):      63.6 ms ±   7.6 ms    [User: 37.2 ms, System: 17.8 ms]
  Range (min … max):    57.3 ms …  88.6 ms    40 runs

compared to something like

package main
// magic.go

import "fmt"

func main() {
	fmt.Println(
		`add-zsh-hook -Uz chpwd() {
  if [ "${TEA_MAGIC:-}" != 0 -a -x "/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea ]; then
    source <("/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea +tea.xyz/magic -Esk --chaste env)
  fi
}

# if the user put tea in eg. /usr/local/bin then don’t pollute their PATH
if ! tea --prefix 2>&1 >/dev/null; then
  export PATH="/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin:$PATH" fi

function command_not_found_handler {
  if [ "${TEA_MAGIC:-}" != 0 -a -x "/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea ]; then
    "/Users/m0c0j7y/.tea/tea.xyz/v0.21.0/bin"/tea -- $*
  fi
}`)
}

❯ hyperfine --warmup=3 ./magic
Benchmark 1: ./magic
  Time (mean ± σ):      10.5 ms ±   9.2 ms    [User: 1.5 ms, System: 3.0 ms]
  Range (min … max):     0.0 ms …  36.9 ms    160 runs

  Warning: Command took less than 5 ms to complete. Note that the results might be inaccurate because hyperfine can not calibrate the shell startup time much more precise than this limit. You can try to use the `-N`/`--shell=none` option to disable the shell completely.

The difference is even starker when run "e2e"

[vegerot]

possible solutions:

1. Cache the output of tea --magic in some file and update the shell one-liner into a two-liner (🤢 amirite?) to use that file if it exists

[mxcl]

Yeah 100ms is not acceptable for sure. Once we are 1.0.0 I plan to rewrite in Rust. But until then deno is much faster for dev.

Having said this, I'm surprised it is this much since --magic is a pretty hot path.

I can see a few quick fixes, make tea a shell script that handles some of the options fast and then delegates the rest. Unfortunately shell magic involves calling tea so that is every cd. Possibly we could cache that though.

I'll give it some thought. Thanks for the (very) detailed report!

[vegerot]

Thank you! btw when including zsh start time the difference is even more dramatic

[lino-levan]

Deno recently merged a PR to allow for snapshotting of ES modules (denoland/deno#17460). When/if this gets extended for use in deno compile, we should see a pretty hefty perf improvement. In my (rather limited) understanding, it essentially converts typescript from a JIT language to a compiled language by doing the compile step ahead of time.

While this obviously will not "solve" the problem of typescript being slower than rust, it should alleviate a lot of the pain for users in the mean-time.

[mxcl]

That's good news. If we can get startup down 50% - 80% then a rewrite in rust may never be necessary.

[jhheider]

there's always the option of shipping a second binary. tea --magic --silent is, as you say, a hot path. writing it in Rust and shipping {{prefix}}/bin/tea-magic is probably quite easy, if it's a big win for responsiveness.

[jhheider]

pure rust is a slight improvement:

$ hyperfine --warmup=3 "tea --magic" 
Benchmark 1: tea --magic
  Time (mean ± σ):      47.5 ms ±   1.3 ms    [User: 43.3 ms, System: 3.4 ms]
  Range (min … max):    46.2 ms …  53.8 ms    60 runs
 
$ hyperfine --warmup=3 "./tea-magic zsh"
Benchmark 1: ./tea-magic zsh
  Time (mean ± σ):       0.6 ms ±   0.5 ms    [User: 0.3 ms, System: 0.2 ms]
  Range (min … max):     0.2 ms …   9.4 ms    1084 runs
 
  Warning: Command took less than 5 ms to complete. Note that the results might be inaccurate because hyperfine can not calibrate the shell startup time much more precise than this limit. You can try to use the `-N`/`--shell=none` option to disable the shell completely.
  Warning: Statistical outliers were detected. Consider re-running this benchmark on a quiet PC without any interferences from other programs. It might help to use the '--warmup' or '--prepare' options.

[jhheider]

zsh startup adds a fair bit. I believe it's sourceing the functions:

$ hyperfine --warmup=3 'zsh -c "source <(./tea-magic zsh)"'
Benchmark 1: zsh -c "source <(./tea-magic zsh)"
  Time (mean ± σ):      51.1 ms ±   1.2 ms    [User: 44.1 ms, System: 5.2 ms]
  Range (min … max):    50.0 ms …  59.1 ms    56 runs

$ hyperfine --warmup=3 'zsh -c "echo hi"'
Benchmark 1: zsh -c "echo hi"
  Time (mean ± σ):       1.6 ms ±   0.8 ms    [User: 0.4 ms, System: 0.6 ms]
  Range (min … max):     1.0 ms …  10.5 ms    680 runs

$ hyperfine --warmup=3 'zsh -c "source <(env)"'
Benchmark 1: zsh -c "source <(env)"
  Time (mean ± σ):       5.6 ms ±   0.9 ms    [User: 1.0 ms, System: 3.7 ms]
  Range (min … max):     5.0 ms …  19.9 ms    336 runs

[mxcl]

seems like maybe deno gave us a speed up?

$ time tea --magic
_tea_chpwd_hook() {
  if [ "${TEA_MAGIC:-}" != 0 -a -x "/usr/local/bin"/tea ]; then
    source <("/usr/local/bin"/tea +tea.xyz/magic -Esk --chaste env)
  fi
}

typeset -ag chpwd_functions

if [[ -z "${chpwd_functions[(r)_tea_hook]+1}" ]]; then
  chpwd_functions=( _tea_chpwd_hook ${chpwd_functions[@]} )
fi

if [[ "$PATH" != *"$HOME/.local/bin"* ]]; then
  export PATH="$HOME/.local/bin:$PATH"
fi

if ! command -v tea 2>&1 >/dev/null || ! tea --prefix 2>&1 >/dev/null; then
  export PATH="/usr/local/bin:$PATH"
fi

function command_not_found_handler {
  if [ "${TEA_MAGIC:-}" != 0 -a -x "/usr/local/bin"/tea ]; then
    "/usr/local/bin"/tea -- $*
  fi
}
tea --magic  0.06s user 0.01s system 98% cpu 0.074 total

[jhheider]

$ hyperfine --warmup=3 'zsh -c "source <(tea --magic=zsh)"'
installed: ~/.tea/crates.io/hyperfine/v1.16.1
Benchmark 1: zsh -c "source <(tea --magic=zsh)"
  Time (mean ± σ):     109.2 ms ±   2.0 ms    [User: 95.7 ms, System: 12.6 ms]
  Range (min … max):   107.3 ms … 114.9 ms    27 runs

That looks like we might be twice as fast as we used to.

[vegerot]

Not on my machine. No statistical difference

❯ hyperfine --warmup=3 "zsh -c 'source <(~/.tea/tea.xyz/v0.21.0/bin/tea --magic=zsh)'"  "zsh -c 'source <(~/.tea/tea.xyz/v0.25.3/bin/tea --magic=zsh)'"
Benchmark 1: zsh -c 'source <(~/.tea/tea.xyz/v0.21.0/bin/tea --magic=zsh)'
  Time (mean ± σ):     241.5 ms ±  10.5 ms    [User: 178.6 ms, System: 43.3 ms]
  Range (min … max):   232.2 ms … 264.5 ms    12 runs

Benchmark 2: zsh -c 'source <(~/.tea/tea.xyz/v0.25.3/bin/tea --magic=zsh)'
  Time (mean ± σ):     252.9 ms ±  15.6 ms    [User: 182.5 ms, System: 44.9 ms]
  Range (min … max):   235.7 ms … 287.6 ms    12 runs

Summary
  'zsh -c 'source <(~/.tea/tea.xyz/v0.21.0/bin/tea --magic=zsh)'' ran
    1.05 ± 0.08 times faster than 'zsh -c 'source <(~/.tea/tea.xyz/v0.25.3/bin/tea --magic=zsh)''

off-topic: to measure this, I wanted to use tea in tea, but was blocked by #473

[mxcl]

k so time tea --prefix is ~10ms. Thus our position that this is deno’s fault is wrong. Somehow --magic adds 90ms.

[vegerot]

k so time tea --prefix is ~10ms. Thus our position that this is deno’s fault is wrong. Somehow --magic adds 90ms.

What are you running on? It's about ten times slower on my machine

❯ hyperfine --warmup=2 "tea --prefix"                   
                                                                                                                                                       
Benchmark 1: tea --prefix
  Time (mean ± σ):     164.8 ms ±  13.4 ms    [User: 118.1 ms, System: 34.0 ms]
  Range (min … max):   142.0 ms … 199.5 ms    17 runs

I'm running on a 2019 MacBook Pro, 2.4 GHz 8-core i9 with 32 GB of RAM

[vegerot]

Deno is responsible for almost half that time

❯ hyperfine --warmup=1 "deno run <(echo \"console.log('I love tea!')\")"
Benchmark 1: deno run <(echo "console.log('I love tea!')")
  Time (mean ± σ):      44.3 ms ±  10.9 ms    [User: 24.8 ms, System: 17.9 ms]
  Range (min … max):    34.0 ms …  62.4 ms    39 runs