Re: profile prompt rendering time

[Filipe Silva <filipe.silva@xxxxxxxxx>]

Nikolay thanks. With my poor man's approach, enabling and disabling the
plugin while performing the same test would give me the performance hit of
activating the plugin in the first place. Your approach, on the other hand,
is way, way more sofisticated than mine. I have to admit that I can't
follow 100% of what you said, actually.

On Wed, Jul 13, 2016 at 9:28 PM, Nikolay Aleksandrovich Pavlov (ZyX) <
kp-pav@xxxxxxxxx> wrote:

> It is rather strange to see this discussion. I would read OP post as “I
> installed some plugin and as the result prompt rendering appears to be
> slow, I need to determine *what* is slow”… up until he said explicitly
> “when i hit enter, start counting <…> stop counting when this prompt
> appears. show me elapsed time”. I have no idea how determining total
> execution time is going to help with slow prompt: this should change ones
> knowledge from “I see that prompt is slow” to “I see that prompt is slow,
> specifically it takes N seconds to appear”.
>
> If OP wants more practial answer I can suggest to use `set -x`, `float
> SECONDS` and `PS4='+%N:%i|$SECONDS> '` with `setopt promptsubst`. E.g.:
>
> ```
> (float SECONDS; PS4='+%N:%i|$SECONDS> '; setopt promptsubst; PS1='$(sleep
> 5)' ; set -x; echo -n; print -P "${PS1}"; echo -n)
> +/bin/zsh:237|9.894828127e+05> echo -n
> +/bin/zsh:237|9.894828129e+05> print -P '$(sleep 5)'
> +/bin/zsh:237|9.894828156e+05> sleep 5
>
> +/bin/zsh:237|9.894878230e+05> echo -n
> ```
>
> if you are sure that problem is exactly in PS1. If not
>
> ```
> % zsh
> %% float SECONDS
> %% setopt promptsubst
> %% PS4='+%N:%i|$SECONDS> '
> %% set -x
> %% exit
> ```
>
> For me this is giving something like
>
> ```
> +term_reset:2|5.749184800e+01> emulate -L zsh
> +term_reset:3|5.749191200e+01> [[ -n /dev/pts/8 ]]
> +term_reset:3|5.749194000e+01> ((  1  ))
> +term_reset:4|5.749214300e+01> _echoti rmacs
> +_echoti:2|5.749222300e+01> emulate -L zsh
> +_echoti:3|5.749227700e+01> ((  1  ))
> +_echoti:3|5.749231100e+01> echoti rmacs
> +term_reset:5|5.749236900e+01> _echoti sgr0
> +_echoti:2|5.749239800e+01> emulate -L zsh
> +_echoti:3|5.749242700e+01> ((  1  ))
> +_echoti:3|5.749245600e+01> echoti sgr0
> +term_reset:6|5.749250600e+01> _echoti cnorm
> +_echoti:2|5.749253400e+01> emulate -L zsh
> +_echoti:3|5.749256300e+01> ((  1  ))
> +_echoti:3|5.749259200e+01> echoti cnorm
> +term_reset:7|5.749264300e+01> _echoti smkx
> +_echoti:2|5.749267200e+01> emulate -L zsh
> +_echoti:3|5.749270000e+01> ((  1  ))
> +_echoti:3|5.749272800e+01> echoti smkx
> +term_reset:8|5.749277700e+01> echo -n ''
> +_powerline_set_jobnum:11|5.749283300e+01> _POWERLINE_JOBNUM=0
> +_powerline_update_counter:1|5.749287800e+01> zpython '_powerline.precmd()'
> +_powerline_set_main_keymap_name:1|5.749309500e+01> local REPLY
> +_powerline_set_main_keymap_name:2|5.749313100e+01>
> _powerline_get_main_keymap_name
> +_powerline_get_main_keymap_name:1|5.749315900e+01>
> REPLY=+_powerline_get_main_keymap_name:1|5.749467000e+01> bindkey -lL main
> +_powerline_get_main_keymap_name:1|5.749315900e+01> REPLY=evi
> +_powerline_set_main_keymap_name:3|5.749628400e+01>
> _powerline_set_true_keymap_name evi
> +_powerline_set_true_keymap_name:1|5.749633100e+01> _POWERLINE_MODE=evi
> +_powerline_set_true_keymap_name:2|5.749807400e+01> bindkey -lL evi
> +_powerline_set_true_keymap_name:2|5.750009900e+01> local plm_bk='bindkey
> -N evi'
> +_powerline_set_true_keymap_name:3|5.750017900e+01> [[ 'bindkey -N evi' ==
> bindkey\ -A* ]]
> ```
>
> which needs some post-processing to actually be useful. But if there are
> not much commands this output may be reviewed manually.
>
> Quick google:“profile zsh scripts” shows that there are people also using
> similar approach and have already written everything necessary to do real
> profiling: http://blog.xebia.com/profiling-zsh-shell-scripts/. Post also
> mentiones zprof.
>