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