profile prompt rendering time

profile prompt rendering time

[Filipe Silva]

[-- Attachment #1: Type: text/plain, Size: 765 bytes --]

Hi,

short version: How can I profile each rendering of a zsh prompt?

long version: I've recently came across a plugin (rupa/z) that, when
installed, hit my zsh prompt rendering time by a noticeable amount.

When I say prompt rendering time, I'm not refering to amount of time that
it takes for the first zsh prompt to appear when I issue, for an example,
`exec zsh` (that is achieve by issuing `time zsh -i -c "print -n"`).

I'm talking about the time that it takes for zsh to give me another prompt
once that it is fully loaded. In other words, I want to achieve this:

~ $ ls (when i hit enter, start counting)
code/ notes/ file.txt
~ $ (stop counting when this prompt appears. show me elapsed time)

Is that a way to do that?

thanks in advance,

Filipe Silva

Re: profile prompt rendering time

[Bart Schaefer]

On Jul 13, 11:17am, Filipe Silva wrote:
}
} I'm talking about the time that it takes for zsh to give me another
} prompt once that it is fully loaded. In other words, I want to achieve
} this:
} 
} ~ $ ls (when i hit enter, start counting)
} code/ notes/ file.txt
} ~ $ (stop counting when this prompt appears. show me elapsed time)

By your literal example, you would be getting a timing that includes
the execution of "ls".  Is that really what you want?

Assuming not, probably the closest you can get is to declare

    float SECONDS

and then print $SECONDS at the end of your precmd function, and at the
beginning of the zle-line-init widget call "zle -M $SECONDS".

However, I don't know how to explain in detail how to accomplish that
because you mention using plugins and I have no way to know whether
those plugins have co-opted precmd or zle-line-init for other uses.

If you really do want to include the execution time of "ls", then
print $SECONDS at the end of preexec instead of at the end of precmd.

Just to demonstrate, here's the output from precmd/zle-line-init with
an otherwise virgin "zsh -f" on my desktop:

torch% echo start
start
4.800639270e+02                                                                 
torch% 
4.800641060e+02

Re: profile prompt rendering time

[Filipe Silva]

[-- Attachment #1: Type: text/plain, Size: 1915 bytes --]

Hi, Bart. thanks for the help. I can work with the execution time of ls
included, no problem.
that's because I can compare the execution time of ls in the same dir, with
the plugin, and without the plugin. The difference between the two tests
will give me the performance hit of the plugin.

But I did not really understand where I have to declare SECONDS.See if I
understand correctly. I'll open my zshrc and type this:

```
preexec() {
  float SECONDS
}
precmd() {
  print $SECONDS
}
```

is that right?

Also, is 4.800e+2 = 480 milliseconds?

thanks again,

Filipe.



On Wed, Jul 13, 2016 at 3:08 PM, Bart Schaefer <schaefer@brasslantern.com>
wrote:

> On Jul 13, 11:17am, Filipe Silva wrote:
> }
> } I'm talking about the time that it takes for zsh to give me another
> } prompt once that it is fully loaded. In other words, I want to achieve
> } this:
> }
> } ~ $ ls (when i hit enter, start counting)
> } code/ notes/ file.txt
> } ~ $ (stop counting when this prompt appears. show me elapsed time)
>
> By your literal example, you would be getting a timing that includes
> the execution of "ls".  Is that really what you want?
>
> Assuming not, probably the closest you can get is to declare
>
>     float SECONDS
>
> and then print $SECONDS at the end of your precmd function, and at the
> beginning of the zle-line-init widget call "zle -M $SECONDS".
>
> However, I don't know how to explain in detail how to accomplish that
> because you mention using plugins and I have no way to know whether
> those plugins have co-opted precmd or zle-line-init for other uses.
>
> If you really do want to include the execution time of "ls", then
> print $SECONDS at the end of preexec instead of at the end of precmd.
>
> Just to demonstrate, here's the output from precmd/zle-line-init with
> an otherwise virgin "zsh -f" on my desktop:
>
> torch% echo start
> start
> 4.800639270e+02
> torch%
> 4.800641060e+02
>
>

Re: profile prompt rendering time

[Bart Schaefer]

On Jul 13,  4:31pm, Filipe Silva wrote:
}
} Hi, Bart. thanks for the help. I can work with the execution time of ls
} included, no problem.

If you use precmd + zle-line-init then you don't need to.  Just saying.

} But I did not really understand where I have to declare SECONDS.

Anywhere in your .zshrc or similar init file, or at the command line,
as long as it happens before the first event for which you want to
get the timings.

} See if I understand correctly. I'll open my zshrc and type this:
} 
} ```
} preexec() {
}   float SECONDS
} }
} precmd() {
}   print $SECONDS
} }
} ```
} 
} is that right?

Not quite.  To spell out the example:

    float SECONDS
    preexec() { print BEFORE COMMAND: $SECONDS }
    precmd() { print BEFORE PROMPT: $SECONDS }
    zle-line-init() { zle -M "AFTER PROMPT: $SECONDS" }
    zle -N zle-line-init

This will give e.g.:

