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