1" Test Vim profiler 2if !has('profile') 3 finish 4endif 5 6func Test_profile_func() 7 let lines = [ 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 \ ] 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 = [ 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 \ ] 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 = [ 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 \ ] 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 = [ 313 \ 'func! Foo()', 314 \ 'endfunc', 315 \ 'for i in range(10)', 316 \ ' " a comment', 317 \ ' call Foo()', 318 \ 'endfor', 319 \ 'call Foo()', 320 \ ] 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 !has('multi_byte') || &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 = [ 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 call writefile(lines, 'Xprofile_file.vim') 472 call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') 473 call assert_equal(0, v:shell_error) 474 475 let lines = readfile('Xprofile_file.log') 476 call assert_equal(26, len(lines)) 477 478 " Check that: 479 " - Foo1() is called twice (profdel not invoked) 480 " - Foo2() is called once (profdel invoked after it was called) 481 " - Foo3() is not called (profdel invoked before it was called) 482 call assert_equal('FUNCTION Foo1()', lines[0]) 483 call assert_match('Defined:.*Xprofile_file.vim', lines[1]) 484 call assert_equal('Called 2 times', lines[2]) 485 call assert_equal('FUNCTION Foo2()', lines[8]) 486 call assert_equal('Called 1 time', lines[10]) 487 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[16]) 488 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[21]) 489 490 call delete('Xprofile_file.vim') 491 call delete('Xprofile_file.log') 492endfunc 493 494func Test_profdel_star() 495 " Foo() is invoked once before and once after 'profdel *'. 496 " So profiling should report it only once. 497 let lines = [ 498 \ 'profile start Xprofile_file.log', 499 \ 'func! Foo()', 500 \ 'endfunc', 501 \ 'profile func Foo', 502 \ 'call Foo()', 503 \ 'profdel *', 504 \ 'call Foo()' ] 505 call writefile(lines, 'Xprofile_file.vim') 506 call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') 507 call assert_equal(0, v:shell_error) 508 509 let lines = readfile('Xprofile_file.log') 510 call assert_equal(16, len(lines)) 511 512 call assert_equal('FUNCTION Foo()', lines[0]) 513 call assert_match('Defined:.*Xprofile_file.vim', lines[1]) 514 call assert_equal('Called 1 time', lines[2]) 515 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[8]) 516 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[12]) 517 518 call delete('Xprofile_file.vim') 519 call delete('Xprofile_file.log') 520endfunc 521