[bug]: Constant CPU usage

mustaqimM commented 2 years ago

What happened?

Hello, I noticed with even just a plain zinit .zshrc, around 0.7% per shell is used; this increases with more plugins.

Steps to reproduce

.zshrc with contents:

ZINIT_HOME="${XDG_DATA_HOME:-${HOME}/.local/share}/zinit/zinit.git"
source "${ZINIT_HOME}/zinit.zsh"

Relevant output

No response

Screenshots and recordings

Zinit with no plugins: swappy-20220819_070853

Zinit with plugins: swappy-20220819_081746

zsh -df: swappy-20220819_071332

Operating System & Version

Zsh version

zsh 5.9 (x86_64-unknown-linux-gnu)

Terminal emulator

alacritty

If using WSL on Windows, which version of WSL

No response

Additional context

No response

Code of Conduct

[X] I agree to follow this project's Code of Conduct

vladdoster commented 2 years ago

~And what is the CPU usage without Zinit?~

Didn't see the last picture

vladdoster commented 2 years ago

I've hunted down this code that I will investigate.

It seems to be constantly running in the background

poetaman commented 2 years ago

I see the same behavior, CPU usage without zinit for a zsh shell on my end is 0. With zinit is high, the same pattern reported by @mustaqimM. The constant CPU usage stops when an application is run in zsh shell, for instance vim/nvim. On my end the idle CPU usage of vim/nvim is 0. So keeping vim/nvim instance open in a zsh shell has lower overall CPU activity than keeping the shell at prompt waiting for user input.

@vladdoster How did you hunt that down? Any tool/methodology or commenting different parts of code?

vladdoster commented 1 year ago

@reportaman Noted. Thanks for the information!

I've finally got some time to dig into this tonight and over Labor day weekend.

To answer your questions:

I started a new Zsh instance with debugging via:

exec zsh --interactive --login --verbose --xtrace

and saw this output over and over when idle.

There is another tool I like for debugging, but will be cumbersome/frustrating to use if you aren't super familiar with using a debugger. That said, observability is useful even if you're just debugging your personal ZSH configuration.

https://zshdb.readthedocs.io/en/latest/

vladdoster commented 1 year ago

Have a feeling this is related to #315?

psprint commented 1 year ago

This can be lowered down by making scheduler sleep for a longer time like 5 seconds. It currently sleeps for 1 second.

wt., 1 lis 2022, 12:46 użytkownik vladislav doster @.***> napisał:

Have a feeling this is related to #315 https://github.com/zdharma-continuum/zinit/issues/315?

— Reply to this email directly, view it on GitHub https://github.com/zdharma-continuum/zinit/issues/362#issuecomment-1298399159, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABOE4CHR3PYJZ6K72GHLRJLWGD7KXANCNFSM567OJ6QA . You are receiving this because you are subscribed to this thread.Message ID: @.***>

vladdoster commented 1 year ago

@psprint whats the reason for running the scheduler so often?

psprint commented 1 year ago

It's for wait ice - it's checked every second to run tasks in proper time slots. I guess that it could be changed to sleep for exactly the needed time or to sleep longer after e.g. fitst 5 seconds.

czw., 3 lis 2022, 01:15 użytkownik vladislav doster < @.***> napisał:

@psprint https://github.com/psprint whats the reason for running the scheduler so often?

— Reply to this email directly, view it on GitHub https://github.com/zdharma-continuum/zinit/issues/362#issuecomment-1301513181, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABOE4CHR6JPFHQ3Y5S4W5T3WGL7ZLANCNFSM567OJ6QA . You are receiving this because you were mentioned.Message ID: @.***>

psprint commented 1 year ago

@vladdoster: the fix is in #409.

poetaman commented 1 year ago

Can it be event based, or can a user use zinit in a way to avoid this loop altogether? It might look like low overhead, but that's subjective. At the moment an idle zsh shell with zinit installed executes 2 million+ aarch64 instructions per second on my computer. A power user who has tens of shell sessions open over time would see battery dipping... Or if someone were to port their zshrc to something like raspberry pi or other smaller computers they will have to get rid of zinit.

psprint commented 1 year ago

Can it be event based, or can a user use zinit in a way to avoid this loop altogether? It might look like low overhead, but that's subjective. At the moment an idle zsh shell with zinit installed executes 2 million+ aarch64 instructions per second on my computer. A power user who has tens of shell sessions on over time would see battery dipping... Or if someone were to port their zshrc to something like raspberry pi or other smaller computers they will have to get rid of zinit.

