blob: c8c877d5c1e4454bd8344da89cfa4b042f8a00cf [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 Moolenaare5ea3462021-01-25 21:01:48 +01008source vim9.vim
Bram Moolenaar93344c22019-08-14 21:12:05 +02009
Bram Moolenaar296b1f22017-01-15 15:22:33 +010010func Test_profile_func()
Bram Moolenaarb2049902021-01-24 12:53:53 +010011 call RunProfileFunc('func', 'let', 'let')
12 call RunProfileFunc('def', 'var', '')
13endfunc
14
15func RunProfileFunc(command, declare, assign)
Bram Moolenaarc79745a2019-05-20 22:12:34 +020016 let lines =<< trim [CODE]
17 profile start Xprofile_func.log
18 profile func Foo*
Bram Moolenaarb2049902021-01-24 12:53:53 +010019 XXX Foo1()
20 endXXX
21 XXX Foo2()
22 DDD counter = 100
23 while counter > 0
24 AAA counter = counter - 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +020025 endwhile
Bram Moolenaara21df1d2020-03-17 20:57:09 +010026 sleep 1m
Bram Moolenaarb2049902021-01-24 12:53:53 +010027 endXXX
28 XXX Foo3()
29 endXXX
30 XXX Bar()
31 endXXX
Bram Moolenaarc79745a2019-05-20 22:12:34 +020032 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]
Bram Moolenaar296b1f22017-01-15 15:22:33 +010045
Bram Moolenaarb2049902021-01-24 12:53:53 +010046 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
Bram Moolenaar296b1f22017-01-15 15:22:33 +010050 call writefile(lines, 'Xprofile_func.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +020051 call system(GetVimCommand()
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +020052 \ . ' -es --clean'
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010053 \ . ' -c "so Xprofile_func.vim"'
54 \ . ' -c "qall!"')
55 call assert_equal(0, v:shell_error)
56
Bram Moolenaar296b1f22017-01-15 15:22:33 +010057 let lines = readfile('Xprofile_func.log')
58
Bram Moolenaar296b1f22017-01-15 15:22:33 +010059 " - Foo1() is called 3 times but should be reported as called twice
60 " since one call is in between "profile pause" .. "profile continue".
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010061 " - Foo2() should come before Foo1() since Foo1() does much more work.
Bram Moolenaar296b1f22017-01-15 15:22:33 +010062 " - Foo3() is not reported because function is deleted.
63 " - Unlike Foo3(), Foo2() should not be deleted since there is a check
64 " for v:profiling.
65 " - Bar() is not reported since it does not match "profile func Foo*".
Bram Moolenaara21df1d2020-03-17 20:57:09 +010066 call assert_equal(31, len(lines))
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010067
68 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar181d4f52019-09-18 22:04:56 +020069 call assert_match('Defined:.*Xprofile_func.vim:3', lines[1])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +020070 call assert_equal('Called 2 times', lines[2])
71 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3])
72 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4])
73 call assert_equal('', lines[5])
74 call assert_equal('count total (s) self (s)', lines[6])
75 call assert_equal('', lines[7])
76 call assert_equal('FUNCTION Foo2()', lines[8])
77 call assert_equal('Called 1 time', lines[10])
78 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[11])
79 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[12])
80 call assert_equal('', lines[13])
81 call assert_equal('count total (s) self (s)', lines[14])
Bram Moolenaarb2049902021-01-24 12:53:53 +010082 call assert_match('^\s*1\s\+.*\s\(let\|var\) counter = 100$', lines[15])
83 call assert_match('^\s*101\s\+.*\swhile counter > 0$', lines[16])
84 call assert_match('^\s*100\s\+.*\s \(let\)\= counter = counter - 1$', lines[17])
85 call assert_match('^\s*10[01]\s\+.*\sendwhile$', lines[18])
Bram Moolenaara21df1d2020-03-17 20:57:09 +010086 call assert_match('^\s*1\s\+.\+sleep 1m$', lines[19])
87 call assert_equal('', lines[20])
88 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[21])
89 call assert_equal('count total (s) self (s) function', lines[22])
90 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[23])
91 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[24])
92 call assert_equal('', lines[25])
93 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[26])
94 call assert_equal('count total (s) self (s) function', lines[27])
95 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo2()$', lines[28])
96 call assert_match('^\s*2\s\+\d\+\.\d\+\s\+Foo1()$', lines[29])
97 call assert_equal('', lines[30])
Bram Moolenaar296b1f22017-01-15 15:22:33 +010098
99 call delete('Xprofile_func.vim')
100 call delete('Xprofile_func.log')
101endfunc
102
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200103func Test_profile_func_with_ifelse()
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100104 call Run_profile_func_with_ifelse('func', 'let')
105 call Run_profile_func_with_ifelse('def', 'var')
Bram Moolenaarced68a02021-01-24 17:53:47 +0100106endfunc
107
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100108func Run_profile_func_with_ifelse(command, declare)
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200109 let lines =<< trim [CODE]
Bram Moolenaarced68a02021-01-24 17:53:47 +0100110 XXX Foo1()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200111 if 1
Bram Moolenaarced68a02021-01-24 17:53:47 +0100112 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200113 elseif 1
Bram Moolenaarced68a02021-01-24 17:53:47 +0100114 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200115 else
Bram Moolenaarced68a02021-01-24 17:53:47 +0100116 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200117 endif
Bram Moolenaarced68a02021-01-24 17:53:47 +0100118 endXXX
119 XXX Foo2()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200120 if 0
Bram Moolenaarced68a02021-01-24 17:53:47 +0100121 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200122 elseif 1
Bram Moolenaarced68a02021-01-24 17:53:47 +0100123 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200124 else
Bram Moolenaarced68a02021-01-24 17:53:47 +0100125 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200126 endif
Bram Moolenaarced68a02021-01-24 17:53:47 +0100127 endXXX
128 XXX Foo3()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200129 if 0
Bram Moolenaarced68a02021-01-24 17:53:47 +0100130 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200131 elseif 0
Bram Moolenaarced68a02021-01-24 17:53:47 +0100132 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200133 else
Bram Moolenaarced68a02021-01-24 17:53:47 +0100134 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200135 endif
Bram Moolenaarced68a02021-01-24 17:53:47 +0100136 endXXX
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200137 call Foo1()
138 call Foo2()
139 call Foo3()
140 [CODE]
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200141
Bram Moolenaarced68a02021-01-24 17:53:47 +0100142 call map(lines, {k, v -> substitute(v, 'XXX', a:command, '') })
143 call map(lines, {k, v -> substitute(v, 'DDD', a:declare, '') })
Bram Moolenaarced68a02021-01-24 17:53:47 +0100144
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 Moolenaar107e9ce2021-01-24 20:52:00 +0100222 call Run_profile_func_with_trycatch('func', 'let')
223 call Run_profile_func_with_trycatch('def', 'var')
224endfunc
225
226func Run_profile_func_with_trycatch(command, declare)
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200227 let lines =<< trim [CODE]
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100228 XXX Foo1()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200229 try
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100230 DDD x = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200231 catch
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100232 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200233 finally
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100234 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200235 endtry
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100236 endXXX
237 XXX Foo2()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200238 try
239 throw 0
240 catch
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100241 DDD x = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200242 finally
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100243 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200244 endtry
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100245 endXXX
246 XXX Foo3()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200247 try
248 throw 0
249 catch
250 throw 1
251 finally
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100252 DDD x = 2
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200253 endtry
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100254 endXXX
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200255 call Foo1()
256 call Foo2()
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100257 let rethrown = 0
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200258 try
259 call Foo3()
260 catch
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100261 let rethrown = 1
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200262 endtry
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100263 if rethrown != 1
264 " call Foo1 again so that the test fails
265 call Foo1()
266 endif
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200267 [CODE]
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200268
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100269 call map(lines, {k, v -> substitute(v, 'XXX', a:command, '') })
270 call map(lines, {k, v -> substitute(v, 'DDD', a:declare, '') })
271
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200272 call writefile(lines, 'Xprofile_func.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200273 call system(GetVimCommand()
274 \ . ' -es -i NONE --noplugin'
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200275 \ . ' -c "profile start Xprofile_func.log"'
276 \ . ' -c "profile func Foo*"'
277 \ . ' -c "so Xprofile_func.vim"'
278 \ . ' -c "qall!"')
279 call assert_equal(0, v:shell_error)
280
281 let lines = readfile('Xprofile_func.log')
282
283 " - Foo1() should pass 'try' 'finally' blocks.
284 " - Foo2() should pass 'catch' 'finally' blocks.
285 " - Foo3() should not pass 'endtry'.
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200286 call assert_equal(57, len(lines))
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200287
288 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200289 call assert_match('Defined:.*Xprofile_func.vim', lines[1])
290 call assert_equal('Called 1 time', lines[2])
291 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[3])
292 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[4])
293 call assert_equal('', lines[5])
294 call assert_equal('count total (s) self (s)', lines[6])
295 call assert_match('^\s*1\s\+.*\stry$', lines[7])
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100296 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 0$', lines[8])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200297 call assert_match( '^\s\+catch$', lines[9])
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100298 call assert_match( '^\s\+\(let\|var\) x = 1$', lines[10])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200299 call assert_match('^\s*1\s\+.*\sfinally$', lines[11])
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100300 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 2$', lines[12])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200301 call assert_match('^\s*1\s\+.*\sendtry$', lines[13])
302 call assert_equal('', lines[14])
303 call assert_equal('FUNCTION Foo2()', lines[15])
304 call assert_equal('Called 1 time', lines[17])
305 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[18])
306 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[19])
307 call assert_equal('', lines[20])
308 call assert_equal('count total (s) self (s)', lines[21])
309 call assert_match('^\s*1\s\+.*\stry$', lines[22])
310 call assert_match('^\s*1\s\+.*\s throw 0$', lines[23])
311 call assert_match('^\s*1\s\+.*\scatch$', lines[24])
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100312 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 1$', lines[25])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200313 call assert_match('^\s*1\s\+.*\sfinally$', lines[26])
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100314 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 2$', lines[27])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200315 call assert_match('^\s*1\s\+.*\sendtry$', lines[28])
316 call assert_equal('', lines[29])
317 call assert_equal('FUNCTION Foo3()', lines[30])
318 call assert_equal('Called 1 time', lines[32])
319 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[33])
320 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[34])
321 call assert_equal('', lines[35])
322 call assert_equal('count total (s) self (s)', lines[36])
323 call assert_match('^\s*1\s\+.*\stry$', lines[37])
324 call assert_match('^\s*1\s\+.*\s throw 0$', lines[38])
325 call assert_match('^\s*1\s\+.*\scatch$', lines[39])
326 call assert_match('^\s*1\s\+.*\s throw 1$', lines[40])
327 call assert_match('^\s*1\s\+.*\sfinally$', lines[41])
Bram Moolenaar107e9ce2021-01-24 20:52:00 +0100328 call assert_match('^\s*1\s\+.*\s \(let\|var\) x = 2$', lines[42])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200329 call assert_match( '^\s\+endtry$', lines[43])
330 call assert_equal('', lines[44])
331 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[45])
332 call assert_equal('count total (s) self (s) function', lines[46])
333 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[47])
334 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[48])
335 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[49])
336 call assert_equal('', lines[50])
337 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[51])
338 call assert_equal('count total (s) self (s) function', lines[52])
339 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[53])
340 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[54])
341 call assert_match('^\s*1\s\+\d\+\.\d\+\s\+Foo.()$', lines[55])
342 call assert_equal('', lines[56])
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200343
344 call delete('Xprofile_func.vim')
345 call delete('Xprofile_func.log')
346endfunc
347
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100348func Test_profile_file()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200349 let lines =<< trim [CODE]
Bram Moolenaare7eb9272019-06-24 00:58:07 +0200350 func! Foo()
351 endfunc
352 for i in range(10)
353 " a comment
354 call Foo()
355 endfor
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200356 call Foo()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200357 [CODE]
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100358
359 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200360 call system(GetVimCommandClean()
361 \ . ' -es'
Bram Moolenaarc011a3d2017-01-16 22:37:42 +0100362 \ . ' -c "profile start Xprofile_file.log"'
363 \ . ' -c "profile file Xprofile_file.vim"'
364 \ . ' -c "so Xprofile_file.vim"'
365 \ . ' -c "so Xprofile_file.vim"'
366 \ . ' -c "qall!"')
367 call assert_equal(0, v:shell_error)
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100368
369 let lines = readfile('Xprofile_file.log')
370
371 call assert_equal(14, len(lines))
372
373 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0])
374 call assert_equal('Sourced 2 times', lines[1])
375 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2])
376 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3])
377 call assert_equal('', lines[4])
378 call assert_equal('count total (s) self (s)', lines[5])
Bram Moolenaar67435d92017-10-19 21:04:37 +0200379 call assert_match(' 2 0.\d\+ func! Foo()', lines[6])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100380 call assert_equal(' endfunc', lines[7])
381 " Loop iterates 10 times. Since script runs twice, body executes 20 times.
382 " First line of loop executes one more time than body to detect end of loop.
383 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+for i in range(10)$', lines[8])
384 call assert_equal(' " a comment', lines[9])
Bram Moolenaard21b16f2017-08-14 23:13:30 +0200385 " if self and total are equal we only get one number
386 call assert_match('^\s*20\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[10])
Bram Moolenaar7feb35e2018-08-21 17:49:54 +0200387 call assert_match('^\s*22\s\+\d\+\.\d\+\s\+endfor$', lines[11])
Bram Moolenaare32bbde2017-01-15 21:12:48 +0100388 " if self and total are equal we only get one number
389 call assert_match('^\s*2\s\+\(\d\+\.\d\+\s\+\)\=\d\+\.\d\+\s\+call Foo()$', lines[12])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100390 call assert_equal('', lines[13])
391
392 call delete('Xprofile_file.vim')
393 call delete('Xprofile_file.log')
394endfunc
395
Bram Moolenaar67435d92017-10-19 21:04:37 +0200396func Test_profile_file_with_cont()
397 let lines = [
398 \ 'echo "hello',
399 \ ' \ world"',
400 \ 'echo "foo ',
401 \ ' \bar"',
402 \ ]
403
404 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200405 call system(GetVimCommandClean()
406 \ . ' -es'
Bram Moolenaar67435d92017-10-19 21:04:37 +0200407 \ . ' -c "profile start Xprofile_file.log"'
408 \ . ' -c "profile file Xprofile_file.vim"'
409 \ . ' -c "so Xprofile_file.vim"'
410 \ . ' -c "qall!"')
411 call assert_equal(0, v:shell_error)
412
413 let lines = readfile('Xprofile_file.log')
414 call assert_equal(11, len(lines))
415
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200416 call assert_match('^SCRIPT .*Xprofile_file.vim$', lines[0])
417 call assert_equal('Sourced 1 time', lines[1])
418 call assert_match('^Total time:\s\+\d\+\.\d\+$', lines[2])
419 call assert_match('^ Self time:\s\+\d\+\.\d\+$', lines[3])
420 call assert_equal('', lines[4])
421 call assert_equal('count total (s) self (s)', lines[5])
422 call assert_match(' 1 0.\d\+ echo "hello', lines[6])
423 call assert_equal(' \ world"', lines[7])
424 call assert_match(' 1 0.\d\+ echo "foo ', lines[8])
425 call assert_equal(' \bar"', lines[9])
426 call assert_equal('', lines[10])
Bram Moolenaar67435d92017-10-19 21:04:37 +0200427
428 call delete('Xprofile_file.vim')
429 call delete('Xprofile_file.log')
430endfunc
431
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100432func Test_profile_completion()
433 call feedkeys(":profile \<C-A>\<C-B>\"\<CR>", 'tx')
434 call assert_equal('"profile continue file func pause start', @:)
435
436 call feedkeys(":profile start test_prof\<C-A>\<C-B>\"\<CR>", 'tx')
437 call assert_match('^"profile start.* test_profile\.vim', @:)
438endfunc
439
440func Test_profile_errors()
441 call assert_fails("profile func Foo", 'E750:')
442 call assert_fails("profile pause", 'E750:')
443 call assert_fails("profile continue", 'E750:')
444endfunc
Bram Moolenaarac112f02017-12-05 16:46:28 +0100445
446func Test_profile_truncate_mbyte()
Bram Moolenaar30276f22019-01-24 17:59:39 +0100447 if &enc !=# 'utf-8'
Bram Moolenaarac112f02017-12-05 16:46:28 +0100448 return
449 endif
450
451 let lines = [
452 \ 'scriptencoding utf-8',
453 \ 'func! Foo()',
454 \ ' return [',
455 \ ' \ "' . join(map(range(0x4E00, 0x4E00 + 340), 'nr2char(v:val)'), '') . '",',
456 \ ' \ "' . join(map(range(0x4F00, 0x4F00 + 340), 'nr2char(v:val)'), '') . '",',
457 \ ' \ ]',
458 \ 'endfunc',
459 \ 'call Foo()',
460 \ ]
461
462 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200463 call system(GetVimCommandClean()
464 \ . ' -es --cmd "set enc=utf-8"'
Bram Moolenaarac112f02017-12-05 16:46:28 +0100465 \ . ' -c "profile start Xprofile_file.log"'
466 \ . ' -c "profile file Xprofile_file.vim"'
467 \ . ' -c "so Xprofile_file.vim"'
468 \ . ' -c "qall!"')
469 call assert_equal(0, v:shell_error)
470
471 split Xprofile_file.log
472 if &fenc != ''
473 call assert_equal('utf-8', &fenc)
474 endif
475 /func! Foo()
476 let lnum = line('.')
477 call assert_match('^\s*return \[$', getline(lnum + 1))
478 call assert_match("\u4F52$", getline(lnum + 2))
479 call assert_match("\u5052$", getline(lnum + 3))
480 call assert_match('^\s*\\ \]$', getline(lnum + 4))
481 bwipe!
482
483 call delete('Xprofile_file.vim')
484 call delete('Xprofile_file.log')
485endfunc
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200486
487func Test_profdel_func()
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200488 let lines =<< trim [CODE]
489 profile start Xprofile_file.log
490 func! Foo1()
491 endfunc
492 func! Foo2()
493 endfunc
494 func! Foo3()
495 endfunc
496
497 profile func Foo1
498 profile func Foo2
499 call Foo1()
500 call Foo2()
501
502 profile func Foo3
503 profdel func Foo2
504 profdel func Foo3
505 call Foo1()
506 call Foo2()
507 call Foo3()
508 [CODE]
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200509 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200510 call system(GetVimCommandClean() . ' -es -c "so Xprofile_file.vim" -c q')
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200511 call assert_equal(0, v:shell_error)
512
513 let lines = readfile('Xprofile_file.log')
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200514 call assert_equal(26, len(lines))
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200515
516 " Check that:
517 " - Foo1() is called twice (profdel not invoked)
518 " - Foo2() is called once (profdel invoked after it was called)
519 " - Foo3() is not called (profdel invoked before it was called)
520 call assert_equal('FUNCTION Foo1()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200521 call assert_match('Defined:.*Xprofile_file.vim', lines[1])
522 call assert_equal('Called 2 times', lines[2])
523 call assert_equal('FUNCTION Foo2()', lines[8])
524 call assert_equal('Called 1 time', lines[10])
525 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[16])
526 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[21])
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200527
528 call delete('Xprofile_file.vim')
529 call delete('Xprofile_file.log')
530endfunc
531
532func Test_profdel_star()
533 " Foo() is invoked once before and once after 'profdel *'.
534 " So profiling should report it only once.
Bram Moolenaarc79745a2019-05-20 22:12:34 +0200535 let lines =<< trim [CODE]
536 profile start Xprofile_file.log
537 func! Foo()
538 endfunc
539 profile func Foo
540 call Foo()
541 profdel *
542 call Foo()
543 [CODE]
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200544 call writefile(lines, 'Xprofile_file.vim')
Bram Moolenaar93344c22019-08-14 21:12:05 +0200545 call system(GetVimCommandClean() . ' -es -c "so Xprofile_file.vim" -c q')
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200546 call assert_equal(0, v:shell_error)
547
548 let lines = readfile('Xprofile_file.log')
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200549 call assert_equal(16, len(lines))
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200550
551 call assert_equal('FUNCTION Foo()', lines[0])
Bram Moolenaar4c7b08f2018-09-10 22:03:40 +0200552 call assert_match('Defined:.*Xprofile_file.vim', lines[1])
553 call assert_equal('Called 1 time', lines[2])
554 call assert_equal('FUNCTIONS SORTED ON TOTAL TIME', lines[8])
555 call assert_equal('FUNCTIONS SORTED ON SELF TIME', lines[12])
Bram Moolenaar1fbfe7c2018-06-30 21:18:13 +0200556
557 call delete('Xprofile_file.vim')
558 call delete('Xprofile_file.log')
559endfunc
Bram Moolenaar16358802019-08-30 18:37:26 +0200560
561" When typing the function it won't have a script ID, test that this works.
562func Test_profile_typed_func()
563 CheckScreendump
564
565 let lines =<< trim END
566 profile start XprofileTypedFunc
567 END
568 call writefile(lines, 'XtestProfile')
569 let buf = RunVimInTerminal('-S XtestProfile', #{})
570
571 call term_sendkeys(buf, ":func DoSomething()\<CR>"
572 \ .. "echo 'hello'\<CR>"
573 \ .. "endfunc\<CR>")
574 call term_sendkeys(buf, ":profile func DoSomething\<CR>")
575 call term_sendkeys(buf, ":call DoSomething()\<CR>")
Bram Moolenaar6a2c5a72020-04-08 21:50:25 +0200576 call TermWait(buf, 100)
Bram Moolenaar16358802019-08-30 18:37:26 +0200577 call StopVimInTerminal(buf)
578 let lines = readfile('XprofileTypedFunc')
579 call assert_equal("FUNCTION DoSomething()", lines[0])
580 call assert_equal("Called 1 time", lines[1])
581
582 " clean up
583 call delete('XprofileTypedFunc')
584 call delete('XtestProfile')
585endfunc
Bram Moolenaar6d91bcb2020-08-12 18:50:36 +0200586
Bram Moolenaare5ea3462021-01-25 21:01:48 +0100587func Test_vim9_profiling()
588 " only tests that compiling and calling functions doesn't crash
589 let lines =<< trim END
590 vim9script
591 def Func()
592 Crash()
593 enddef
594 def Crash()
595 enddef
Bram Moolenaar98989a02021-01-26 12:06:30 +0100596 prof start Xprofile_crash.log
Bram Moolenaare5ea3462021-01-25 21:01:48 +0100597 prof func Func
598 Func()
599 END
Bram Moolenaar98989a02021-01-26 12:06:30 +0100600 call writefile(lines, 'Xprofile_crash.vim')
601 call system(GetVimCommandClean() . ' -es -c "so Xprofile_crash.vim" -c q')
602 call assert_equal(0, v:shell_error)
Bram Moolenaare5ea3462021-01-25 21:01:48 +0100603 call CheckScriptSuccess(lines)
Bram Moolenaar98989a02021-01-26 12:06:30 +0100604 call delete('Xprofile_crash.vim')
605 call delete('Xprofile_crash.log')
Bram Moolenaare5ea3462021-01-25 21:01:48 +0100606endfunc
607
608
Bram Moolenaar6d91bcb2020-08-12 18:50:36 +0200609" vim: shiftwidth=2 sts=2 expandtab