torch% echo hello
BEFORE COMMAND: 7.365769200e+01
hello
BEFORE PROMPT: 7.365787900e+01                                                  
torch% 
AFTER PROMPT: 7.365904200e+01

You don't really need both preexec and precmd, I included them to
show the difference.  You DO need zle-line-init, there's no other
place to read the clock immediately after the prompt is displayed.

} Also, is 4.800e+2 = 480 milliseconds?

$SECONDS is the elapsed time in seconds since the shell started.  So
you have to subtract to get the delta.  Maybe this is better:

    float START SECONDS
    precmd() { START=$SECONDS }
    zle-line-init() { zle -M "ELAPSED: $((SECONDS - START)) seconds" }

Silly example to demonstrate:

torch% setopt promptsubst; PS1='$(sleep 3)'"$PS1"
torch% 
ELAPSED: 3.015070000000037 seconds

Re: profile prompt rendering time

[Richo Healey]

On 13/07/16 11:17 -0300, Filipe Silva wrote:
>Hi,
>
>short version: How can I profile each rendering of a zsh prompt?
>
>long version: I've recently came across a plugin (rupa/z) that, when
>installed, hit my zsh prompt rendering time by a noticeable amount.
>
>When I say prompt rendering time, I'm not refering to amount of time that
>it takes for the first zsh prompt to appear when I issue, for an example,
>`exec zsh` (that is achieve by issuing `time zsh -i -c "print -n"`).
>
>I'm talking about the time that it takes for zsh to give me another prompt
>once that it is fully loaded. In other words, I want to achieve this:
>
>~ $ ls (when i hit enter, start counting)
>code/ notes/ file.txt
>~ $ (stop counting when this prompt appears. show me elapsed time)
>
>Is that a way to do that?
>
>thanks in advance,
>
>Filipe Silva

You could do something fairly janky and just wrap your whole prompt in a
function that emits the prompt, and time(1)'s itself.

Re: profile prompt rendering time

[Filipe Silva]

[-- Attachment #1: Type: text/plain, Size: 1223 bytes --]

Yes! that'd be neat Richo. I was thinking of doing that to the right
prompt.

Thanks Bart. I'll try to work that on a custom prompt.

On Wed, Jul 13, 2016 at 6:37 PM, Richo Healey <richo@psych0tik.net> wrote:

> On 13/07/16 11:17 -0300, Filipe Silva wrote:
>
>> Hi,
>>
>> short version: How can I profile each rendering of a zsh prompt?
>>
>> long version: I've recently came across a plugin (rupa/z) that, when
>> installed, hit my zsh prompt rendering time by a noticeable amount.
>>
>> When I say prompt rendering time, I'm not refering to amount of time that
>> it takes for the first zsh prompt to appear when I issue, for an example,
>> `exec zsh` (that is achieve by issuing `time zsh -i -c "print -n"`).
>>
>> I'm talking about the time that it takes for zsh to give me another prompt
>> once that it is fully loaded. In other words, I want to achieve this:
>>
>> ~ $ ls (when i hit enter, start counting)
>> code/ notes/ file.txt
>> ~ $ (stop counting when this prompt appears. show me elapsed time)
>>
>> Is that a way to do that?
>>
>> thanks in advance,
>>
>> Filipe Silva
>>
>
> You could do something fairly janky and just wrap your whole prompt in a
> function that emits the prompt, and time(1)'s itself.
>

Re: profile prompt rendering time

[Bart Schaefer]

On Jul 13,  2:37pm, Richo Healey wrote:
}
} You could do something fairly janky and just wrap your whole prompt in a
} function that emits the prompt, and time(1)'s itself.

Indeed,

    time ( print -P "$PS1" )

might actually provide all the information you want.  (You need the
subshell because "time" on a built-in is a no-op.)

Re: profile prompt rendering time

[Filipe Silva]

[-- Attachment #1: Type: text/plain, Size: 492 bytes --]

Awesome! Is there a way to do that but with the delta?

On Wed, Jul 13, 2016 at 8:49 PM, Bart Schaefer <schaefer@brasslantern.com>
wrote:

> On Jul 13,  2:37pm, Richo Healey wrote:
> }
> } You could do something fairly janky and just wrap your whole prompt in a
> } function that emits the prompt, and time(1)'s itself.
>
> Indeed,
>
>     time ( print -P "$PS1" )
>
> might actually provide all the information you want.  (You need the
> subshell because "time" on a built-in is a no-op.)
>

Re: profile prompt rendering time

[Bart Schaefer]

On Jul 13,  9:23pm, Filipe Silva wrote:
}
} Awesome! Is there a way to do that but with the delta?

The "time" command will only output elapsed time, so it is the delta.

However, as Nikolay points out, the plugin is probably spending some
time in the precmd function itself, not loading all the work into the
value of $PS1.  So just timing the printing of the prompt may not
tell you very much.

Re: profile prompt rendering time

[Nikolay Aleksandrovich Pavlov (ZyX)]

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.

Re: profile prompt rendering time

[Filipe Silva]

[-- Attachment #1: Type: text/plain, Size: 3986 bytes --]

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@yandex.ru> 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.
>