Yes the fix is in #409, @poetaman . It changes the sleep time to 10 seconds and makes a short circuit exit if no tasks.

poetaman commented 1 year ago

@vladdoster A significant slowdown on my system (with fan kicking in) made me do more testing. Haven't tested this with @psprint's patch but currently there is bug that increases the number of instructions executed per second by 2+ million instructions for every cd command executed in a zsh shell. Is anyone also seeing the same??? Try cd'ing multiple times in and out of two different directories and see it for yourself...

When the system slowed down I had already spent many hours cding back and forth in the shell. Imagine a long session, where user keeps shell open for days or weeks. This CPU usage will pile up to eventually take the system down. Not sure if @psprint 's patch would just delay the effect. Also, not sure if other activity on the shell also produces such increase in CPU usage. IMHO, in an ideal world everything is event driven, when shell is idling, it shouldn't consume CPU. Is there a hook to completely turn off this background activity completely? I wouldn't mind letting go of some fancy features if it makes it a more silent shell.

Not sure if the plugins have anything to do with this. Here's what zinit update prints (which I guess shows all plugins):

❯ zinit update
Assuming --all is passed
[self-update] updating zinit repository
.
.
Note: updating also unloaded plugins
Updating sindresorhus/pure
Updating skywind3000/z.lua
Updating zdharma-continuum/fast-syntax-highlighting
.
.
Note: Compiling: fast-syntax-highlighting.plugin.zsh… OK.
Updating zdharma-continuum/history-search-multi-word
Updating zdharma-continuum/zinit-annex-as-monitor
.
.
Note: Compiling: z-a-readurl.plugin.zsh… OK.
Updating zdharma-continuum/zinit-annex-bin-gem-node
Updating zdharma-continuum/zinit-annex-patch-dl
Updating zdharma-continuum/zinit-annex-rust
Updating zsh-users/zsh-autosuggestions
The update took 17.65 seconds

vladdoster commented 1 year ago

@poetaman I saw there might be a bug in fast-syntax-highlighting. You might try removing it and see if anything improves?

vladdoster commented 1 year ago

Oh, wait. Also a bug in read-URL. Working on the fix now.

poetaman commented 1 year ago

@vladdoster I commented out all those plugins, the issue and its scale remains same with zinit (each cd increases instructions per second by 2+ million ARM instructions on Apple M1 chips while shell is waiting for user input). So I guess it is caused by the bug you just found in zinit.

poetaman commented 1 year ago

@vladdoster If you mean https://github.com/zdharma-continuum/zinit-annex-readurl, I don't have it in my plug-ins for zinit. So the source of bug seems zinit core itself...

vladdoster commented 1 year ago

Have you seen this? Just shooting from the hip.

https://github.com/zsh-users/zsh-syntax-highlighting/issues/895

Btw, how are you calculating instruction count?

Could you paste output of following?

zmodload zsh/zprof
# 1. cd to a few directories / what causes slowdown
# 2. copy zprof output to clipboard 
zprof | pbcopy
# 3. paste in this issue
# 4. profit?! ;^)

poetaman commented 1 year ago

@vladdoster

Btw, how are you calculating instruction count?

Using CPU performance counters, that's the most accurate one can get. On macOS this comes integrated with top, on Linux they have it under procfs (to give users more fine grained information). Ready for some bonus boring video? In the left shell you will see top tracking zsh process to the right. As you will see, CPU usage of zinit increases by 2 million instructions/second for every cd command run in it. As zinit will consume increasingly more CPU cycles per second, by the end of a long period of activity in the same shell session, user will notice significant system slowdown. The zprof output is attached below the video. Btw, I would like to reiterate one thing: zsh session with zinit consumes 0 cycles if one is to run a command, and does consume at least 2 million CPU cycles from the onset if the shell is waiting for user input. It seems counter intuitive, but one can reduce their CPU consumption by opening worthless processes (like touch foo && less foo) that restricts zsh from idling at prompt.

https://user-images.githubusercontent.com/71736629/208232014-d3f00900-1acb-42b8-9961-ec9499dc557c.mp4

