Slowness when pasting commands with bracketed-paste-magic enabled; slowness with zle -U

[doubleloop]

I have string copied from my text editor:

echo aaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaaa

• when I paste it to my local machine (zsh 5.2) it will run for more then 10 minutes with 100% cpu usage
• when I disable zsh-syntax-highlighting, it is pasted instantly
• when I ssh to my remote machine (zsh 5.0.2), it is also pasted almost instantly with zsh-syntax-highlighting enabled.. (I have exactly the same configuration of zsh on my remote)
• when I use ctrl+r wpapper (zsh-navigation-tools) wich uses zle -U to paste command from history (https://github.com/psprint/zsh-navigation-tools/blob/master/n-history#L46) it works very long (10m+) both on local and remote.

Of course I do not use such extreme commands like in this example, but commands I use when I am pasting are long enough to make the lagging of 5-10 seconds.

[danielshahaf]

I cannot reproduce that: when I paste your long echo aa…aa command, it is pasted instantly and rendered in reverse video. Using zsh 5.3-to-be from git master.

Can you reproduce it in zsh -f + source zsh-syntax-highlighting.zsh? Do you use a framework (oh-my-zsh/prezto/antigen/etc)? Do you use bracketed-paste-magic?

Workaround: set ZSH_HIGHLIGHT_MAXLENGTH=300 in your .zshrc.

[doubleloop]

Hmm, I can not reproduce it with zsh -f + source zsh-syntax-highlighting.zsh..
I am using oh-my-zsh. I will try to investigate more, still if you have any suggestions what to look for it would be helpful.

my zshrc (rest is default ohmyzsh with some aliases):

plugins=(
    common-aliases fasd colorize colored-man extract command-not-found
    vagrant
    gitfast gitignore zsh-git-prompt
    debian
    pip python virtualenv virtualenvwrapper
    atom sublime 
    cabal stack
    gradle
    valut
    zsh-navigation-tools
    zsh-autosuggestions
    zsh-syntax-highlighting 
)
...
# color completions
eval `dircolors`
zstyle ':completion:*' list-colors "${(@s.:.)LS_COLORS}"

# colors of hilight
ZSH_HIGHLIGHT_HIGHLIGHTERS=(main brackets)
ZSH_HIGHLIGHT_STYLES[alias]='fg=cyan,bold'
ZSH_HIGHLIGHT_STYLES[builtin]='fg=cyan,bold'
ZSH_HIGHLIGHT_STYLES[function]='fg=cyan,bold'
ZSH_HIGHLIGHT_STYLES[command]='fg=cyan,bold'
ZSH_HIGHLIGHT_STYLES[precommand]='fg=cyan,bold,underline'
# ZSH_HIGHLIGHT_STYLES[commandseparator]='none'
ZSH_HIGHLIGHT_STYLES[hashed-command]='fg=cyan,bold'

3 plugins are in custom:

• zsh-autosuggestions (https://github.com/zsh-users/zsh-autosuggestions)
• zsh-git-prompt (https://github.com/olivierverdier/zsh-git-prompt)
• zsh-syntax-highlighting

[doubleloop]

The workaround reduced time to about 7 seconds:)

[doubleloop]

I investigated more and the line that was causing the problem is:

ZSH_HIGHLIGHT_HIGHLIGHTERS=(main brackets)

if I comment it, the problem disappears.

[danielshahaf]

I can reproduce this: with your highlighters setting, pasting your example text to zsh -f, and even typing a single space at the end of it, is noticeably slow (I'm seeing subsecond delays, but it's still noticeable).

[danielshahaf]

zprof output is basically what you'd expect:

num  calls                time                       self            name
-----------------------------------------------------------------------------------
 1)    6        1347.66   224.61   98.12%   1347.66   224.61   98.12%  _zsh_highlight_brackets_highlighter
 2)    7        1372.82   196.12   99.95%     20.52     2.93    1.49%  _zsh_highlight_call_widget
 3)    7        1352.30   193.19   98.46%      3.79     0.54    0.28%  _zsh_highlight
 4)    7           0.76     0.11    0.06%      0.39     0.06    0.03%  _zsh_highlight_brackets_highlighter_predicate
 5)    5           5.39     1.08    0.39%      0.37     0.07    0.03%  _zsh_highlight_widget_self-insert
 6)    7           0.32     0.05    0.02%      0.32     0.05    0.02%  _zsh_highlight_cursor_moved
 7)    1           1.07     1.07    0.08%      0.12     0.12    0.01%  _zsh_highlight_widget_accept-line
 8)    1        1366.96  1366.96   99.52%      0.10     0.10    0.01%  _zsh_highlight_widget_bracketed-paste
 9)    1           0.09     0.09    0.01%      0.09     0.09    0.01%  _zsh_highlight_apply_zle_highlight
10)    1           0.07     0.07    0.01%      0.07     0.07    0.01%  _zsh_highlight_preexec_hook
11)    1           0.05     0.05    0.00%      0.05     0.05    0.00%  _zsh_highlight_buffer_modified

[ericfreese]

