blob: d037c778e599a5361cb963bbb850baa95e169d42 [file] [log] [blame]
Bram Moolenaar296b1f22017-01-15 15:22:33 +01001" Test Vim profiler
Bram Moolenaarb0f94c12019-06-13 22:19:53 +02002
Bram Moolenaarb46fecd2019-06-15 17:58:09 +02003source check.vim
4CheckFeature profile
Bram Moolenaar296b1f22017-01-15 15:22:33 +01005
Bram Moolenaar93344c22019-08-14 21:12:05 +02006source shared.vim
Bram Moolenaar16358802019-08-30 18:37:26 +02007source screendump.vim
Bram Moolenaar93344c22019-08-14 21:12:05 +02008
Bram Moolenaar296b1f22017-01-15 15:22:33 +01009func Test_profile_func()
Bram Moolenaarb2049902021-01-24 12:53:53 +010010 call RunProfileFunc('func', 'let', 'let')
11 call RunProfileFunc('def', 'var', '')
12endfunc
13
14func RunProfileFunc(command, declare, assign)
Bram Moolenaarc79745a2019-05-20 22:12:34 +020015 let lines =<< trim [CODE]
16 profile start Xprofile_func.log
17 profile func Foo*
Bram Moolenaarb2049902021-01-24 12:53:53 +010018 XXX Foo1()
19 endXXX
20 XXX Foo2()
21 DDD counter = 100
22 while counter > 0
23 AAA counter = counter - 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +020024 endwhile
Bram Moolenaara21df1d2020-03-17 20:57:09 +010025 sleep 1m
Bram Moolenaarb2049902021-01-24 12:53:53 +010026 endXXX
27 XXX Foo3()
28 endXXX
29 XXX Bar()
30 endXXX
Bram Moolenaarc79745a2019-05-20 22:12:34 +020031 call Foo1()
32 call Foo1()
33 profile pause
34 call Foo1()
35 profile continue
36 call Foo2()
37 call Foo3()
38 call Bar()
39 if !v:profiling
40 delfunc Foo2
41 endif
42 delfunc Foo3
43 [CODE]
Bram Moolenaar296b1f22017-01-15 15:22:33 +010044
Bram Moolenaarb2049902021-01-24 12:53:53 +010045 call map(lines, {k, v -> substitute(v, 'XXX', a:command, '') })
46 call map(lines, {k, v -> substitute(v, 'DDD', a:declare, '') })
47 call map(lines, {k, v -> substitute(v, 'AAA', a:assign, '') })
48
Bram Moolenaar296b1f22017-01-15 15:22:33 +010049 call writefile(lines, 'Xprofile_func.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +020050 call system(GetVimCommand()
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +020051 \ . ' -es --clean'
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010052 \ . ' -c "so Xprofile_func.vim"'
53 \ . ' -c "qall!"')
54 call assert_equal(0, v:shell_error)
55
Bram Moolenaar296b1f22017-01-15 15:22:33 +010056 let lines = readfile('Xprofile_func.log')
57
Bram Moolenaar296b1f22017-01-15 15:22:33 +010058 " - Foo1() is called 3 times but should be reported as called twice
59 " since one call is in between "profile pause" .. "profile continue".
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010060 " - Foo2() should come before Foo1() since Foo1() does much more work.
Bram Moolenaar296b1f22017-01-15 15:22:33 +010061 " - Foo3() is not reported because function is deleted.
62 " - Unlike Foo3(), Foo2() should not be deleted since there is a check
63 " for v:profiling.
64 " - Bar() is not reported since it does not match "profile func Foo*".
Bram Moolenaara21df1d2020-03-17 20:57:09 +010065 call assert_equal(31, len(lines))
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010066
67 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar181d4f52019-09-18 22:04:56 +020068 call assert_match('Defined:.*Xprofile_func.vim:3', lines[1])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +020069 call assert_equal('Called 2 times', lines[2])
70 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3])
71 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4])
72 call assert_equal('', lines[5])
73 call assert_equal('count total (s) self (s)', lines[6])
74 call assert_equal('', lines[7])
75 call assert_equal('FUNCTION Foo2()', lines[8])
76 call assert_equal('Called 1 time', lines[10])
77 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[11])
78 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[12])
79 call assert_equal('', lines[13])
80 call assert_equal('count total (s) self (s)', lines[14])
Bram Moolenaarb2049902021-01-24 12:53:53 +010081 call assert_match('^\s*1\s\+.*\s\(let\|var\) counter = 100$', lines[15])
82 call assert_match('^\s*101\s\+.*\swhile counter > 0$', lines[16])
83 call assert_match('^\s*100\s\+.*\s \(let\)\= counter = counter - 1$', lines[17])
84 call assert_match('^\s*10[01]\s\+.*\sendwhile$', lines[18])
Bram Moolenaara21df1d2020-03-17 20:57:09 +010085 call assert_match('^\s*1\s\+.\+sleep 1m$', lines[19])
86 call assert_equal('', lines[20])
87 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[21])
88 call assert_equal('count total (s) self (s) function', lines[22])
89 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[23])
90 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[24])
91 call assert_equal('', lines[25])
92 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[26])
93 call assert_equal('count total (s) self (s) function', lines[27])
94 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[28])
95 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[29])
96 call assert_equal('', lines[30])
Bram Moolenaar296b1f22017-01-15 15:22:33 +010097
98 call delete('Xprofile_func.vim')
99 call delete('Xprofile_func.log')
100endfunc
101
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200102func Test_profile_func_with_ifelse()
Bram Moolenaarced68a02021-01-24 17:53:47 +0100103 call Run_profile_func_with_ifelse('func', 'let', 'let')
104 call Run_profile_func_with_ifelse('def', 'var', '')
105endfunc
106
107func Run_profile_func_with_ifelse(command, declare, assign)
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200108 let lines =<< trim [CODE]
Bram Moolenaarced68a02021-01-24 17:53:47 +0100109 XXX Foo1()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200110 if 1
Bram Moolenaarced68a02021-01-24 17:53:47 +0100111 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200112 elseif 1
Bram Moolenaarced68a02021-01-24 17:53:47 +0100113 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200114 else
Bram Moolenaarced68a02021-01-24 17:53:47 +0100115 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200116 endif
Bram Moolenaarced68a02021-01-24 17:53:47 +0100117 endXXX
118 XXX Foo2()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200119 if 0
Bram Moolenaarced68a02021-01-24 17:53:47 +0100120 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200121 elseif 1
Bram Moolenaarced68a02021-01-24 17:53:47 +0100122 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200123 else
Bram Moolenaarced68a02021-01-24 17:53:47 +0100124 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200125 endif
Bram Moolenaarced68a02021-01-24 17:53:47 +0100126 endXXX
127 XXX Foo3()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200128 if 0
Bram Moolenaarced68a02021-01-24 17:53:47 +0100129 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200130 elseif 0
Bram Moolenaarced68a02021-01-24 17:53:47 +0100131 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200132 else
Bram Moolenaarced68a02021-01-24 17:53:47 +0100133 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200134 endif
Bram Moolenaarced68a02021-01-24 17:53:47 +0100135 endXXX
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200136 call Foo1()
137 call Foo2()
138 call Foo3()
139 [CODE]
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200140
Bram Moolenaarced68a02021-01-24 17:53:47 +0100141 call map(lines, {k, v -> substitute(v, 'XXX', a:command, '') })
142 call map(lines, {k, v -> substitute(v, 'DDD', a:declare, '') })
143 call map(lines, {k, v -> substitute(v, 'AAA', a:assign, '') })
144
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200145 call writefile(lines, 'Xprofile_func.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200146 call system(GetVimCommand()
147 \ . ' -es -i NONE --noplugin'
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200148 \ . ' -c "profile start Xprofile_func.log"'
149 \ . ' -c "profile func Foo*"'
150 \ . ' -c "so Xprofile_func.vim"'
151 \ . ' -c "qall!"')
152 call assert_equal(0, v:shell_error)
153
154 let lines = readfile('Xprofile_func.log')
155
156 " - Foo1() should pass 'if' block.
157 " - Foo2() should pass 'elseif' block.
158 " - Foo3() should pass 'else' block.
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200159 call assert_equal(57, len(lines))
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200160
161 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200162 call assert_match('Defined:.*Xprofile_func.vim', lines[1])
163 call assert_equal('Called 1 time', lines[2])
164 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3])
165 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4])
166 call assert_equal('', lines[5])
167 call assert_equal('count total (s) self (s)', lines[6])
168 call assert_match('^\s*1\s\+.*\sif 1$', lines[7])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100169 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 0$', lines[8])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200170 call assert_match( '^\s\+elseif 1$', lines[9])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100171 call assert_match( '^\s\+\(let\|var\) x = 1$', lines[10])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200172 call assert_match( '^\s\+else$', lines[11])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100173 call assert_match( '^\s\+\(let\|var\) x = 2$', lines[12])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200174 call assert_match('^\s*1\s\+.*\sendif$', lines[13])
175 call assert_equal('', lines[14])
176 call assert_equal('FUNCTION Foo2()', lines[15])
177 call assert_equal('Called 1 time', lines[17])
178 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18])
179 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19])
180 call assert_equal('', lines[20])
181 call assert_equal('count total (s) self (s)', lines[21])
182 call assert_match('^\s*1\s\+.*\sif 0$', lines[22])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100183 call assert_match( '^\s\+\(let\|var\) x = 0$', lines[23])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200184 call assert_match('^\s*1\s\+.*\selseif 1$', lines[24])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100185 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 1$', lines[25])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200186 call assert_match( '^\s\+else$', lines[26])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100187 call assert_match( '^\s\+\(let\|var\) x = 2$', lines[27])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200188 call assert_match('^\s*1\s\+.*\sendif$', lines[28])
189 call assert_equal('', lines[29])
190 call assert_equal('FUNCTION Foo3()', lines[30])
191 call assert_equal('Called 1 time', lines[32])
192 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33])
193 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34])
194 call assert_equal('', lines[35])
195 call assert_equal('count total (s) self (s)', lines[36])
196 call assert_match('^\s*1\s\+.*\sif 0$', lines[37])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100197 call assert_match( '^\s\+\(let\|var\) x = 0$', lines[38])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200198 call assert_match('^\s*1\s\+.*\selseif 0$', lines[39])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100199 call assert_match( '^\s\+\(let\|var\) x = 1$', lines[40])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200200 call assert_match('^\s*1\s\+.*\selse$', lines[41])
Bram Moolenaarced68a02021-01-24 17:53:47 +0100201 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 2$', lines[42])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200202 call assert_match('^\s*1\s\+.*\sendif$', lines[43])
203 call assert_equal('', lines[44])
204 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45])
205 call assert_equal('count total (s) self (s) function', lines[46])
206 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47])
207 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48])
208 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49])
209 call assert_equal('', lines[50])
210 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51])
211 call assert_equal('count total (s) self (s) function', lines[52])
212 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53])
213 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54])
214 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55])
215 call assert_equal('', lines[56])
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200216
217 call delete('Xprofile_func.vim')
218 call delete('Xprofile_func.log')
219endfunc
220
221func Test_profile_func_with_trycatch()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200222 let lines =<< trim [CODE]
223 func! Foo1()
224 try
225 let x = 0
226 catch
227 let x = 1
228 finally
229 let x = 2
230 endtry
231 endfunc
232 func! Foo2()
233 try
234 throw 0
235 catch
236 let x = 1
237 finally
238 let x = 2
239 endtry
240 endfunc
241 func! Foo3()
242 try
243 throw 0
244 catch
245 throw 1
246 finally
247 let x = 2
248 endtry
249 endfunc
250 call Foo1()
251 call Foo2()
252 try
253 call Foo3()
254 catch
255 endtry
256 [CODE]
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200257
258 call writefile(lines, 'Xprofile_func.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200259 call system(GetVimCommand()
260 \ . ' -es -i NONE --noplugin'
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200261 \ . ' -c "profile start Xprofile_func.log"'
262 \ . ' -c "profile func Foo*"'
263 \ . ' -c "so Xprofile_func.vim"'
264 \ . ' -c "qall!"')
265 call assert_equal(0, v:shell_error)
266
267 let lines = readfile('Xprofile_func.log')
268
269 " - Foo1() should pass 'try' 'finally' blocks.
270 " - Foo2() should pass 'catch' 'finally' blocks.
271 " - Foo3() should not pass 'endtry'.
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200272 call assert_equal(57, len(lines))
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200273
274 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200275 call assert_match('Defined:.*Xprofile_func.vim', lines[1])
276 call assert_equal('Called 1 time', lines[2])
277 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3])
278 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4])
279 call assert_equal('', lines[5])
280 call assert_equal('count total (s) self (s)', lines[6])
281 call assert_match('^\s*1\s\+.*\stry$', lines[7])
282 call assert_match('^\s*1\s\+.*\s let x = 0$', lines[8])
283 call assert_match( '^\s\+catch$', lines[9])
284 call assert_match( '^\s\+let x = 1$', lines[10])
285 call assert_match('^\s*1\s\+.*\sfinally$', lines[11])
286 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[12])
287 call assert_match('^\s*1\s\+.*\sendtry$', lines[13])
288 call assert_equal('', lines[14])
289 call assert_equal('FUNCTION Foo2()', lines[15])
290 call assert_equal('Called 1 time', lines[17])
291 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18])
292 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19])
293 call assert_equal('', lines[20])
294 call assert_equal('count total (s) self (s)', lines[21])
295 call assert_match('^\s*1\s\+.*\stry$', lines[22])
296 call assert_match('^\s*1\s\+.*\s throw 0$', lines[23])
297 call assert_match('^\s*1\s\+.*\scatch$', lines[24])
298 call assert_match('^\s*1\s\+.*\s let x = 1$', lines[25])
299 call assert_match('^\s*1\s\+.*\sfinally$', lines[26])
300 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[27])
301 call assert_match('^\s*1\s\+.*\sendtry$', lines[28])
302 call assert_equal('', lines[29])
303 call assert_equal('FUNCTION Foo3()', lines[30])
304 call assert_equal('Called 1 time', lines[32])
305 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33])
306 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34])
307 call assert_equal('', lines[35])
308 call assert_equal('count total (s) self (s)', lines[36])
309 call assert_match('^\s*1\s\+.*\stry$', lines[37])
310 call assert_match('^\s*1\s\+.*\s throw 0$', lines[38])
311 call assert_match('^\s*1\s\+.*\scatch$', lines[39])
312 call assert_match('^\s*1\s\+.*\s throw 1$', lines[40])
313 call assert_match('^\s*1\s\+.*\sfinally$', lines[41])
314 call assert_match('^\s*1\s\+.*\s let x = 2$', lines[42])
315 call assert_match( '^\s\+endtry$', lines[43])
316 call assert_equal('', lines[44])
317 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45])
318 call assert_equal('count total (s) self (s) function', lines[46])
319 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47])
320 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48])
321 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49])
322 call assert_equal('', lines[50])
323 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51])
324 call assert_equal('count total (s) self (s) function', lines[52])
325 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53])
326 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54])
327 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55])
328 call assert_equal('', lines[56])
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200329
330 call delete('Xprofile_func.vim')
331 call delete('Xprofile_func.log')
332endfunc
333
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100334func Test_profile_file()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200335 let lines =<< trim [CODE]
Bram Moolenaare7eb9272019-06-24 00:58:07 +0200336 func! Foo()
337 endfunc
338 for i in range(10)
339 " a comment
340 call Foo()
341 endfor
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200342 call Foo()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200343 [CODE]
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100344
345 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200346 call system(GetVimCommandClean()
347 \ . ' -es'
Bram Moolenaarc011a3d2017-01-16 22:37:42 +0100348 \ . ' -c "profile start Xprofile_file.log"'
349 \ . ' -c "profile file Xprofile_file.vim"'
350 \ . ' -c "so Xprofile_file.vim"'
351 \ . ' -c "so Xprofile_file.vim"'
352 \ . ' -c "qall!"')
353 call assert_equal(0, v:shell_error)
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100354
355 let lines = readfile('Xprofile_file.log')
356
357 call assert_equal(14, len(lines))
358
359 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0])
360 call assert_equal('Sourced 2 times', lines[1])
361 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2])
362 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3])
363 call assert_equal('', lines[4])
364 call assert_equal('count total (s) self (s)', lines[5])
Bram Moolenaar67435d92017-10-19 21:04:37 +0200365 call assert_match(' 2 0.\d\+ func! Foo()', lines[6])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100366 call assert_equal(' endfunc', lines[7])
367 " Loop iterates 10 times. Since script runs twice, body executes 20 times.
368 " First line of loop executes one more time than body to detect end of loop.
369 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+for i in range(10)$', lines[8])
370 call assert_equal(' " a comment', lines[9])
Bram Moolenaard21b16f2017-08-14 23:13:30 +0200371 " if self and total are equal we only get one number
372 call assert_match('^\s*20\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[10])
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200373 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+endfor$', lines[11])
Bram Moolenaare32bbde2017-01-15 21:12:48 +0100374 " if self and total are equal we only get one number
375 call assert_match('^\s*2\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[12])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100376 call assert_equal('', lines[13])
377
378 call delete('Xprofile_file.vim')
379 call delete('Xprofile_file.log')
380endfunc
381
Bram Moolenaar67435d92017-10-19 21:04:37 +0200382func Test_profile_file_with_cont()
383 let lines = [
384 \ 'echo "hello',
385 \ ' \ world"',
386 \ 'echo "foo ',
387 \ ' \bar"',
388 \ ]
389
390 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200391 call system(GetVimCommandClean()
392 \ . ' -es'
Bram Moolenaar67435d92017-10-19 21:04:37 +0200393 \ . ' -c "profile start Xprofile_file.log"'
394 \ . ' -c "profile file Xprofile_file.vim"'
395 \ . ' -c "so Xprofile_file.vim"'
396 \ . ' -c "qall!"')
397 call assert_equal(0, v:shell_error)
398
399 let lines = readfile('Xprofile_file.log')
400 call assert_equal(11, len(lines))
401
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200402 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0])
403 call assert_equal('Sourced 1 time', lines[1])
404 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2])
405 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3])
406 call assert_equal('', lines[4])
407 call assert_equal('count total (s) self (s)', lines[5])
408 call assert_match(' 1 0.\d\+ echo "hello', lines[6])
409 call assert_equal(' \ world"', lines[7])
410 call assert_match(' 1 0.\d\+ echo "foo ', lines[8])
411 call assert_equal(' \bar"', lines[9])
412 call assert_equal('', lines[10])
Bram Moolenaar67435d92017-10-19 21:04:37 +0200413
414 call delete('Xprofile_file.vim')
415 call delete('Xprofile_file.log')
416endfunc
417
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100418func Test_profile_completion()
419 call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx')
420 call assert_equal('"profile continue file func pause start', @:)
421
422 call feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx')
423 call assert_match('^"profile start.* test_profile\.vim', @:)
424endfunc
425
426func Test_profile_errors()
427 call assert_fails("profile func Foo", 'E750:')
428 call assert_fails("profile pause", 'E750:')
429 call assert_fails("profile continue", 'E750:')
430endfunc
Bram Moolenaarac112f02017-12-05 16:46:28 +0100431
432func Test_profile_truncate_mbyte()
Bram Moolenaar30276f22019-01-24 17:59:39 +0100433 if &enc !=# 'utf-8'
Bram Moolenaarac112f02017-12-05 16:46:28 +0100434 return
435 endif
436
437 let lines = [
438 \ 'scriptencoding utf-8',
439 \ 'func! Foo()',
440 \ ' return [',
441 \ ' \ "' . join(map(range(0x4E00, 0x4E00 + 340), 'nr2char(v:val)'), '') . '",',
442 \ ' \ "' . join(map(range(0x4F00, 0x4F00 + 340), 'nr2char(v:val)'), '') . '",',
443 \ ' \ ]',
444 \ 'endfunc',
445 \ 'call Foo()',
446 \ ]
447
448 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200449 call system(GetVimCommandClean()
450 \ . ' -es --cmd "set enc=utf-8"'
Bram Moolenaarac112f02017-12-05 16:46:28 +0100451 \ . ' -c "profile start Xprofile_file.log"'
452 \ . ' -c "profile file Xprofile_file.vim"'
453 \ . ' -c "so Xprofile_file.vim"'
454 \ . ' -c "qall!"')
455 call assert_equal(0, v:shell_error)
456
457 split Xprofile_file.log
458 if &fenc != ''
459 call assert_equal('utf-8', &fenc)
460 endif
461 /func! Foo()
462 let lnum = line('.')
463 call assert_match('^\s*return \[$', getline(lnum + 1))
464 call assert_match("\u4F52$", getline(lnum + 2))
465 call assert_match("\u5052$", getline(lnum + 3))
466 call assert_match('^\s*\\ \]$', getline(lnum + 4))
467 bwipe!
468
469 call delete('Xprofile_file.vim')
470 call delete('Xprofile_file.log')
471endfunc
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200472
473func Test_profdel_func()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200474 let lines =<< trim [CODE]
475 profile start Xprofile_file.log
476 func! Foo1()
477 endfunc
478 func! Foo2()
479 endfunc
480 func! Foo3()
481 endfunc
482
483 profile func Foo1
484 profile func Foo2
485 call Foo1()
486 call Foo2()
487
488 profile func Foo3
489 profdel func Foo2
490 profdel func Foo3
491 call Foo1()
492 call Foo2()
493 call Foo3()
494 [CODE]
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200495 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200496 call system(GetVimCommandClean() . ' -es -c "so Xprofile_file.vim" -c q')
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200497 call assert_equal(0, v:shell_error)
498
499 let lines = readfile('Xprofile_file.log')
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200500 call assert_equal(26, len(lines))
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200501
502 " Check that:
503 " - Foo1() is called twice (profdel not invoked)
504 " - Foo2() is called once (profdel invoked after it was called)
505 " - Foo3() is not called (profdel invoked before it was called)
506 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200507 call assert_match('Defined:.*Xprofile_file.vim', lines[1])
508 call assert_equal('Called 2 times', lines[2])
509 call assert_equal('FUNCTION Foo2()', lines[8])
510 call assert_equal('Called 1 time', lines[10])
511 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[16])
512 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[21])
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200513
514 call delete('Xprofile_file.vim')
515 call delete('Xprofile_file.log')
516endfunc
517
518func Test_profdel_star()
519 " Foo() is invoked once before and once after 'profdel *'.
520 " So profiling should report it only once.
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200521 let lines =<< trim [CODE]
522 profile start Xprofile_file.log
523 func! Foo()
524 endfunc
525 profile func Foo
526 call Foo()
527 profdel *
528 call Foo()
529 [CODE]
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200530 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200531 call system(GetVimCommandClean() . ' -es -c "so Xprofile_file.vim" -c q')
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200532 call assert_equal(0, v:shell_error)
533
534 let lines = readfile('Xprofile_file.log')
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200535 call assert_equal(16, len(lines))
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200536
537 call assert_equal('FUNCTION Foo()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200538 call assert_match('Defined:.*Xprofile_file.vim', lines[1])
539 call assert_equal('Called 1 time', lines[2])
540 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[8])
541 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[12])
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200542
543 call delete('Xprofile_file.vim')
544 call delete('Xprofile_file.log')
545endfunc
Bram Moolenaar16358802019-08-30 18:37:26 +0200546
547" When typing the function it won't have a script ID, test that this works.
548func Test_profile_typed_func()
549 CheckScreendump
550
551 let lines =<< trim END
552 profile start XprofileTypedFunc
553 END
554 call writefile(lines, 'XtestProfile')
555 let buf = RunVimInTerminal('-S XtestProfile', #{})
556
557 call term_sendkeys(buf, ":func DoSomething()\<CR>"
558 \ .. "echo 'hello'\<CR>"
559 \ .. "endfunc\<CR>")
560 call term_sendkeys(buf, ":profile func DoSomething\<CR>")
561 call term_sendkeys(buf, ":call DoSomething()\<CR>")
Bram Moolenaar6a2c5a72020-04-08 21:50:25 +0200562 call TermWait(buf, 100)
Bram Moolenaar16358802019-08-30 18:37:26 +0200563 call StopVimInTerminal(buf)
564 let lines = readfile('XprofileTypedFunc')
565 call assert_equal("FUNCTION DoSomething()", lines[0])
566 call assert_equal("Called 1 time", lines[1])
567
568 " clean up
569 call delete('XprofileTypedFunc')
570 call delete('XtestProfile')
571endfunc
Bram Moolenaar6d91bcb2020-08-12 18:50:36 +0200572
573" vim: shiftwidth=2 sts=2 expandtab