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