1" Test Vim profiler 2 3source check.vim 4CheckFeature profile 5 6source shared.vim 7source screendump.vim 8 9func Test_profile_func() 10 let lines =<< trim [CODE] 11 profile start Xprofile_func.log 12 profile func Foo* 13 func! Foo1() 14 endfunc 15 func! Foo2() 16 let l:count = 100 17 while l:count > 0 18 let l:count = l:count - 1 19 endwhile 20 endfunc 21 func! Foo3() 22 endfunc 23 func! Bar() 24 endfunc 25 call Foo1() 26 call Foo1() 27 profile pause 28 call Foo1() 29 profile continue 30 call Foo2() 31 call Foo3() 32 call Bar() 33 if !v:profiling 34 delfunc Foo2 35 endif 36 delfunc Foo3 37 [CODE] 38 39 call writefile(lines, 'Xprofile_func.vim') 40 call system(GetVimCommand() 41 \ . ' -es --clean' 42 \ . ' -c "so Xprofile_func.vim"' 43 \ . ' -c "qall!"') 44 call assert_equal(0, v:shell_error) 45 46 let lines = readfile('Xprofile_func.log') 47 48 " - Foo1() is called 3 times but should be reported as called twice 49 " since one call is in between "profile pause" .. "profile continue". 50 " - Foo2() should come before Foo1() since Foo1() does much more work. 51 " - Foo3() is not reported because function is deleted. 52 " - Unlike Foo3(), Foo2() should not be deleted since there is a check 53 " for v:profiling. 54 " - Bar() is not reported since it does not match "profile func Foo*". 55 call assert_equal(30, len(lines)) 56 57 call assert_equal('FUNCTION Foo1()', lines[0]) 58 call assert_match('Defined:.*Xprofile_func.vim:3', lines[1]) 59 call assert_equal('Called 2 times', lines[2]) 60 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) 61 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) 62 call assert_equal('', lines[5]) 63 call assert_equal('count total (s) self (s)', lines[6]) 64 call assert_equal('', lines[7]) 65 call assert_equal('FUNCTION Foo2()', lines[8]) 66 call assert_equal('Called 1 time', lines[10]) 67 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[11]) 68 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[12]) 69 call assert_equal('', lines[13]) 70 call assert_equal('count total (s) self (s)', lines[14]) 71 call assert_match('^\s*1\s\+.*\slet l:count = 100$', lines[15]) 72 call assert_match('^\s*101\s\+.*\swhile l:count > 0$', lines[16]) 73 call assert_match('^\s*100\s\+.*\s let l:count = l:count - 1$', lines[17]) 74 call assert_match('^\s*101\s\+.*\sendwhile$', lines[18]) 75 call assert_equal('', lines[19]) 76 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[20]) 77 call assert_equal('count total (s) self (s) function', lines[21]) 78 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[22]) 79 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[23]) 80 call assert_equal('', lines[24]) 81 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[25]) 82 call assert_equal('count total (s) self (s) function', lines[26]) 83 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[27]) 84 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[28]) 85 call assert_equal('', lines[29]) 86 87 call delete('Xprofile_func.vim') 88 call delete('Xprofile_func.log') 89endfunc 90 91func Test_profile_func_with_ifelse() 92 let lines =<< trim [CODE] 93 func! Foo1() 94 if 1 95 let x = 0 96 elseif 1 97 let x = 1 98 else 99 let x = 2 100 endif 101 endfunc 102 func! Foo2() 103 if 0 104 let x = 0 105 elseif 1 106 let x = 1 107 else 108 let x = 2 109 endif 110 endfunc 111 func! Foo3() 112 if 0 113 let x = 0 114 elseif 0 115 let x = 1 116 else 117 let x = 2 118 endif 119 endfunc 120 call Foo1() 121 call Foo2() 122 call Foo3() 123 [CODE] 124 125 call writefile(lines, 'Xprofile_func.vim') 126 call system(GetVimCommand() 127 \ . ' -es -i NONE --noplugin' 128 \ . ' -c "profile start Xprofile_func.log"' 129 \ . ' -c "profile func Foo*"' 130 \ . ' -c "so Xprofile_func.vim"' 131 \ . ' -c "qall!"') 132 call assert_equal(0, v:shell_error) 133 134 let lines = readfile('Xprofile_func.log') 135 136 " - Foo1() should pass 'if' block. 137 " - Foo2() should pass 'elseif' block. 138 " - Foo3() should pass 'else' block. 139 call assert_equal(57, len(lines)) 140 141 call assert_equal('FUNCTION Foo1()', lines[0]) 142 call assert_match('Defined:.*Xprofile_func.vim', lines[1]) 143 call assert_equal('Called 1 time', lines[2]) 144 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) 145 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) 146 call assert_equal('', lines[5]) 147 call assert_equal('count total (s) self (s)', lines[6]) 148 call assert_match('^\s*1\s\+.*\sif 1$', lines[7]) 149 call assert_match('^\s*1\s\+.*\s let x = 0$', lines[8]) 150 call assert_match( '^\s\+elseif 1$', lines[9]) 151 call assert_match( '^\s\+let x = 1$', lines[10]) 152 call assert_match( '^\s\+else$', lines[11]) 153 call assert_match( '^\s\+let x = 2$', lines[12]) 154 call assert_match('^\s*1\s\+.*\sendif$', lines[13]) 155 call assert_equal('', lines[14]) 156 call assert_equal('FUNCTION Foo2()', lines[15]) 157 call assert_equal('Called 1 time', lines[17]) 158 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18]) 159 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19]) 160 call assert_equal('', lines[20]) 161 call assert_equal('count total (s) self (s)', lines[21]) 162 call assert_match('^\s*1\s\+.*\sif 0$', lines[22]) 163 call assert_match( '^\s\+let x = 0$', lines[23]) 164 call assert_match('^\s*1\s\+.*\selseif 1$', lines[24]) 165 call assert_match('^\s*1\s\+.*\s let x = 1$', lines[25]) 166 call assert_match( '^\s\+else$', lines[26]) 167 call assert_match( '^\s\+let x = 2$', lines[27]) 168 call assert_match('^\s*1\s\+.*\sendif$', lines[28]) 169 call assert_equal('', lines[29]) 170 call assert_equal('FUNCTION Foo3()', lines[30]) 171 call assert_equal('Called 1 time', lines[32]) 172 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33]) 173 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34]) 174 call assert_equal('', lines[35]) 175 call assert_equal('count total (s) self (s)', lines[36]) 176 call assert_match('^\s*1\s\+.*\sif 0$', lines[37]) 177 call assert_match( '^\s\+let x = 0$', lines[38]) 178 call assert_match('^\s*1\s\+.*\selseif 0$', lines[39]) 179 call assert_match( '^\s\+let x = 1$', lines[40]) 180 call assert_match('^\s*1\s\+.*\selse$', lines[41]) 181 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[42]) 182 call assert_match('^\s*1\s\+.*\sendif$', lines[43]) 183 call assert_equal('', lines[44]) 184 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45]) 185 call assert_equal('count total (s) self (s) function', lines[46]) 186 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47]) 187 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48]) 188 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49]) 189 call assert_equal('', lines[50]) 190 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51]) 191 call assert_equal('count total (s) self (s) function', lines[52]) 192 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53]) 193 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54]) 194 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55]) 195 call assert_equal('', lines[56]) 196 197 call delete('Xprofile_func.vim') 198 call delete('Xprofile_func.log') 199endfunc 200 201func Test_profile_func_with_trycatch() 202 let lines =<< trim [CODE] 203 func! Foo1() 204 try 205 let x = 0 206 catch 207 let x = 1 208 finally 209 let x = 2 210 endtry 211 endfunc 212 func! Foo2() 213 try 214 throw 0 215 catch 216 let x = 1 217 finally 218 let x = 2 219 endtry 220 endfunc 221 func! Foo3() 222 try 223 throw 0 224 catch 225 throw 1 226 finally 227 let x = 2 228 endtry 229 endfunc 230 call Foo1() 231 call Foo2() 232 try 233 call Foo3() 234 catch 235 endtry 236 [CODE] 237 238 call writefile(lines, 'Xprofile_func.vim') 239 call system(GetVimCommand() 240 \ . ' -es -i NONE --noplugin' 241 \ . ' -c "profile start Xprofile_func.log"' 242 \ . ' -c "profile func Foo*"' 243 \ . ' -c "so Xprofile_func.vim"' 244 \ . ' -c "qall!"') 245 call assert_equal(0, v:shell_error) 246 247 let lines = readfile('Xprofile_func.log') 248 249 " - Foo1() should pass 'try' 'finally' blocks. 250 " - Foo2() should pass 'catch' 'finally' blocks. 251 " - Foo3() should not pass 'endtry'. 252 call assert_equal(57, len(lines)) 253 254 call assert_equal('FUNCTION Foo1()', lines[0]) 255 call assert_match('Defined:.*Xprofile_func.vim', lines[1]) 256 call assert_equal('Called 1 time', lines[2]) 257 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3]) 258 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4]) 259 call assert_equal('', lines[5]) 260 call assert_equal('count total (s) self (s)', lines[6]) 261 call assert_match('^\s*1\s\+.*\stry$', lines[7]) 262 call assert_match('^\s*1\s\+.*\s let x = 0$', lines[8]) 263 call assert_match( '^\s\+catch$', lines[9]) 264 call assert_match( '^\s\+let x = 1$', lines[10]) 265 call assert_match('^\s*1\s\+.*\sfinally$', lines[11]) 266 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[12]) 267 call assert_match('^\s*1\s\+.*\sendtry$', lines[13]) 268 call assert_equal('', lines[14]) 269 call assert_equal('FUNCTION Foo2()', lines[15]) 270 call assert_equal('Called 1 time', lines[17]) 271 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18]) 272 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19]) 273 call assert_equal('', lines[20]) 274 call assert_equal('count total (s) self (s)', lines[21]) 275 call assert_match('^\s*1\s\+.*\stry$', lines[22]) 276 call assert_match('^\s*1\s\+.*\s throw 0$', lines[23]) 277 call assert_match('^\s*1\s\+.*\scatch$', lines[24]) 278 call assert_match('^\s*1\s\+.*\s let x = 1$', lines[25]) 279 call assert_match('^\s*1\s\+.*\sfinally$', lines[26]) 280 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[27]) 281 call assert_match('^\s*1\s\+.*\sendtry$', lines[28]) 282 call assert_equal('', lines[29]) 283 call assert_equal('FUNCTION Foo3()', lines[30]) 284 call assert_equal('Called 1 time', lines[32]) 285 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33]) 286 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34]) 287 call assert_equal('', lines[35]) 288 call assert_equal('count total (s) self (s)', lines[36]) 289 call assert_match('^\s*1\s\+.*\stry$', lines[37]) 290 call assert_match('^\s*1\s\+.*\s throw 0$', lines[38]) 291 call assert_match('^\s*1\s\+.*\scatch$', lines[39]) 292 call assert_match('^\s*1\s\+.*\s throw 1$', lines[40]) 293 call assert_match('^\s*1\s\+.*\sfinally$', lines[41]) 294 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[42]) 295 call assert_match( '^\s\+endtry$', lines[43]) 296 call assert_equal('', lines[44]) 297 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45]) 298 call assert_equal('count total (s) self (s) function', lines[46]) 299 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47]) 300 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48]) 301 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49]) 302 call assert_equal('', lines[50]) 303 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51]) 304 call assert_equal('count total (s) self (s) function', lines[52]) 305 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53]) 306 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54]) 307 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55]) 308 call assert_equal('', lines[56]) 309 310 call delete('Xprofile_func.vim') 311 call delete('Xprofile_func.log') 312endfunc 313 314func Test_profile_file() 315 let lines =<< trim [CODE] 316 func! Foo() 317 endfunc 318 for i in range(10) 319 " a comment 320 call Foo() 321 endfor 322 call Foo() 323 [CODE] 324 325 call writefile(lines, 'Xprofile_file.vim') 326 call system(GetVimCommandClean() 327 \ . ' -es' 328 \ . ' -c "profile start Xprofile_file.log"' 329 \ . ' -c "profile file Xprofile_file.vim"' 330 \ . ' -c "so Xprofile_file.vim"' 331 \ . ' -c "so Xprofile_file.vim"' 332 \ . ' -c "qall!"') 333 call assert_equal(0, v:shell_error) 334 335 let lines = readfile('Xprofile_file.log') 336 337 call assert_equal(14, len(lines)) 338 339 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) 340 call assert_equal('Sourced 2 times', lines[1]) 341 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) 342 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) 343 call assert_equal('', lines[4]) 344 call assert_equal('count total (s) self (s)', lines[5]) 345 call assert_match(' 2 0.\d\+ func! Foo()', lines[6]) 346 call assert_equal(' endfunc', lines[7]) 347 " Loop iterates 10 times. Since script runs twice, body executes 20 times. 348 " First line of loop executes one more time than body to detect end of loop. 349 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+for i in range(10)$', lines[8]) 350 call assert_equal(' " a comment', lines[9]) 351 " if self and total are equal we only get one number 352 call assert_match('^\s*20\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[10]) 353 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+endfor$', lines[11]) 354 " if self and total are equal we only get one number 355 call assert_match('^\s*2\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[12]) 356 call assert_equal('', lines[13]) 357 358 call delete('Xprofile_file.vim') 359 call delete('Xprofile_file.log') 360endfunc 361 362func Test_profile_file_with_cont() 363 let lines = [ 364 \ 'echo "hello', 365 \ ' \ world"', 366 \ 'echo "foo ', 367 \ ' \bar"', 368 \ ] 369 370 call writefile(lines, 'Xprofile_file.vim') 371 call system(GetVimCommandClean() 372 \ . ' -es' 373 \ . ' -c "profile start Xprofile_file.log"' 374 \ . ' -c "profile file Xprofile_file.vim"' 375 \ . ' -c "so Xprofile_file.vim"' 376 \ . ' -c "qall!"') 377 call assert_equal(0, v:shell_error) 378 379 let lines = readfile('Xprofile_file.log') 380 call assert_equal(11, len(lines)) 381 382 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) 383 call assert_equal('Sourced 1 time', lines[1]) 384 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) 385 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) 386 call assert_equal('', lines[4]) 387 call assert_equal('count total (s) self (s)', lines[5]) 388 call assert_match(' 1 0.\d\+ echo "hello', lines[6]) 389 call assert_equal(' \ world"', lines[7]) 390 call assert_match(' 1 0.\d\+ echo "foo ', lines[8]) 391 call assert_equal(' \bar"', lines[9]) 392 call assert_equal('', lines[10]) 393 394 call delete('Xprofile_file.vim') 395 call delete('Xprofile_file.log') 396endfunc 397 398func Test_profile_completion() 399 call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx') 400 call assert_equal('"profile continue file func pause start', @:) 401 402 call feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx') 403 call assert_match('^"profile start.* test_profile\.vim', @:) 404endfunc 405 406func Test_profile_errors() 407 call assert_fails("profile func Foo", 'E750:') 408 call assert_fails("profile pause", 'E750:') 409 call assert_fails("profile continue", 'E750:') 410endfunc 411 412func Test_profile_truncate_mbyte() 413 if &enc !=# 'utf-8' 414 return 415 endif 416 417 let lines = [ 418 \ 'scriptencoding utf-8', 419 \ 'func! Foo()', 420 \ ' return [', 421 \ ' \ "' . join(map(range(0x4E00, 0x4E00 + 340), 'nr2char(v:val)'), '') . '",', 422 \ ' \ "' . join(map(range(0x4F00, 0x4F00 + 340), 'nr2char(v:val)'), '') . '",', 423 \ ' \ ]', 424 \ 'endfunc', 425 \ 'call Foo()', 426 \ ] 427 428 call writefile(lines, 'Xprofile_file.vim') 429 call system(GetVimCommandClean() 430 \ . ' -es --cmd "set enc=utf-8"' 431 \ . ' -c "profile start Xprofile_file.log"' 432 \ . ' -c "profile file Xprofile_file.vim"' 433 \ . ' -c "so Xprofile_file.vim"' 434 \ . ' -c "qall!"') 435 call assert_equal(0, v:shell_error) 436 437 split Xprofile_file.log 438 if &fenc != '' 439 call assert_equal('utf-8', &fenc) 440 endif 441 /func! Foo() 442 let lnum = line('.') 443 call assert_match('^\s*return \[$', getline(lnum + 1)) 444 call assert_match("\u4F52$", getline(lnum + 2)) 445 call assert_match("\u5052$", getline(lnum + 3)) 446 call assert_match('^\s*\\ \]$', getline(lnum + 4)) 447 bwipe! 448 449 call delete('Xprofile_file.vim') 450 call delete('Xprofile_file.log') 451endfunc 452 453func Test_profdel_func() 454 let lines =<< trim [CODE] 455 profile start Xprofile_file.log 456 func! Foo1() 457 endfunc 458 func! Foo2() 459 endfunc 460 func! Foo3() 461 endfunc 462 463 profile func Foo1 464 profile func Foo2 465 call Foo1() 466 call Foo2() 467 468 profile func Foo3 469 profdel func Foo2 470 profdel func Foo3 471 call Foo1() 472 call Foo2() 473 call Foo3() 474 [CODE] 475 call writefile(lines, 'Xprofile_file.vim') 476 call system(GetVimCommandClean() . ' -es -c "so Xprofile_file.vim" -c q') 477 call assert_equal(0, v:shell_error) 478 479 let lines = readfile('Xprofile_file.log') 480 call assert_equal(26, len(lines)) 481 482 " Check that: 483 " - Foo1() is called twice (profdel not invoked) 484 " - Foo2() is called once (profdel invoked after it was called) 485 " - Foo3() is not called (profdel invoked before it was called) 486 call assert_equal('FUNCTION Foo1()', lines[0]) 487 call assert_match('Defined:.*Xprofile_file.vim', lines[1]) 488 call assert_equal('Called 2 times', lines[2]) 489 call assert_equal('FUNCTION Foo2()', lines[8]) 490 call assert_equal('Called 1 time', lines[10]) 491 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[16]) 492 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[21]) 493 494 call delete('Xprofile_file.vim') 495 call delete('Xprofile_file.log') 496endfunc 497 498func Test_profdel_star() 499 " Foo() is invoked once before and once after 'profdel *'. 500 " So profiling should report it only once. 501 let lines =<< trim [CODE] 502 profile start Xprofile_file.log 503 func! Foo() 504 endfunc 505 profile func Foo 506 call Foo() 507 profdel * 508 call Foo() 509 [CODE] 510 call writefile(lines, 'Xprofile_file.vim') 511 call system(GetVimCommandClean() . ' -es -c "so Xprofile_file.vim" -c q') 512 call assert_equal(0, v:shell_error) 513 514 let lines = readfile('Xprofile_file.log') 515 call assert_equal(16, len(lines)) 516 517 call assert_equal('FUNCTION Foo()', lines[0]) 518 call assert_match('Defined:.*Xprofile_file.vim', lines[1]) 519 call assert_equal('Called 1 time', lines[2]) 520 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[8]) 521 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[12]) 522 523 call delete('Xprofile_file.vim') 524 call delete('Xprofile_file.log') 525endfunc 526 527" When typing the function it won't have a script ID, test that this works. 528func Test_profile_typed_func() 529 CheckScreendump 530 531 let lines =<< trim END 532 profile start XprofileTypedFunc 533 END 534 call writefile(lines, 'XtestProfile') 535 let buf = RunVimInTerminal('-S XtestProfile', #{}) 536 537 call term_sendkeys(buf, ":func DoSomething()\<CR>" 538 \ .. "echo 'hello'\<CR>" 539 \ .. "endfunc\<CR>") 540 call term_sendkeys(buf, ":profile func DoSomething\<CR>") 541 call term_sendkeys(buf, ":call DoSomething()\<CR>") 542 call term_wait(buf, 200) 543 call StopVimInTerminal(buf) 544 let lines = readfile('XprofileTypedFunc') 545 call assert_equal("FUNCTION DoSomething()", lines[0]) 546 call assert_equal("Called 1 time", lines[1]) 547 548 " clean up 549 call delete('XprofileTypedFunc') 550 call delete('XtestProfile') 551endfunc 552