Pretty sure this has to do with bracketed-paste-magic. See zsh-users/zsh-autosuggestions#141

[danielshahaf]

@ericfreese I can reproduce slowness in zsh -f with only ZSH_HIGHLIGHT_HIGHLIGHTERS=(brackets), i.e., without bracketed-paste-magic. I guess these are two separate issues, then: one in the brackets highlighter and one involving b-p-magic.

[danielshahaf]

Breaking out the two for loops in _zsh_highlight_brackets_highlighter into subfunctions gives:

% zprof
num  calls                time                       self            name
-----------------------------------------------------------------------------------
 1)    6        1352.17   225.36   97.96%   1352.17   225.36   97.96%  f
 2)    7        1379.45   197.06   99.94%     19.26     2.75    1.40%  _zsh_highlight_call_widget
 3)    7        1360.19   194.31   98.54%      5.48     0.78    0.40%  _zsh_highlight
 4)    6        1353.63   225.61   98.07%      1.25     0.21    0.09%  _zsh_highlight_brackets_highlighter
 5)    5           9.30     1.86    0.67%      0.57     0.11    0.04%  _zsh_highlight_widget_self-insert
 6)    7           0.99     0.14    0.07%      0.49     0.07    0.04%  _zsh_highlight_brackets_highlighter_predicate
 7)    7           0.45     0.06    0.03%      0.45     0.06    0.03%  _zsh_highlight_cursor_moved
 8)    6           0.21     0.04    0.02%      0.21     0.04    0.02%  g
 9)    1           1.12     1.12    0.08%      0.13     0.13    0.01%  _zsh_highlight_widget_accept-line
10)    1        1369.83  1369.83   99.24%      0.10     0.10    0.01%  _zsh_highlight_widget_bracketed-paste
11)    1           0.09     0.09    0.01%      0.09     0.09    0.01%  _zsh_highlight_apply_zle_highlight
12)    1           0.07     0.07    0.01%      0.07     0.07    0.01%  _zsh_highlight_preexec_hook
13)    1           0.06     0.06    0.00%      0.06     0.06    0.00%  _zsh_highlight_buffer_modified

Here, f is the first for loop and g the second.

[danielshahaf]

@doubleloop Is the behaviour under zsh -f with ZSH_HIGHLIGHT_HIGHLIGHTERS=(brackets) identical to the behaviour you were originally seeing?

[danielshahaf]

@doubleloop Can you try this patch?

diff --git a/highlighters/brackets/brackets-highlighter.zsh b/highlighters/brackets/brackets-highlighter.zsh
index 2571b58..ac9b426 100644
--- a/highlighters/brackets/brackets-highlighter.zsh
+++ b/highlighters/brackets/brackets-highlighter.zsh
@@ -52,7 +52,7 @@ _zsh_highlight_brackets_highlighter()
   region_highlight=()

   # Find all brackets and remember which one is matching
-  for (( pos = 0; pos < buflen; pos++ )) ; do
+  for pos in {0..${buflen}} ; do
     local char="$BUFFER[pos+1]"
     case $char in
       ["([{"])

Timing data:

$ zsh -f
% time (for (( x = 0; x < 1000000; x++ )) ; do done) 
( for ((x = 0; x < 1000000; x++ )) do; ; done; )  1.49s user 0.00s system 99% cpu 1.509 total
% time (for (( x = 0; x < 1000000; x++ )) ; do done) 
( for ((x = 0; x < 1000000; x++ )) do; ; done; )  1.52s user 0.00s system 99% cpu 1.529 total
% time (for (( x = 0; x < 1000000; x++ )) ; do done) 
( for ((x = 0; x < 1000000; x++ )) do; ; done; )  1.59s user 0.00s system 97% cpu 1.630 total
% 
% 
% time (for x in {0..999999} ; do done) 
( for x in {0..999999}; do; ; done; )  0.87s user 0.04s system 99% cpu 0.909 total
% time (for x in {0..999999} ; do done) 
( for x in {0..999999}; do; ; done; )  0.88s user 0.03s system 99% cpu 0.925 total
% time (for x in {0..999999} ; do done) 
( for x in {0..999999}; do; ; done; )  0.83s user 0.05s system 99% cpu 0.887 total

[doubleloop]

Strange.
I pulled current master with your commit (b52a485).

1. In case of zsh -f and ZSH_HIGHLIGHT_HIGHLIGHTERS=(brackets) there is no problem (still there is tiny improvement when I compare before and after commit but we talk about less then second)
2. When I use oh-my-zsh (current master) with all stuff commented out so entire zshrc file is this:

export ZSH=$HOME/.oh-my-zsh
plugins=(
    zsh-syntax-highlighting 
)
source $ZSH/oh-my-zsh.sh
ZSH_HIGHLIGHT_HIGHLIGHTERS=(brackets)

the issue is there (10+ minutes). When I comment ZSH_HIGHLIGHT_HIGHLIGHTERS=(brackets) everything works ok. In this situation the newest commit does not matter nor the patch you posted. I've never read oh-my-zsh code so just in case I did rm -rf ~/.oh-my-zsh/cache/* before testing.