Wednesday, March 26, 2014

Re: Extremely slow when using relativenumber & syntax highlighting

patrick hemmer wrote:

> Whenever I have relative line number on (relativenumber), and
> syntax highlighting enabled (syntax on), moving the cursor is
> painfully slow. Not only moving between lines, but just moving
> the cursor left/right on the same line.
>
> I've tried removing my local .vim & .vimrc files as well as the
> ones in /etc to have a completely default config. As soon as
> I `syntax on` and `set rnu`, it starts exhibiting the issue.
>
> It doesn't seem to do this on all files though, just most. As a
> reliable way to duplicate the issue, I can copy the http://yaml.org
> web page content into a .yaml file, and edit that.
> But I get it in multiple languages, perl, yaml, ruby, & other.
>
> Version 7.4 with patches 1-193 (though I've had this behavior for years with older versions).


I can reproduce the slowness using the yaml file copied
from http://yaml.org

Here are some timings with and without relativenumber
when moving 50 times horizontally with l and h:

$ time vim -u NONE foo.yaml \
-c 'set relativenumber' \
-c 'syntax on' +10 \
-c 'call feedkeys("llllllllllhhhhhhhhhhllllllllllhhhhhhhhhhllllllllll:q\<CR>")'
real 0m4.677s
user 0m1.447s
sys 0m3.226s
--> slow!

$ time vim -u NONE foo.yaml \
-c 'set norelativenumber' \
-c 'syntax on' +10 \
-c 'call feedkeys("llllllllllhhhhhhhhhhllllllllllhhhhhhhhhhllllllllll:q\<CR>")'
real 0m0.166s
user 0m0.086s
sys 0m0.077s
--> fast

If I use ":syntime on" and ":syntime report", I see this:

With relativenumber:

TOTAL COUNT MATCH SLOWEST AVERAGE NAME PATTERN
3.706423 7752 7395 0.002521 0.000478 yamlPlainScalar
\%([\-?:,\[\]{}#&*!|>'"%@`]\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\|[?:\-]\%(\%(\%([\n\r\uFEFF \t]\)\@!\p\)\)\@=
1.105733 4029 2040 0.000742 0.000274 yamlFloat
\%([\[\]{}, \t]\@!\p\)\@<!\%([+-]\=\%(\%(\d[0-9_]*\)\.[0-9_]*\%([eE][+-]\d\+\)\=\|\.[0-9_]\+\%([eE][-+][0-
0.711836 1224 0 0.001174 0.000582 yamlBlockMappingKey
\%#=1\s*\zs\%([\-?:,\[\]{}#&*!|>'"%@`]\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\|[?:\-]\%(\%(\%([\n\r\uFEFF \t]\)\

0.481088 2703 153 0.000815 0.000178 yamlInteger
\%([\[\]{}, \t]\@!\p\)\@<!\%([+-]\=\%(0\%(b[0-1_]\+\|[0-7_]\+\|x[0-9a-fA-F_]\+\)\=\|\%([1-9][0-9_]*\%(:[0-
0.044233 2601 0 0.000042 0.000017 yamlTimestamp
\%([\[\]{}, \t]\@!\p\)\@<!\%(\d\{4}-\d\d\=-\d\d\=\%(\%([Tt]\|\s\+\)\%(\d\d\=\):\%(\d\d\):\%(\d\d\)\%(\.\%(
0.038902 2652 408 0.000056 0.000015 yamlBlockMappingKey
\%#=1^\s*\zs\%([\-?:,\[\]{}#&*!|>'"%@`]\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\|[?:\-]\%(\%(\%([\n\r\uFEFF \t]\)

0.023793 3825 2448 0.000029 0.000006 yamlComment
\%\(^\|\s\)#
0.007552 3825 1224 0.000009 0.000002
yamlBlockCollectionItemStart ^\s*\zs-\%(\s\+-\)*\s
0.006340 2601 0 0.000009 0.000002
yamlBlockMappingMerge ^\s*\zs<<\ze:\%(\s\|$\)
0.004530 1224 1224 0.000008 0.000004 yamlComment $
0.003572 2601 0 0.000008 0.000001 yamlDocumentEnd
^\.\.\.\ze\%(\s\|$\)
0.002253 2601 0 0.000003 0.000001 yamlFlowCollection \[
0.002248 2601 51 0.000031 0.000001 yamlDirective
^\ze%\%(\%([\n\r\uFEFF \t]\)\@!\p\)\+\s\+
0.002189 2601 51 0.000004 0.000001 yamlDocumentStart
^---\ze\%(\s\|$\)
0.001827 2601 0 0.000025 0.000001 yamlConstant \<\~\>
0.001594 2601 0 0.000019 0.000001 yamlMappingKeyStart ?\ze\s
0.001468 2703 255 0.000002 0.000001 yamlFlowString "
0.001446 2652 51 0.000002 0.000001 yamlFlowString '
0.001407 2601 0 0.000013 0.000001 yamlAlias
\*\%(\%([\n\r\uFEFF \t,\[\]{}]\)\@!\p\)\+
0.001404 2601 0 0.000002 0.000001 yamlFlowMapping {
0.001372 2601 0 0.000002 0.000001 yamlAnchor
&\%(\%([\n\r\uFEFF \t,\[\]{}]\)\@!\p\)\+
0.001313 2601 0 0.000002 0.000001 yamlNodeTag
!<\%(%\x\x\|\%(\w\|-\)\|[#/;?:@&=+$,.!~*''()\[\]]\)\+>\|\%(!\%(\w\|-\)\+!\|!!\|!\)\%(%\x\x\|\%(\w\|-\)\|[#
0.000839 1224 0 0.000002 0.000001
yamlBlockMappingMerge <<\ze\s*:\%(\s\|$\)
0.000823 408 408 0.000005 0.000002 yamlKeyValueDelimiter \s*:
0.000506 408 408 0.000003 0.000001 yamlKeyValueDelimiter \s*:
0.000503 51 0 0.000011 0.000010
yamlReservedDirective %\%(\%(TAG\|YAML\)\s\)\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\+
0.000147 51 51 0.000004 0.000003 yamlYAMLVersion \d\+\.\d\+
0.000128 51 51 0.000003 0.000003 yamlYAMLDirective %YAML\s\+
0.000121 51 51 0.000003 0.000002 yamlDirective $
0.000078 51 0 0.000002 0.000002 yamlTAGDirective %TAG\s\+
0.000062 102 102 0.000001 0.000001 yamlFlowString "
0.000052 102 0 0.000001 0.000001 yamlFlowString \\"
0.000028 51 0 0.000001 0.000001 yamlEscape
\\\%([\\"abefnrtv\^0_ NLP\n]\|x\x\x\|u\x\{4}\|U\x\{8}\)

6.155810 66351


Without relative number:

TOTAL COUNT MATCH SLOWEST AVERAGE NAME PATTERN
0.071678 152 145 0.001796 0.000472 yamlPlainScalar
\%([\-?:,\[\]{}#&*!|>'"%@`]\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\|[?:\-]\%(\%(\%([\n\r\uFEFF \t]\)\@!\p\)\)\@=
0.021474 79 40 0.000679 0.000272 yamlFloat
\%([\[\]{}, \t]\@!\p\)\@<!\%([+-]\=\%(\%(\d[0-9_]*\)\.[0-9_]*\%([eE][+-]\d\+\)\=\|\.[0-9_]\+\%([eE][-+][0-
0.013851 24 0 0.001121 0.000577 yamlBlockMappingKey
\%#=1\s*\zs\%([\-?:,\[\]{}#&*!|>'"%@`]\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\|[?:\-]\%(\%(\%([\n\r\uFEFF \t]\)\

0.009354 53 3 0.000627 0.000176 yamlInteger
\%([\[\]{}, \t]\@!\p\)\@<!\%([+-]\=\%(0\%(b[0-1_]\+\|[0-7_]\+\|x[0-9a-fA-F_]\+\)\=\|\%([1-9][0-9_]*\%(:[0-
0.000884 51 0 0.000029 0.000017 yamlTimestamp
\%([\[\]{}, \t]\@!\p\)\@<!\%(\d\{4}-\d\d\=-\d\d\=\%(\%([Tt]\|\s\+\)\%(\d\d\=\):\%(\d\d\):\%(\d\d\)\%(\.\%(
0.000778 52 8 0.000055 0.000015 yamlBlockMappingKey
\%#=1^\s*\zs\%([\-?:,\[\]{}#&*!|>'"%@`]\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\|[?:\-]\%(\%(\%([\n\r\uFEFF \t]\)

0.000469 75 48 0.000024 0.000006 yamlComment
\%\(^\|\s\)#
0.000150 75 24 0.000014 0.000002
yamlBlockCollectionItemStart ^\s*\zs-\%(\s\+-\)*\s
0.000115 51 0 0.000004 0.000002
yamlBlockMappingMerge ^\s*\zs<<\ze:\%(\s\|$\)
0.000088 24 24 0.000005 0.000004 yamlComment $
0.000074 51 0 0.000004 0.000001 yamlDocumentEnd
^\.\.\.\ze\%(\s\|$\)
0.000046 51 1 0.000021 0.000001 yamlDirective
^\ze%\%(\%([\n\r\uFEFF \t]\)\@!\p\)\+\s\+
0.000044 51 0 0.000001 0.000001 yamlFlowCollection \[
0.000043 51 1 0.000004 0.000001 yamlDocumentStart
^---\ze\%(\s\|$\)
0.000036 51 0 0.000001 0.000001 yamlConstant \<\~\>
0.000032 52 1 0.000001 0.000001 yamlFlowString '
0.000032 51 0 0.000001 0.000001 yamlFlowMapping {
0.000032 51 0 0.000002 0.000001 yamlMappingKeyStart ?\ze\s
0.000032 51 0 0.000001 0.000001 yamlAnchor
&\%(\%([\n\r\uFEFF \t,\[\]{}]\)\@!\p\)\+
0.000032 51 0 0.000001 0.000001 yamlAlias
\*\%(\%([\n\r\uFEFF \t,\[\]{}]\)\@!\p\)\+
0.000026 53 5 0.000001 0.000000 yamlFlowString "
0.000018 51 0 0.000001 0.000000 yamlNodeTag
!<\%(%\x\x\|\%(\w\|-\)\|[#/;?:@&=+$,.!~*''()\[\]]\)\+>\|\%(!\%(\w\|-\)\+!\|!!\|!\)\%(%\x\x\|\%(\w\|-\)\|[#
0.000017 24 0 0.000001 0.000001
yamlBlockMappingMerge <<\ze\s*:\%(\s\|$\)
0.000017 8 8 0.000003 0.000002 yamlKeyValueDelimiter \s*:
0.000011 1 0 0.000011 0.000011
yamlReservedDirective %\%(\%(TAG\|YAML\)\s\)\@!\%(\%([\n\r\uFEFF
\t]\)\@!\p\)\+
0.000009 8 8 0.000002 0.000001 yamlKeyValueDelimiter \s*:
0.000003 1 1 0.000003 0.000003 yamlDirective $
0.000003 1 1 0.000003 0.000003 yamlYAMLVersion \d\+\.\d\+
0.000002 1 1 0.000002 0.000002 yamlYAMLDirective %YAML\s\+
0.000002 2 0 0.000001 0.000001 yamlFlowString \\"
0.000001 1 0 0.000001 0.000001 yamlTAGDirective %TAG\s\+
0.000000 2 2 0.000000 0.000000 yamlFlowString "
0.000000 1 0 0.000000 0.000000 yamlEscape
\\\%([\\"abefnrtv\^0_ NLP\n]\|x\x\x\|u\x\{4}\|U\x\{8}\)

0.119353 1301

So somehow regexp are being checked far more often
when relativenumber is on, which does not seem right
considering that the command mostly moves horizontally.

Using callgrind, I see that:
* with 'norelativenumber', update_screen() was called only once
* with 'relativenumber', update_screen() was called 51 times

Notice that the command I used was moving:
- 50 times horizontally with h and l
- 1 time vertically using +10

This means that with relativenumber, update_screen() gets
called each time we move horizontally with h or l which does
not seem needed at first sight.

The code that seems responsible for the spurious redraw is:
move.c:1190 (commenting that line as a experiment makes it fast)
so the logic to decide whether to redraw is wrong but I can't see
how to fix it:

1175 /* Redraw when w_row changes and 'relativenumber' is set */
1176 if (((curwin->w_valid & VALID_WROW) == 0 && (curwin->w_p_rnu
1177 #ifdef FEAT_SYN_HL
1178 /* or when w_row changes and 'cursorline' is set. */
1179 || curwin->w_p_cul
1180

No comments: