Thursday, March 27, 2014

Re: Extremely slow when using relativenumber & syntax highlighting

[fullquote, since copying vim-dev]
Am 2014-03-27 00:05, schrieb Dominique Pellé:
> 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: