Can I profile my .zshrc/.zshenv?

Question

It seems like my shell is taking way too long to start up. Is there any way to profile it so I can figure out what's slowing it down so much?

Answer 1

Try adding this at the beginning of the file:

# set the trace prompt to include seconds, nanoseconds, script name and line number
# This is GNU date syntax; by default Macs ship with the BSD date program, which isn't compatible
PS4='+$(date "+%s:%N") %N:%i> '
# save file stderr to file descriptor 3 and redirect stderr (including trace 
# output) to a file with the script's PID as an extension
exec 3>&2 2>/tmp/startlog.$$
# set options to turn on tracing and expansion of commands contained in the prompt
setopt xtrace prompt_subst

and this at the end:

# turn off tracing
unsetopt xtrace
# restore stderr to the value saved in FD 3
exec 2>&3 3>&-

And you should get a detailed log showing the epoch_second.nanosecond time of the execution of each line. Note that GNU date (and OS support) is required to have nanosecond output.

Edit:

added comments

Edit 2:

If you have zsh 4.3.12 or later, you should be able to set PS4 like this instead of using the date command:

zmodload zsh/datetime
setopt promptsubst
PS4='+$EPOCHREALTIME %N:%i> '

which should work on both Linux and OS X to give you nanosecond precision.

Answer 2

You can start your timer at the first suspicious point in your ~/.zshrc (or at the beginning):

integer t0=$(date '+%s')  # move this around
... maybe something suspect ...

# End of zshrc
function {
    local -i t1 startup
    t1=$(date '+%s')
    startup=$(( t1 - t0 ))
    [[ $startup -gt 1 ]] && print "Hmm, poor shell startup time: $startup"
}
unset t0

This alerts me if ever I see a too-slow startup, and I leave it in as a permanent wrapper.

For more sophisticated measurements, there is a zsh module called zprof. It's as simple as temporarily wrapping the contents of your ~/.zshrc in a zmodload zsh/zprof and zprof. This will dump some verbose profiling tables that are easy enough to interpret.

More info in zshmodules(1) manpage.

When I find things that are particularly slow (rbenv init, vcs_info check-for-changes, antigen, nvm, zsh-mime-setup, interpreter version checking, etc) I add SLOW comments as reminders, and try to find workarounds. Slow startups can cause a lot grief, so I tend to avoid zsh packages/framewords whose inner workings I don't grok. compinit is the slowest thing I'm willing to live with and is ~half of total startup time.

Answer 3

Zsh has a profiling module. At the beginning of ~/.zshrc or ~/.zshenv add it like:

# Uncomment to use the profiling module
# zmodload zsh/zprof

Uncomment it, start a new interactive shell then run the command zprof. You will get a detailed list of items you can review to better understand where your performance bottlenecks are:

num  calls                time                       self            name
-----------------------------------------------------------------------------------
 1)    1           7.29     7.29   19.60%      7.29     7.29   19.60%  _p9k_init_ssh
 2)    2           6.72     3.36   18.06%      6.63     3.31   17.81%  gitstatus_start_impl
 3)    1           4.00     4.00   10.75%      4.00     4.00   10.75%  _p9k_must_init
 4)    3          19.28     6.43   51.80%      3.82     1.27   10.28%  (anon)
 5)    1           1.63     1.63    4.37%      1.63     1.63    4.37%  _p9k_restore_state_impl
 6)    1          16.92    16.92   45.46%      1.61     1.61    4.32%  _p9k_precmd_impl
 7)    1           7.13     7.13   19.16%      0.87     0.87    2.33%  _p9k_set_prompt
 8)   22           6.26     0.28   16.83%      0.84     0.04    2.27%  _p9k_build_segment
 9)   17           0.82     0.05    2.19%      0.82     0.05    2.19%  _p9k_param
10)    6           2.24     0.37    6.02%      0.74     0.12    1.98%  _p9k_left_prompt_segment
11)    5           0.59     0.12    1.60%      0.59     0.12    1.60%  add-zsh-hook
12)    1           3.05     3.05    8.20%      0.58     0.58    1.56%  prompt_dir

And here's a one-liner from speeding up zsh you'll appreciate if start time feels sporadic:

for i in $(seq 1 10); do /usr/bin/time zsh -i -c exit; done

Run that job and you should see output like:

        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys
        0.05 real         0.02 user         0.02 sys

Profit.