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 |
|
53 | #if serve | |
54 |
|
54 | |||
55 | Profiling of HTTP requests works |
|
55 | Profiling of HTTP requests works | |
56 |
|
56 | |||
57 |
$ |
|
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 |
|
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