num  calls                time                       self            name
-----------------------------------------------------------------------------------
 1)    7         227.92    32.56   43.07%    227.92    32.56   43.07%  my_preexec
 2)  230         122.88     0.53   23.22%    122.88     0.53   23.22%  (anon)
 3)    7          92.06    13.15   17.39%     92.06    13.15   17.39%  my_precmd
 4)  230         178.84     0.78   33.79%     55.11     0.24   10.41%  @zinit-scheduler
 5)    7           9.92     1.42    1.87%      9.92     1.42    1.87%  iterm2_decorate_prompt
 6)    3           5.59     1.86    1.06%      4.95     1.65    0.94%  _path_files
 7)    3          18.82     6.27    3.56%      4.36     1.45    0.82%  _main_complete
 8)    6           1.77     0.29    0.33%      1.77     0.29    0.33%  _tags
 9)    6           1.80     0.30    0.34%      1.32     0.22    0.25%  _description
10)    9           1.09     0.12    0.21%      1.09     0.12    0.21%  _setup
11)   12           0.86     0.07    0.16%      0.86     0.07    0.16%  add-zsh-hook
12)    3          10.72     3.57    2.03%      0.85     0.28    0.16%  _alternative
13)    3          11.72     3.91    2.21%      0.72     0.24    0.14%  _cd
14)    3          13.84     4.61    2.62%      0.63     0.21    0.12%  _complete
15)    3          12.33     4.11    2.33%      0.61     0.20    0.12%  _dispatch
16)    7           1.01     0.14    0.19%      0.58     0.08    0.11%  iterm2_preexec
17)    6           1.18     0.20    0.22%      0.47     0.08    0.09%  _next_label
18)    7           0.43     0.06    0.08%      0.43     0.06    0.08%  iterm2_before_cmd_executes
19)    3          13.01     4.34    2.46%      0.42     0.14    0.08%  _normal
20)    7          10.57     1.51    2.00%      0.39     0.06    0.07%  iterm2_precmd
21)    3           0.35     0.12    0.07%      0.35     0.12    0.07%  _have_glob_qual
22)    3           0.28     0.09    0.05%      0.28     0.09    0.05%  _list_files
23)    3           0.28     0.09    0.05%      0.28     0.09    0.05%  _directory_stack
24)    3           0.26     0.09    0.05%      0.26     0.09    0.05%  _set_command
25)    3           0.24     0.08    0.05%      0.24     0.08    0.05%  _requested
26)    3           0.20     0.07    0.04%      0.20     0.07    0.04%  _first
27)    7           0.17     0.02    0.03%      0.14     0.02    0.03%  iterm2_print_state_data
28)    7           0.27     0.04    0.05%      0.10     0.01    0.02%  iterm2_after_cmd_executes
29)    7           0.02     0.00    0.00%      0.02     0.00    0.00%  iterm2_print_user_vars

-----------------------------------------------------------------------------------

 1)    7         227.92    32.56   43.07%    227.92    32.56   43.07%  my_preexec

-----------------------------------------------------------------------------------

 4)  230         178.84     0.78   33.79%     55.11     0.24   10.41%  @zinit-scheduler
      12/12        0.86     0.07    0.16%      0.86     0.07             add-zsh-hook [11]
     230/230     122.88     0.53   23.22%    122.88     0.53             (anon) [2]

-----------------------------------------------------------------------------------

     230/230     122.88     0.53   23.22%    122.88     0.53             @zinit-scheduler [4]
 2)  230         122.88     0.53   23.22%    122.88     0.53   23.22%  (anon)

-----------------------------------------------------------------------------------

 3)    7          92.06    13.15   17.39%     92.06    13.15   17.39%  my_precmd

-----------------------------------------------------------------------------------

 7)    3          18.82     6.27    3.56%      4.36     1.45    0.82%  _main_complete
       3/9         0.61     0.20    0.12%      0.61     0.20             _setup [10]
       3/3        13.84     4.61    2.62%      0.63     0.21             _complete [14]

-----------------------------------------------------------------------------------

       3/3        13.84     4.61    2.62%      0.63     0.21             _main_complete [7]
14)    3          13.84     4.61    2.62%      0.63     0.21    0.12%  _complete
       3/3         0.20     0.07    0.04%      0.20     0.07             _first [26]
       3/3        13.01     4.34    2.46%      0.42     0.14             _normal [19]

-----------------------------------------------------------------------------------

       3/3        13.01     4.34    2.46%      0.42     0.14             _complete [14]
19)    3          13.01     4.34    2.46%      0.42     0.14    0.08%  _normal
       3/3         0.26     0.09    0.05%      0.26     0.09             _set_command [24]
       3/3        12.33     4.11    2.33%      0.61     0.20             _dispatch [15]

