Mercurial > vim
view src/testdir/test_profile.vim @ 15753:14581b56bb87
Added tag v8.1.0883 for changeset bd442b02c9e5aade2180796268146365862ee9a2
author | Bram Moolenaar <Bram@vim.org> |
---|---|
date | Fri, 08 Feb 2019 17:00:08 +0100 |
parents | 2dcaa860e3fc |
children | 9c90cf08cfa8 |
line wrap: on
line source
" Test Vim profiler if !has('profile') finish endif func Test_profile_func() let lines = [ \ 'profile start Xprofile_func.log', \ 'profile func Foo*"', \ "func! Foo1()", \ "endfunc", \ "func! Foo2()", \ " let l:count = 100", \ " while l:count > 0", \ " let l:count = l:count - 1", \ " endwhile", \ "endfunc", \ "func! Foo3()", \ "endfunc", \ "func! Bar()", \ "endfunc", \ "call Foo1()", \ "call Foo1()", \ "profile pause", \ "call Foo1()", \ "profile continue", \ "call Foo2()", \ "call Foo3()", \ "call Bar()", \ "if !v:profiling", \ " delfunc Foo2", \ "endif", \ "delfunc Foo3", \ ] call writefile(lines, 'Xprofile_func.vim') call system(v:progpath \ . ' -es --clean' \ . ' -c "so Xprofile_func.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_func.log') " - Foo1() is called 3 times but should be reported as called twice " since one call is in between "profile pause" .. "profile continue". " - Foo2() should come before Foo1() since Foo1() does much more work. " - Foo3() is not reported because function is deleted. " - Unlike Foo3(), Foo2() should not be deleted since there is a check " for v:profiling. " - Bar() is not reported since it does not match "profile func Foo*". call assert_equal(30, len(lines)) call assert_equal('FUNCTION Foo1()', lines[0]) call assert_match('Defined:.*Xprofile_func.vim', lines[1]) call assert_equal('Called 2 times', lines[2]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) call assert_equal('', lines[5]) call assert_equal('count total (s) self (s)', lines[6]) call assert_equal('', lines[7]) call assert_equal('FUNCTION Foo2()', lines[8]) call assert_equal('Called 1 time', lines[10]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[11]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[12]) call assert_equal('', lines[13]) call assert_equal('count total (s) self (s)', lines[14]) call assert_match('^\s*1\s\+.*\slet l:count = 100$', lines[15]) call assert_match('^\s*101\s\+.*\swhile l:count > 0$', lines[16]) call assert_match('^\s*100\s\+.*\s let l:count = l:count - 1$', lines[17]) call assert_match('^\s*101\s\+.*\sendwhile$', lines[18]) call assert_equal('', lines[19]) call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[20]) call assert_equal('count total (s) self (s) function', lines[21]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[22]) call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[23]) call assert_equal('', lines[24]) call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[25]) call assert_equal('count total (s) self (s) function', lines[26]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[27]) call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[28]) call assert_equal('', lines[29]) call delete('Xprofile_func.vim') call delete('Xprofile_func.log') endfunc func Test_profile_func_with_ifelse() let lines = [ \ "func! Foo1()", \ " if 1", \ " let x = 0", \ " elseif 1", \ " let x = 1", \ " else", \ " let x = 2", \ " endif", \ "endfunc", \ "func! Foo2()", \ " if 0", \ " let x = 0", \ " elseif 1", \ " let x = 1", \ " else", \ " let x = 2", \ " endif", \ "endfunc", \ "func! Foo3()", \ " if 0", \ " let x = 0", \ " elseif 0", \ " let x = 1", \ " else", \ " let x = 2", \ " endif", \ "endfunc", \ "call Foo1()", \ "call Foo2()", \ "call Foo3()", \ ] call writefile(lines, 'Xprofile_func.vim') call system(v:progpath \ . ' -es -u NONE -U NONE -i NONE --noplugin' \ . ' -c "profile start Xprofile_func.log"' \ . ' -c "profile func Foo*"' \ . ' -c "so Xprofile_func.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_func.log') " - Foo1() should pass 'if' block. " - Foo2() should pass 'elseif' block. " - Foo3() should pass 'else' block. call assert_equal(57, len(lines)) call assert_equal('FUNCTION Foo1()', lines[0]) call assert_match('Defined:.*Xprofile_func.vim', lines[1]) call assert_equal('Called 1 time', lines[2]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) call assert_equal('', lines[5]) call assert_equal('count total (s) self (s)', lines[6]) call assert_match('^\s*1\s\+.*\sif 1$', lines[7]) call assert_match('^\s*1\s\+.*\s let x = 0$', lines[8]) call assert_match( '^\s\+elseif 1$', lines[9]) call assert_match( '^\s\+let x = 1$', lines[10]) call assert_match( '^\s\+else$', lines[11]) call assert_match( '^\s\+let x = 2$', lines[12]) call assert_match('^\s*1\s\+.*\sendif$', lines[13]) call assert_equal('', lines[14]) call assert_equal('FUNCTION Foo2()', lines[15]) call assert_equal('Called 1 time', lines[17]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19]) call assert_equal('', lines[20]) call assert_equal('count total (s) self (s)', lines[21]) call assert_match('^\s*1\s\+.*\sif 0$', lines[22]) call assert_match( '^\s\+let x = 0$', lines[23]) call assert_match('^\s*1\s\+.*\selseif 1$', lines[24]) call assert_match('^\s*1\s\+.*\s let x = 1$', lines[25]) call assert_match( '^\s\+else$', lines[26]) call assert_match( '^\s\+let x = 2$', lines[27]) call assert_match('^\s*1\s\+.*\sendif$', lines[28]) call assert_equal('', lines[29]) call assert_equal('FUNCTION Foo3()', lines[30]) call assert_equal('Called 1 time', lines[32]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34]) call assert_equal('', lines[35]) call assert_equal('count total (s) self (s)', lines[36]) call assert_match('^\s*1\s\+.*\sif 0$', lines[37]) call assert_match( '^\s\+let x = 0$', lines[38]) call assert_match('^\s*1\s\+.*\selseif 0$', lines[39]) call assert_match( '^\s\+let x = 1$', lines[40]) call assert_match('^\s*1\s\+.*\selse$', lines[41]) call assert_match('^\s*1\s\+.*\s let x = 2$', lines[42]) call assert_match('^\s*1\s\+.*\sendif$', lines[43]) call assert_equal('', lines[44]) call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45]) call assert_equal('count total (s) self (s) function', lines[46]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49]) call assert_equal('', lines[50]) call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51]) call assert_equal('count total (s) self (s) function', lines[52]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55]) call assert_equal('', lines[56]) call delete('Xprofile_func.vim') call delete('Xprofile_func.log') endfunc func Test_profile_func_with_trycatch() let lines = [ \ "func! Foo1()", \ " try", \ " let x = 0", \ " catch", \ " let x = 1", \ " finally", \ " let x = 2", \ " endtry", \ "endfunc", \ "func! Foo2()", \ " try", \ " throw 0", \ " catch", \ " let x = 1", \ " finally", \ " let x = 2", \ " endtry", \ "endfunc", \ "func! Foo3()", \ " try", \ " throw 0", \ " catch", \ " throw 1", \ " finally", \ " let x = 2", \ " endtry", \ "endfunc", \ "call Foo1()", \ "call Foo2()", \ "try", \ " call Foo3()", \ "catch", \ "endtry", \ ] call writefile(lines, 'Xprofile_func.vim') call system(v:progpath \ . ' -es -u NONE -U NONE -i NONE --noplugin' \ . ' -c "profile start Xprofile_func.log"' \ . ' -c "profile func Foo*"' \ . ' -c "so Xprofile_func.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_func.log') " - Foo1() should pass 'try' 'finally' blocks. " - Foo2() should pass 'catch' 'finally' blocks. " - Foo3() should not pass 'endtry'. call assert_equal(57, len(lines)) call assert_equal('FUNCTION Foo1()', lines[0]) call assert_match('Defined:.*Xprofile_func.vim', lines[1]) call assert_equal('Called 1 time', lines[2]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) call assert_equal('', lines[5]) call assert_equal('count total (s) self (s)', lines[6]) call assert_match('^\s*1\s\+.*\stry$', lines[7]) call assert_match('^\s*1\s\+.*\s let x = 0$', lines[8]) call assert_match( '^\s\+catch$', lines[9]) call assert_match( '^\s\+let x = 1$', lines[10]) call assert_match('^\s*1\s\+.*\sfinally$', lines[11]) call assert_match('^\s*1\s\+.*\s let x = 2$', lines[12]) call assert_match('^\s*1\s\+.*\sendtry$', lines[13]) call assert_equal('', lines[14]) call assert_equal('FUNCTION Foo2()', lines[15]) call assert_equal('Called 1 time', lines[17]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19]) call assert_equal('', lines[20]) call assert_equal('count total (s) self (s)', lines[21]) call assert_match('^\s*1\s\+.*\stry$', lines[22]) call assert_match('^\s*1\s\+.*\s throw 0$', lines[23]) call assert_match('^\s*1\s\+.*\scatch$', lines[24]) call assert_match('^\s*1\s\+.*\s let x = 1$', lines[25]) call assert_match('^\s*1\s\+.*\sfinally$', lines[26]) call assert_match('^\s*1\s\+.*\s let x = 2$', lines[27]) call assert_match('^\s*1\s\+.*\sendtry$', lines[28]) call assert_equal('', lines[29]) call assert_equal('FUNCTION Foo3()', lines[30]) call assert_equal('Called 1 time', lines[32]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34]) call assert_equal('', lines[35]) call assert_equal('count total (s) self (s)', lines[36]) call assert_match('^\s*1\s\+.*\stry$', lines[37]) call assert_match('^\s*1\s\+.*\s throw 0$', lines[38]) call assert_match('^\s*1\s\+.*\scatch$', lines[39]) call assert_match('^\s*1\s\+.*\s throw 1$', lines[40]) call assert_match('^\s*1\s\+.*\sfinally$', lines[41]) call assert_match('^\s*1\s\+.*\s let x = 2$', lines[42]) call assert_match( '^\s\+endtry$', lines[43]) call assert_equal('', lines[44]) call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45]) call assert_equal('count total (s) self (s) function', lines[46]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49]) call assert_equal('', lines[50]) call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51]) call assert_equal('count total (s) self (s) function', lines[52]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54]) call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55]) call assert_equal('', lines[56]) call delete('Xprofile_func.vim') call delete('Xprofile_func.log') endfunc func Test_profile_file() let lines = [ \ 'func! Foo()', \ 'endfunc', \ 'for i in range(10)', \ ' " a comment', \ ' call Foo()', \ 'endfor', \ 'call Foo()', \ ] call writefile(lines, 'Xprofile_file.vim') call system(v:progpath \ . ' -es --clean' \ . ' -c "profile start Xprofile_file.log"' \ . ' -c "profile file Xprofile_file.vim"' \ . ' -c "so Xprofile_file.vim"' \ . ' -c "so Xprofile_file.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_file.log') call assert_equal(14, len(lines)) call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) call assert_equal('Sourced 2 times', lines[1]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) call assert_equal('', lines[4]) call assert_equal('count total (s) self (s)', lines[5]) call assert_match(' 2 0.\d\+ func! Foo()', lines[6]) call assert_equal(' endfunc', lines[7]) " Loop iterates 10 times. Since script runs twice, body executes 20 times. " First line of loop executes one more time than body to detect end of loop. call assert_match('^\s*22\s\+\d\+\.\d\+\s\+for i in range(10)$', lines[8]) call assert_equal(' " a comment', lines[9]) " if self and total are equal we only get one number call assert_match('^\s*20\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[10]) call assert_match('^\s*22\s\+\d\+\.\d\+\s\+endfor$', lines[11]) " if self and total are equal we only get one number call assert_match('^\s*2\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[12]) call assert_equal('', lines[13]) call delete('Xprofile_file.vim') call delete('Xprofile_file.log') endfunc func Test_profile_file_with_cont() let lines = [ \ 'echo "hello', \ ' \ world"', \ 'echo "foo ', \ ' \bar"', \ ] call writefile(lines, 'Xprofile_file.vim') call system(v:progpath \ . ' -es --clean' \ . ' -c "profile start Xprofile_file.log"' \ . ' -c "profile file Xprofile_file.vim"' \ . ' -c "so Xprofile_file.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_file.log') call assert_equal(11, len(lines)) call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) call assert_equal('Sourced 1 time', lines[1]) call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) call assert_equal('', lines[4]) call assert_equal('count total (s) self (s)', lines[5]) call assert_match(' 1 0.\d\+ echo "hello', lines[6]) call assert_equal(' \ world"', lines[7]) call assert_match(' 1 0.\d\+ echo "foo ', lines[8]) call assert_equal(' \bar"', lines[9]) call assert_equal('', lines[10]) call delete('Xprofile_file.vim') call delete('Xprofile_file.log') endfunc func Test_profile_completion() call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx') call assert_equal('"profile continue file func pause start', @:) call feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx') call assert_match('^"profile start.* test_profile\.vim', @:) endfunc func Test_profile_errors() call assert_fails("profile func Foo", 'E750:') call assert_fails("profile pause", 'E750:') call assert_fails("profile continue", 'E750:') endfunc func Test_profile_truncate_mbyte() if &enc !=# 'utf-8' return endif let lines = [ \ 'scriptencoding utf-8', \ 'func! Foo()', \ ' return [', \ ' \ "' . join(map(range(0x4E00, 0x4E00 + 340), 'nr2char(v:val)'), '') . '",', \ ' \ "' . join(map(range(0x4F00, 0x4F00 + 340), 'nr2char(v:val)'), '') . '",', \ ' \ ]', \ 'endfunc', \ 'call Foo()', \ ] call writefile(lines, 'Xprofile_file.vim') call system(v:progpath \ . ' -es --clean --cmd "set enc=utf-8"' \ . ' -c "profile start Xprofile_file.log"' \ . ' -c "profile file Xprofile_file.vim"' \ . ' -c "so Xprofile_file.vim"' \ . ' -c "qall!"') call assert_equal(0, v:shell_error) split Xprofile_file.log if &fenc != '' call assert_equal('utf-8', &fenc) endif /func! Foo() let lnum = line('.') call assert_match('^\s*return \[$', getline(lnum + 1)) call assert_match("\u4F52$", getline(lnum + 2)) call assert_match("\u5052$", getline(lnum + 3)) call assert_match('^\s*\\ \]$', getline(lnum + 4)) bwipe! call delete('Xprofile_file.vim') call delete('Xprofile_file.log') endfunc func Test_profdel_func() let lines = [ \ 'profile start Xprofile_file.log', \ 'func! Foo1()', \ 'endfunc', \ 'func! Foo2()', \ 'endfunc', \ 'func! Foo3()', \ 'endfunc', \ '', \ 'profile func Foo1', \ 'profile func Foo2', \ 'call Foo1()', \ 'call Foo2()', \ '', \ 'profile func Foo3', \ 'profdel func Foo2', \ 'profdel func Foo3', \ 'call Foo1()', \ 'call Foo2()', \ 'call Foo3()' ] call writefile(lines, 'Xprofile_file.vim') call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_file.log') call assert_equal(26, len(lines)) " Check that: " - Foo1() is called twice (profdel not invoked) " - Foo2() is called once (profdel invoked after it was called) " - Foo3() is not called (profdel invoked before it was called) call assert_equal('FUNCTION Foo1()', lines[0]) call assert_match('Defined:.*Xprofile_file.vim', lines[1]) call assert_equal('Called 2 times', lines[2]) call assert_equal('FUNCTION Foo2()', lines[8]) call assert_equal('Called 1 time', lines[10]) call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[16]) call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[21]) call delete('Xprofile_file.vim') call delete('Xprofile_file.log') endfunc func Test_profdel_star() " Foo() is invoked once before and once after 'profdel *'. " So profiling should report it only once. let lines = [ \ 'profile start Xprofile_file.log', \ 'func! Foo()', \ 'endfunc', \ 'profile func Foo', \ 'call Foo()', \ 'profdel *', \ 'call Foo()' ] call writefile(lines, 'Xprofile_file.vim') call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') call assert_equal(0, v:shell_error) let lines = readfile('Xprofile_file.log') call assert_equal(16, len(lines)) call assert_equal('FUNCTION Foo()', lines[0]) call assert_match('Defined:.*Xprofile_file.vim', lines[1]) call assert_equal('Called 1 time', lines[2]) call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[8]) call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[12]) call delete('Xprofile_file.vim') call delete('Xprofile_file.log') endfunc