##// END OF EJS Templates
profiling: use "stat" profiler to profile individual request...
marmoute -
r52734:102770bb stable
parent child Browse files
Show More
@@ -1,188 +1,194
1 test --time
1 test --time
2
2
3 $ hg --time help -q help 2>&1 | grep time > /dev/null
3 $ hg --time help -q help 2>&1 | grep time > /dev/null
4 $ hg init a
4 $ hg init a
5 $ cd a
5 $ cd a
6
6
7 Function to check that statprof ran
7 Function to check that statprof ran
8 $ statprofran () {
8 $ statprofran () {
9 > grep -E 'Sample count:|No samples recorded' > /dev/null
9 > grep -E 'Sample count:|No samples recorded' > /dev/null
10 > }
10 > }
11
11
12 test --profile
12 test --profile
13
13
14 $ hg st --profile 2>&1 | statprofran
14 $ hg st --profile 2>&1 | statprofran
15
15
16 Abreviated version
16 Abreviated version
17
17
18 $ hg st --prof 2>&1 | statprofran
18 $ hg st --prof 2>&1 | statprofran
19
19
20 In alias
20 In alias
21
21
22 $ hg --config "alias.profst=status --profile" profst 2>&1 | statprofran
22 $ hg --config "alias.profst=status --profile" profst 2>&1 | statprofran
23
23
24 #if lsprof
24 #if lsprof
25
25
26 $ prof () {
26 $ prof () {
27 > hg --config profiling.type=ls --profile $@
27 > hg --config profiling.type=ls --profile $@
28 > }
28 > }
29
29
30 $ prof st 2>../out
30 $ prof st 2>../out
31 $ grep CallCount ../out > /dev/null || cat ../out
31 $ grep CallCount ../out > /dev/null || cat ../out
32
32
33 $ prof --config profiling.output=../out st
33 $ prof --config profiling.output=../out st
34 $ grep CallCount ../out > /dev/null || cat ../out
34 $ grep CallCount ../out > /dev/null || cat ../out
35
35
36 $ prof --config profiling.output=blackbox --config extensions.blackbox= st
36 $ prof --config profiling.output=blackbox --config extensions.blackbox= st
37 $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log
37 $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log
38
38
39 $ prof --config profiling.format=text st 2>../out
39 $ prof --config profiling.format=text st 2>../out
40 $ grep CallCount ../out > /dev/null || cat ../out
40 $ grep CallCount ../out > /dev/null || cat ../out
41
41
42 $ echo "[profiling]" >> $HGRCPATH
42 $ echo "[profiling]" >> $HGRCPATH
43 $ echo "format=kcachegrind" >> $HGRCPATH
43 $ echo "format=kcachegrind" >> $HGRCPATH
44
44
45 $ prof st 2>../out
45 $ prof st 2>../out
46 $ grep 'events: Ticks' ../out > /dev/null || cat ../out
46 $ grep 'events: Ticks' ../out > /dev/null || cat ../out
47
47
48 $ prof --config profiling.output=../out st
48 $ prof --config profiling.output=../out st
49 $ grep 'events: Ticks' ../out > /dev/null || cat ../out
49 $ grep 'events: Ticks' ../out > /dev/null || cat ../out
50
50
51 #endif
51 #endif
52
52
53 #if lsprof serve
53 #if serve
54
54
55 Profiling of HTTP requests works
55 Profiling of HTTP requests works
56
56
57 $ prof \
57 $ stats_prof () {
58 > hg --config profiling.type=stat --profile $@
59 > }
60
61 $ stats_prof \
58 > --config profiling.format=text \
62 > --config profiling.format=text \
59 > --config profiling.output=../profile.log \
63 > --config profiling.output=../profile.log \
60 > serve -d \
64 > serve -d \
61 > -p $HGPORT \
65 > -p $HGPORT \
62 > --pid-file ../hg.pid \
66 > --pid-file ../hg.pid \
63 > -A ../access.log \
67 > -A ../access.log \
64 > --errorlog ../error.log
68 > --errorlog ../error.log
65 $ cat ../hg.pid >> $DAEMON_PIDS
69 $ cat ../hg.pid >> $DAEMON_PIDS
66 $ hg -q clone -U http://localhost:$HGPORT ../clone
70 $ hg -q clone -U http://localhost:$HGPORT ../clone
67 $ cat ../error.log
71 $ cat ../error.log
68
72
69 A single profile is logged because file logging doesn't append
73 A single profile is logged because file logging doesn't append
70 $ grep CallCount ../profile.log | wc -l
74 $ grep 'Sample count:' ../profile.log | wc -l
75 \s*1 (re)
76 $ grep 'Total time:' ../profile.log | wc -l
71 \s*1 (re)
77 \s*1 (re)
72
78
73 #endif
79 #endif
74
80
75 Install an extension that can sleep and guarantee a profiler has time to run
81 Install an extension that can sleep and guarantee a profiler has time to run
76
82
77 $ cat >> sleepext_with_a_long_filename.py << EOF
83 $ cat >> sleepext_with_a_long_filename.py << EOF
78 > import time
84 > import time
79 > from mercurial import registrar
85 > from mercurial import registrar
80 > cmdtable = {}
86 > cmdtable = {}
81 > command = registrar.command(cmdtable)
87 > command = registrar.command(cmdtable)
82 > @command(b'sleep', [], b'hg sleep')
88 > @command(b'sleep', [], b'hg sleep')
83 > def sleep_for_at_least_one_stat_cycle(ui, *args, **kwargs):
89 > def sleep_for_at_least_one_stat_cycle(ui, *args, **kwargs):
84 > t = time.time() # don't use time.sleep because we need CPU time
90 > t = time.time() # don't use time.sleep because we need CPU time
85 > while time.time() - t < 0.5:
91 > while time.time() - t < 0.5:
86 > pass
92 > pass
87 > EOF
93 > EOF
88
94
89 $ cat >> $HGRCPATH << EOF
95 $ cat >> $HGRCPATH << EOF
90 > [extensions]
96 > [extensions]
91 > sleep = `pwd`/sleepext_with_a_long_filename.py
97 > sleep = `pwd`/sleepext_with_a_long_filename.py
92 > EOF
98 > EOF
93
99
94 statistical profiler works
100 statistical profiler works
95
101
96 $ hg --profile sleep 2>../out
102 $ hg --profile sleep 2>../out
97 $ cat ../out | statprofran
103 $ cat ../out | statprofran
98
104
99 Various statprof formatters work
105 Various statprof formatters work
100
106
101 $ hg --profile --config profiling.statformat=byline sleep 2>../out || cat ../out
107 $ hg --profile --config profiling.statformat=byline sleep 2>../out || cat ../out
102 $ grep -v _path_stat ../out | head -n 3
108 $ grep -v _path_stat ../out | head -n 3
103 % cumulative self
109 % cumulative self
104 time seconds seconds name
110 time seconds seconds name
105 * sleepext_with_a_long_filename.py:*:sleep_for_at_least_one_stat_cycle (glob)
111 * sleepext_with_a_long_filename.py:*:sleep_for_at_least_one_stat_cycle (glob)
106 $ cat ../out | statprofran
112 $ cat ../out | statprofran
107
113
108 $ hg --profile --config profiling.statformat=bymethod sleep 2>../out || cat ../out
114 $ hg --profile --config profiling.statformat=bymethod sleep 2>../out || cat ../out
109 $ head -n 1 ../out
115 $ head -n 1 ../out
110 % cumulative self
116 % cumulative self
111 $ cat ../out | statprofran
117 $ cat ../out | statprofran
112
118
113 Windows real time tracking is broken, only use CPU
119 Windows real time tracking is broken, only use CPU
114
120
115 #if no-windows
121 #if no-windows
116 $ hg --profile --config profiling.time-track=real --config profiling.statformat=hotpath sleep 2>../out || cat ../out
122 $ hg --profile --config profiling.time-track=real --config profiling.statformat=hotpath sleep 2>../out || cat ../out
117 $ cat ../out | statprofran
123 $ cat ../out | statprofran
118 $ grep sleepext_with_a_long_filename.py ../out | head -n 1
124 $ grep sleepext_with_a_long_filename.py ../out | head -n 1
119 .* [0-9.]+% [0-9.]+s sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line \d+:\s+(while|pass).* (re)
125 .* [0-9.]+% [0-9.]+s sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line \d+:\s+(while|pass).* (re)
120 #endif
126 #endif
121
127
122 $ hg --profile --config profiling.time-track=cpu --config profiling.statformat=hotpath sleep 2>../out || cat ../out
128 $ hg --profile --config profiling.time-track=cpu --config profiling.statformat=hotpath sleep 2>../out || cat ../out
123 $ cat ../out | statprofran
129 $ cat ../out | statprofran
124 $ grep sleepext_with_a_long_filename.py ../out | head -n 1
130 $ grep sleepext_with_a_long_filename.py ../out | head -n 1
125 .* [0-9.]+% [0-9.]+s sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line \d+:\s+(while|pass).* (re)
131 .* [0-9.]+% [0-9.]+s sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line \d+:\s+(while|pass).* (re)
126
132
127 $ hg --profile --config profiling.statformat=json sleep 2>../out || cat ../out
133 $ hg --profile --config profiling.statformat=json sleep 2>../out || cat ../out
128 $ cat ../out
134 $ cat ../out
129 \[\[-?\d+.* (re)
135 \[\[-?\d+.* (re)
130
136
131 statprof can be used as a standalone module
137 statprof can be used as a standalone module
132
138
133 $ "$PYTHON" -m mercurial.statprof hotpath
139 $ "$PYTHON" -m mercurial.statprof hotpath
134 must specify --file to load
140 must specify --file to load
135 [1]
141 [1]
136
142
137 $ cd ..
143 $ cd ..
138
144
139 #if no-chg
145 #if no-chg
140 profiler extension could be loaded before other extensions
146 profiler extension could be loaded before other extensions
141
147
142 $ cat > fooprof.py <<EOF
148 $ cat > fooprof.py <<EOF
143 > import contextlib
149 > import contextlib
144 > import sys
150 > import sys
145 > @contextlib.contextmanager
151 > @contextlib.contextmanager
146 > def profile(ui, fp):
152 > def profile(ui, fp):
147 > print('fooprof: start profile')
153 > print('fooprof: start profile')
148 > sys.stdout.flush()
154 > sys.stdout.flush()
149 > yield
155 > yield
150 > print('fooprof: end profile')
156 > print('fooprof: end profile')
151 > sys.stdout.flush()
157 > sys.stdout.flush()
152 > def extsetup(ui):
158 > def extsetup(ui):
153 > ui.write(b'fooprof: loaded\n')
159 > ui.write(b'fooprof: loaded\n')
154 > EOF
160 > EOF
155
161
156 $ cat > otherextension.py <<EOF
162 $ cat > otherextension.py <<EOF
157 > def extsetup(ui):
163 > def extsetup(ui):
158 > ui.write(b'otherextension: loaded\n')
164 > ui.write(b'otherextension: loaded\n')
159 > EOF
165 > EOF
160
166
161 $ hg init b
167 $ hg init b
162 $ cd b
168 $ cd b
163 $ cat >> .hg/hgrc <<EOF
169 $ cat >> .hg/hgrc <<EOF
164 > [extensions]
170 > [extensions]
165 > other = $TESTTMP/otherextension.py
171 > other = $TESTTMP/otherextension.py
166 > fooprof = $TESTTMP/fooprof.py
172 > fooprof = $TESTTMP/fooprof.py
167 > EOF
173 > EOF
168
174
169 $ hg root
175 $ hg root
170 otherextension: loaded
176 otherextension: loaded
171 fooprof: loaded
177 fooprof: loaded
172 $TESTTMP/b
178 $TESTTMP/b
173 $ HGPROF=fooprof hg root --profile
179 $ HGPROF=fooprof hg root --profile
174 fooprof: loaded
180 fooprof: loaded
175 fooprof: start profile
181 fooprof: start profile
176 otherextension: loaded
182 otherextension: loaded
177 $TESTTMP/b
183 $TESTTMP/b
178 fooprof: end profile
184 fooprof: end profile
179
185
180 $ HGPROF=other hg root --profile 2>&1 | head -n 2
186 $ HGPROF=other hg root --profile 2>&1 | head -n 2
181 otherextension: loaded
187 otherextension: loaded
182 unrecognized profiler 'other' - ignored
188 unrecognized profiler 'other' - ignored
183
189
184 $ HGPROF=unknown hg root --profile 2>&1 | head -n 1
190 $ HGPROF=unknown hg root --profile 2>&1 | head -n 1
185 unrecognized profiler 'unknown' - ignored
191 unrecognized profiler 'unknown' - ignored
186
192
187 $ cd ..
193 $ cd ..
188 #endif
194 #endif
General Comments 0
You need to be logged in to leave comments. Login now