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