-----------------------------------------------------------------------------------

       3/3        12.33     4.11    2.33%      0.61     0.20             _normal [19]
15)    3          12.33     4.11    2.33%      0.61     0.20    0.12%  _dispatch
       3/3        11.72     3.91    2.21%      0.72     0.24             _cd [13]

-----------------------------------------------------------------------------------

       3/3        11.72     3.91    2.21%      0.72     0.24             _dispatch [15]
13)    3          11.72     3.91    2.21%      0.72     0.24    0.14%  _cd
       3/3         0.28     0.09    0.05%      0.28     0.09             _directory_stack [23]
       3/3        10.72     3.57    2.03%      0.85     0.28             _alternative [12]

-----------------------------------------------------------------------------------

       3/3        10.72     3.57    2.03%      0.85     0.28             _cd [13]
12)    3          10.72     3.57    2.03%      0.85     0.28    0.16%  _alternative
       3/3         0.24     0.08    0.05%      0.24     0.08             _requested [25]
       3/6         1.10     0.37    0.21%      0.85     0.28             _description [9]
       6/6         1.18     0.20    0.22%      0.47     0.08             _next_label [17]
       6/6         1.77     0.29    0.33%      1.77     0.29             _tags [8]
       3/3         5.59     1.86    1.06%      4.95     1.65             _path_files [6]

-----------------------------------------------------------------------------------

20)    7          10.57     1.51    2.00%      0.39     0.06    0.07%  iterm2_precmd
       7/7         0.27     0.04    0.05%      0.10     0.01             iterm2_after_cmd_executes [28]
       7/7         9.92     1.42    1.87%      9.92     1.42             iterm2_decorate_prompt [5]

-----------------------------------------------------------------------------------

       7/7         9.92     1.42    1.87%      9.92     1.42             iterm2_precmd [20]
 5)    7           9.92     1.42    1.87%      9.92     1.42    1.87%  iterm2_decorate_prompt

-----------------------------------------------------------------------------------

       3/3         5.59     1.86    1.06%      4.95     1.65             _alternative [12]
 6)    3           5.59     1.86    1.06%      4.95     1.65    0.94%  _path_files
       3/3         0.28     0.09    0.05%      0.28     0.09             _list_files [22]
       3/3         0.35     0.12    0.07%      0.35     0.12             _have_glob_qual [21]

-----------------------------------------------------------------------------------

       3/6         1.10     0.37    0.21%      0.85     0.28             _alternative [12]
       3/6         0.71     0.24    0.13%      0.47     0.16             _next_label [17]
 9)    6           1.80     0.30    0.34%      1.32     0.22    0.25%  _description
       6/9         0.48     0.08    0.09%      0.48     0.08             _setup [10]

-----------------------------------------------------------------------------------

       6/6         1.77     0.29    0.33%      1.77     0.29             _alternative [12]
 8)    6           1.77     0.29    0.33%      1.77     0.29    0.33%  _tags

-----------------------------------------------------------------------------------

       6/6         1.18     0.20    0.22%      0.47     0.08             _alternative [12]
17)    6           1.18     0.20    0.22%      0.47     0.08    0.09%  _next_label
       3/6         0.71     0.24    0.13%      0.47     0.16             _description [9]

-----------------------------------------------------------------------------------

       3/9         0.61     0.20    0.12%      0.61     0.20             _main_complete [7]
       6/9         0.48     0.08    0.09%      0.48     0.08             _description [9]
10)    9           1.09     0.12    0.21%      1.09     0.12    0.21%  _setup

-----------------------------------------------------------------------------------

16)    7           1.01     0.14    0.19%      0.58     0.08    0.11%  iterm2_preexec
       7/7         0.43     0.06    0.08%      0.43     0.06             iterm2_before_cmd_executes [18]

-----------------------------------------------------------------------------------

      12/12        0.86     0.07    0.16%      0.86     0.07             @zinit-scheduler [4]
11)   12           0.86     0.07    0.16%      0.86     0.07    0.16%  add-zsh-hook

-----------------------------------------------------------------------------------

       7/7         0.43     0.06    0.08%      0.43     0.06             iterm2_preexec [16]
18)    7           0.43     0.06    0.08%      0.43     0.06    0.08%  iterm2_before_cmd_executes

-----------------------------------------------------------------------------------

       3/3         0.35     0.12    0.07%      0.35     0.12             _path_files [6]
