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(28, len(lines)) 53 54 call assert_equal('FUNCTION Foo1()', lines[0]) 55 call assert_equal('Called 2 times', lines[1]) 56 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) 57 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) 58 call assert_equal('', lines[4]) 59 call assert_equal('count total (s) self (s)', lines[5]) 60 call assert_equal('', lines[6]) 61 call assert_equal('FUNCTION Foo2()', lines[7]) 62 call assert_equal('Called 1 time', lines[8]) 63 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[9]) 64 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[10]) 65 call assert_equal('', lines[11]) 66 call assert_equal('count total (s) self (s)', lines[12]) 67 call assert_match('^\s*1\s\+.*\slet l:count = 100$', lines[13]) 68 call assert_match('^\s*101\s\+.*\swhile l:count > 0$', lines[14]) 69 call assert_match('^\s*100\s\+.*\s let l:count = l:count - 1$', lines[15]) 70 call assert_match('^\s*100\s\+.*\sendwhile$', lines[16]) 71 call assert_equal('', lines[17]) 72 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[18]) 73 call assert_equal('count total (s) self (s) function', lines[19]) 74 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[20]) 75 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[21]) 76 call assert_equal('', lines[22]) 77 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[23]) 78 call assert_equal('count total (s) self (s) function', lines[24]) 79 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[25]) 80 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[26]) 81 call assert_equal('', lines[27]) 82 83 call delete('Xprofile_func.vim') 84 call delete('Xprofile_func.log') 85endfunc 86 87func Test_profile_file() 88 let lines = [ 89 \ 'func! Foo()', 90 \ 'endfunc', 91 \ 'for i in range(10)', 92 \ ' " a comment', 93 \ ' call Foo()', 94 \ 'endfor', 95 \ 'call Foo()', 96 \ ] 97 98 call writefile(lines, 'Xprofile_file.vim') 99 call system(v:progpath 100 \ . ' -es --clean' 101 \ . ' -c "profile start Xprofile_file.log"' 102 \ . ' -c "profile file Xprofile_file.vim"' 103 \ . ' -c "so Xprofile_file.vim"' 104 \ . ' -c "so Xprofile_file.vim"' 105 \ . ' -c "qall!"') 106 call assert_equal(0, v:shell_error) 107 108 let lines = readfile('Xprofile_file.log') 109 110 call assert_equal(14, len(lines)) 111 112 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) 113 call assert_equal('Sourced 2 times', lines[1]) 114 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) 115 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) 116 call assert_equal('', lines[4]) 117 call assert_equal('count total (s) self (s)', lines[5]) 118 call assert_match(' 2 0.\d\+ func! Foo()', lines[6]) 119 call assert_equal(' endfunc', lines[7]) 120 " Loop iterates 10 times. Since script runs twice, body executes 20 times. 121 " First line of loop executes one more time than body to detect end of loop. 122 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+for i in range(10)$', lines[8]) 123 call assert_equal(' " a comment', lines[9]) 124 " if self and total are equal we only get one number 125 call assert_match('^\s*20\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[10]) 126 call assert_match('^\s*20\s\+\d\+\.\d\+\s\+endfor$', lines[11]) 127 " if self and total are equal we only get one number 128 call assert_match('^\s*2\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[12]) 129 call assert_equal('', lines[13]) 130 131 call delete('Xprofile_file.vim') 132 call delete('Xprofile_file.log') 133endfunc 134 135func Test_profile_file_with_cont() 136 let lines = [ 137 \ 'echo "hello', 138 \ ' \ world"', 139 \ 'echo "foo ', 140 \ ' \bar"', 141 \ ] 142 143 call writefile(lines, 'Xprofile_file.vim') 144 call system(v:progpath 145 \ . ' -es --clean' 146 \ . ' -c "profile start Xprofile_file.log"' 147 \ . ' -c "profile file Xprofile_file.vim"' 148 \ . ' -c "so Xprofile_file.vim"' 149 \ . ' -c "qall!"') 150 call assert_equal(0, v:shell_error) 151 152 let lines = readfile('Xprofile_file.log') 153 call assert_equal(11, len(lines)) 154 155 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0]) 156 call assert_equal('Sourced 1 time', lines[1]) 157 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2]) 158 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3]) 159 call assert_equal('', lines[4]) 160 call assert_equal('count total (s) self (s)', lines[5]) 161 call assert_match(' 1 0.\d\+ echo "hello', lines[6]) 162 call assert_equal(' \ world"', lines[7]) 163 call assert_match(' 1 0.\d\+ echo "foo ', lines[8]) 164 call assert_equal(' \bar"', lines[9]) 165 call assert_equal('', lines[10]) 166 167 call delete('Xprofile_file.vim') 168 call delete('Xprofile_file.log') 169endfunc 170 171func Test_profile_completion() 172 call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx') 173 call assert_equal('"profile continue file func pause start', @:) 174 175 call feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx') 176 call assert_match('^"profile start.* test_profile\.vim', @:) 177endfunc 178 179func Test_profile_errors() 180 call assert_fails("profile func Foo", 'E750:') 181 call assert_fails("profile pause", 'E750:') 182 call assert_fails("profile continue", 'E750:') 183endfunc 184 185func Test_profile_truncate_mbyte() 186 if !has('multi_byte') || &enc !=# 'utf-8' 187 return 188 endif 189 190 let lines = [ 191 \ 'scriptencoding utf-8', 192 \ 'func! Foo()', 193 \ ' return [', 194 \ ' \ "' . join(map(range(0x4E00, 0x4E00 + 340), 'nr2char(v:val)'), '') . '",', 195 \ ' \ "' . join(map(range(0x4F00, 0x4F00 + 340), 'nr2char(v:val)'), '') . '",', 196 \ ' \ ]', 197 \ 'endfunc', 198 \ 'call Foo()', 199 \ ] 200 201 call writefile(lines, 'Xprofile_file.vim') 202 call system(v:progpath 203 \ . ' -es --clean --cmd "set enc=utf-8"' 204 \ . ' -c "profile start Xprofile_file.log"' 205 \ . ' -c "profile file Xprofile_file.vim"' 206 \ . ' -c "so Xprofile_file.vim"' 207 \ . ' -c "qall!"') 208 call assert_equal(0, v:shell_error) 209 210 split Xprofile_file.log 211 if &fenc != '' 212 call assert_equal('utf-8', &fenc) 213 endif 214 /func! Foo() 215 let lnum = line('.') 216 call assert_match('^\s*return \[$', getline(lnum + 1)) 217 call assert_match("\u4F52$", getline(lnum + 2)) 218 call assert_match("\u5052$", getline(lnum + 3)) 219 call assert_match('^\s*\\ \]$', getline(lnum + 4)) 220 bwipe! 221 222 call delete('Xprofile_file.vim') 223 call delete('Xprofile_file.log') 224endfunc 225 226func Test_profdel_func() 227 let lines = [ 228 \ 'profile start Xprofile_file.log', 229 \ 'func! Foo1()', 230 \ 'endfunc', 231 \ 'func! Foo2()', 232 \ 'endfunc', 233 \ 'func! Foo3()', 234 \ 'endfunc', 235 \ '', 236 \ 'profile func Foo1', 237 \ 'profile func Foo2', 238 \ 'call Foo1()', 239 \ 'call Foo2()', 240 \ '', 241 \ 'profile func Foo3', 242 \ 'profdel func Foo2', 243 \ 'profdel func Foo3', 244 \ 'call Foo1()', 245 \ 'call Foo2()', 246 \ 'call Foo3()' ] 247 call writefile(lines, 'Xprofile_file.vim') 248 call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') 249 call assert_equal(0, v:shell_error) 250 251 let lines = readfile('Xprofile_file.log') 252 call assert_equal(24, len(lines)) 253 254 " Check that: 255 " - Foo1() is called twice (profdel not invoked) 256 " - Foo2() is called once (profdel invoked after it was called) 257 " - Foo3() is not called (profdel invoked before it was called) 258 call assert_equal('FUNCTION Foo1()', lines[0]) 259 call assert_equal('Called 2 times', lines[1]) 260 call assert_equal('FUNCTION Foo2()', lines[7]) 261 call assert_equal('Called 1 time', lines[8]) 262 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[14]) 263 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[19]) 264 265 call delete('Xprofile_file.vim') 266 call delete('Xprofile_file.log') 267endfunc 268 269func Test_profdel_star() 270 " Foo() is invoked once before and once after 'profdel *'. 271 " So profiling should report it only once. 272 let lines = [ 273 \ 'profile start Xprofile_file.log', 274 \ 'func! Foo()', 275 \ 'endfunc', 276 \ 'profile func Foo', 277 \ 'call Foo()', 278 \ 'profdel *', 279 \ 'call Foo()' ] 280 call writefile(lines, 'Xprofile_file.vim') 281 call system(v:progpath . ' -es --clean -c "so Xprofile_file.vim" -c q') 282 call assert_equal(0, v:shell_error) 283 284 let lines = readfile('Xprofile_file.log') 285 call assert_equal(15, len(lines)) 286 287 call assert_equal('FUNCTION Foo()', lines[0]) 288 call assert_equal('Called 1 time', lines[1]) 289 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[7]) 290 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[11]) 291 292 call delete('Xprofile_file.vim') 293 call delete('Xprofile_file.log') 294endfunc 295