blob: ee617760f8105b39d748c92a3465e3e29529017e [file] [log] [blame]
Bram Moolenaar296b1f22017-01-15 15:22:33 +01001" Test Vim profiler
2if !has('profile')
3 finish
4endif
5
6func Test_profile_func()
Bram Moolenaar296b1f22017-01-15 15:22:33 +01007 let lines = [
8 \ "func! Foo1()",
9 \ "endfunc",
10 \ "func! Foo2()",
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010011 \ " let l:count = 100",
12 \ " while l:count > 0",
13 \ " let l:count = l:count - 1",
Bram Moolenaar296b1f22017-01-15 15:22:33 +010014 \ " endwhile",
15 \ "endfunc",
16 \ "func! Foo3()",
17 \ "endfunc",
18 \ "func! Bar()",
19 \ "endfunc",
20 \ "call Foo1()",
21 \ "call Foo1()",
22 \ "profile pause",
23 \ "call Foo1()",
24 \ "profile continue",
25 \ "call Foo2()",
26 \ "call Foo3()",
27 \ "call Bar()",
28 \ "if !v:profiling",
29 \ " delfunc Foo2",
30 \ "endif",
31 \ "delfunc Foo3",
32 \ ]
33
34 call writefile(lines, 'Xprofile_func.vim')
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010035 call system(v:progpath
36 \ . ' -es -u NONE -U NONE -i NONE --noplugin'
37 \ . ' -c "profile start Xprofile_func.log"'
38 \ . ' -c "profile func Foo*"'
39 \ . ' -c "so Xprofile_func.vim"'
40 \ . ' -c "qall!"')
41 call assert_equal(0, v:shell_error)
42
Bram Moolenaar296b1f22017-01-15 15:22:33 +010043 let lines = readfile('Xprofile_func.log')
44
Bram Moolenaar296b1f22017-01-15 15:22:33 +010045 " - Foo1() is called 3 times but should be reported as called twice
46 " since one call is in between "profile pause" .. "profile continue".
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010047 " - Foo2() should come before Foo1() since Foo1() does much more work.
Bram Moolenaar296b1f22017-01-15 15:22:33 +010048 " - 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*".
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010052 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])
Bram Moolenaar296b1f22017-01-15 15:22:33 +010082
83 call delete('Xprofile_func.vim')
84 call delete('Xprofile_func.log')
85endfunc
86
87func Test_profile_file()
Bram Moolenaar296b1f22017-01-15 15:22:33 +010088 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')
Bram Moolenaarc011a3d2017-01-16 22:37:42 +010099 call system(v:progpath
100 \ . ' -es -u NONE -U NONE -i NONE --noplugin'
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)
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100107
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])
Bram Moolenaar67435d92017-10-19 21:04:37 +0200118 call assert_match(' 2 0.\d\+ func! Foo()', lines[6])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100119 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])
Bram Moolenaard21b16f2017-08-14 23:13:30 +0200124 " 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])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100126 call assert_match('^\s*20\s\+\d\+\.\d\+\s\+endfor$', lines[11])
Bram Moolenaare32bbde2017-01-15 21:12:48 +0100127 " 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])
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100129 call assert_equal('', lines[13])
130
131 call delete('Xprofile_file.vim')
132 call delete('Xprofile_file.log')
133endfunc
134
Bram Moolenaar67435d92017-10-19 21:04:37 +0200135func 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
Bram Moolenaar296b1f22017-01-15 15:22:33 +0100171func 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
Bram Moolenaarac112f02017-12-05 16:46:28 +0100184
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