21)    3           0.35     0.12    0.07%      0.35     0.12    0.07%  _have_glob_qual

-----------------------------------------------------------------------------------

       3/3         0.28     0.09    0.05%      0.28     0.09             _path_files [6]
22)    3           0.28     0.09    0.05%      0.28     0.09    0.05%  _list_files

-----------------------------------------------------------------------------------

       3/3         0.28     0.09    0.05%      0.28     0.09             _cd [13]
23)    3           0.28     0.09    0.05%      0.28     0.09    0.05%  _directory_stack

-----------------------------------------------------------------------------------

       7/7         0.27     0.04    0.05%      0.10     0.01             iterm2_precmd [20]
28)    7           0.27     0.04    0.05%      0.10     0.01    0.02%  iterm2_after_cmd_executes
       7/7         0.17     0.02    0.03%      0.14     0.02             iterm2_print_state_data [27]

-----------------------------------------------------------------------------------

       3/3         0.26     0.09    0.05%      0.26     0.09             _normal [19]
24)    3           0.26     0.09    0.05%      0.26     0.09    0.05%  _set_command

-----------------------------------------------------------------------------------

       3/3         0.24     0.08    0.05%      0.24     0.08             _alternative [12]
25)    3           0.24     0.08    0.05%      0.24     0.08    0.05%  _requested

-----------------------------------------------------------------------------------

       3/3         0.20     0.07    0.04%      0.20     0.07             _complete [14]
26)    3           0.20     0.07    0.04%      0.20     0.07    0.04%  _first

-----------------------------------------------------------------------------------

       7/7         0.17     0.02    0.03%      0.14     0.02             iterm2_after_cmd_executes [28]
27)    7           0.17     0.02    0.03%      0.14     0.02    0.03%  iterm2_print_state_data
       7/7         0.02     0.00    0.00%      0.02     0.00             iterm2_print_user_vars [29]

-----------------------------------------------------------------------------------

       7/7         0.02     0.00    0.00%      0.02     0.00             iterm2_print_state_data [27]
29)    7           0.02     0.00    0.00%      0.02     0.00    0.00%  iterm2_print_user_vars

yut23 commented 1 year ago

I can reproduce this on Linux with the current main branch at 68a6b42caf224b2ca2c172d58daf9faf5c86beb9. The culprit is the chpwd hook set for @zinit-scheduler, which ends up adding a new sched chain every time the directory is changed (this was added in e28cab88c94232350d46bc1d6b52cd43830e24b6):

eric@xrb /tmp/test % sched
  1 Tue Aug 15 20:16:12 ZINIT[lro-data]="$_:$?:${options[printexitvalue]}"; @zinit-scheduler following "${ZINIT[lro-data]%:*:*}"

eric@xrb /tmp/test % cd test

eric@xrb /tmp/test/test % sched
  1 Tue Aug 15 20:16:16 ZINIT[lro-data]="$_:$?:${options[printexitvalue]}"; @zinit-scheduler following "${ZINIT[lro-data]%:*:*}"
  2 Tue Aug 15 20:16:16 ZINIT[lro-data]="$_:$?:${options[printexitvalue]}"; @zinit-scheduler following "${ZINIT[lro-data]%:*:*}"

eric@xrb /tmp/test/test % cd ..

eric@xrb /tmp/test % sched
  1 Tue Aug 15 20:16:19 ZINIT[lro-data]="$_:$?:${options[printexitvalue]}"; @zinit-scheduler following "${ZINIT[lro-data]%:*:*}"
  2 Tue Aug 15 20:16:19 ZINIT[lro-data]="$_:$?:${options[printexitvalue]}"; @zinit-scheduler following "${ZINIT[lro-data]%:*:*}"
  3 Tue Aug 15 20:16:19 ZINIT[lro-data]="$_:$?:${options[printexitvalue]}"; @zinit-scheduler following "${ZINIT[lro-data]%:*:*}"

https://github.com/zdharma-continuum/zinit/blob/68a6b42caf224b2ca2c172d58daf9faf5c86beb9/zinit.zsh#L2486-L2498

I think a general fix would be to only add a sched entry if there's not already one present in $zsh_scheduled_events (both here and at the top of the function). I'm not sure how the bug referenced on line 2495 would interact with that, though.

As a side note, I used perf stat -I 1000 --interval-clear -p <zsh pid> to look at detailed CPU usage on Linux, and got similar results to @poetaman.

zdharma-continuum / zinit