2010-09-26 22:44:49 +04:00
|
|
|
test --time
|
|
|
|
|
2012-06-12 16:18:18 +04:00
|
|
|
$ hg --time help -q help 2>&1 | grep time > /dev/null
|
2010-09-26 22:44:49 +04:00
|
|
|
$ hg init a
|
|
|
|
$ cd a
|
|
|
|
|
2017-07-31 22:43:26 +03:00
|
|
|
Function to check that statprof ran
|
|
|
|
$ statprofran () {
|
|
|
|
> egrep 'Sample count:|No samples recorded' > /dev/null
|
|
|
|
> }
|
2012-06-10 15:01:40 +04:00
|
|
|
|
2010-09-26 22:44:49 +04:00
|
|
|
test --profile
|
|
|
|
|
2017-07-31 22:43:26 +03:00
|
|
|
$ hg st --profile 2>&1 | statprofran
|
2017-06-09 14:36:07 +03:00
|
|
|
|
|
|
|
Abreviated version
|
|
|
|
|
2017-07-31 22:43:26 +03:00
|
|
|
$ hg st --prof 2>&1 | statprofran
|
2017-06-09 14:36:07 +03:00
|
|
|
|
|
|
|
In alias
|
|
|
|
|
2017-07-31 22:43:26 +03:00
|
|
|
$ hg --config "alias.profst=status --profile" profst 2>&1 | statprofran
|
2017-06-09 14:36:07 +03:00
|
|
|
|
|
|
|
#if lsprof
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ prof='hg --config profiling.type=ls --profile'
|
|
|
|
|
|
|
|
$ $prof st 2>../out
|
2012-06-10 15:01:40 +04:00
|
|
|
$ grep CallCount ../out > /dev/null || cat ../out
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ $prof --config profiling.output=../out st
|
2012-06-10 15:01:40 +04:00
|
|
|
$ grep CallCount ../out > /dev/null || cat ../out
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ $prof --config profiling.output=blackbox --config extensions.blackbox= st
|
2015-09-08 21:39:52 +03:00
|
|
|
$ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ $prof --config profiling.format=text st 2>../out
|
2012-06-10 15:01:40 +04:00
|
|
|
$ grep CallCount ../out > /dev/null || cat ../out
|
|
|
|
|
|
|
|
$ echo "[profiling]" >> $HGRCPATH
|
|
|
|
$ echo "format=kcachegrind" >> $HGRCPATH
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ $prof st 2>../out
|
2012-06-10 15:01:40 +04:00
|
|
|
$ grep 'events: Ticks' ../out > /dev/null || cat ../out
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ $prof --config profiling.output=../out st
|
2012-06-10 15:01:40 +04:00
|
|
|
$ grep 'events: Ticks' ../out > /dev/null || cat ../out
|
|
|
|
|
2016-08-15 04:37:24 +03:00
|
|
|
#endif
|
|
|
|
|
|
|
|
#if lsprof serve
|
|
|
|
|
|
|
|
Profiling of HTTP requests works
|
|
|
|
|
2016-08-17 18:52:15 +03:00
|
|
|
$ $prof --config profiling.format=text --config profiling.output=../profile.log serve -d -p $HGPORT --pid-file ../hg.pid -A ../access.log
|
2016-08-15 04:37:24 +03:00
|
|
|
$ cat ../hg.pid >> $DAEMON_PIDS
|
|
|
|
$ hg -q clone -U http://localhost:$HGPORT ../clone
|
|
|
|
|
|
|
|
A single profile is logged because file logging doesn't append
|
|
|
|
$ grep CallCount ../profile.log | wc -l
|
|
|
|
\s*1 (re)
|
|
|
|
|
2012-06-10 15:01:40 +04:00
|
|
|
#endif
|
2012-06-11 03:40:51 +04:00
|
|
|
|
2016-11-05 06:50:38 +03:00
|
|
|
Install an extension that can sleep and guarantee a profiler has time to run
|
|
|
|
|
|
|
|
$ cat >> sleepext.py << EOF
|
|
|
|
> import time
|
2016-01-09 17:07:20 +03:00
|
|
|
> from mercurial import registrar, commands
|
2016-11-05 06:50:38 +03:00
|
|
|
> cmdtable = {}
|
2016-01-09 17:07:20 +03:00
|
|
|
> command = registrar.command(cmdtable)
|
2017-06-25 05:50:05 +03:00
|
|
|
> @command(b'sleep', [], 'hg sleep')
|
2016-11-05 06:50:38 +03:00
|
|
|
> def sleep(ui, *args, **kwargs):
|
|
|
|
> time.sleep(0.1)
|
|
|
|
> EOF
|
|
|
|
|
|
|
|
$ cat >> $HGRCPATH << EOF
|
|
|
|
> [extensions]
|
|
|
|
> sleep = `pwd`/sleepext.py
|
|
|
|
> EOF
|
|
|
|
|
|
|
|
statistical profiler works
|
|
|
|
|
2016-11-05 07:44:25 +03:00
|
|
|
$ hg --profile sleep 2>../out
|
2017-07-31 22:43:26 +03:00
|
|
|
$ cat ../out | statprofran
|
2016-11-05 06:50:38 +03:00
|
|
|
|
|
|
|
Various statprof formatters work
|
|
|
|
|
2016-11-05 07:44:25 +03:00
|
|
|
$ hg --profile --config profiling.statformat=byline sleep 2>../out
|
2016-11-05 06:50:38 +03:00
|
|
|
$ head -n 1 ../out
|
|
|
|
% cumulative self
|
2017-07-31 22:43:26 +03:00
|
|
|
$ cat ../out | statprofran
|
2016-11-05 06:50:38 +03:00
|
|
|
|
2016-11-05 07:44:25 +03:00
|
|
|
$ hg --profile --config profiling.statformat=bymethod sleep 2>../out
|
2016-11-05 06:50:38 +03:00
|
|
|
$ head -n 1 ../out
|
|
|
|
% cumulative self
|
2017-07-31 22:43:26 +03:00
|
|
|
$ cat ../out | statprofran
|
2016-11-05 06:50:38 +03:00
|
|
|
|
2016-11-05 07:44:25 +03:00
|
|
|
$ hg --profile --config profiling.statformat=hotpath sleep 2>../out
|
2017-07-31 22:43:26 +03:00
|
|
|
$ cat ../out | statprofran
|
2016-11-05 06:50:38 +03:00
|
|
|
|
2016-11-05 07:44:25 +03:00
|
|
|
$ hg --profile --config profiling.statformat=json sleep 2>../out
|
2016-11-05 06:50:38 +03:00
|
|
|
$ cat ../out
|
2017-04-20 16:45:45 +03:00
|
|
|
\[\[-?\d+.* (re)
|
2016-11-05 06:50:38 +03:00
|
|
|
|
2018-02-02 23:17:46 +03:00
|
|
|
#if normal-layout
|
2017-01-19 09:45:07 +03:00
|
|
|
statprof can be used as a standalone module
|
|
|
|
|
|
|
|
$ $PYTHON -m mercurial.statprof hotpath
|
|
|
|
must specify --file to load
|
|
|
|
[1]
|
2018-02-02 23:17:46 +03:00
|
|
|
#endif
|
2017-01-19 09:45:07 +03:00
|
|
|
|
2012-06-11 03:40:51 +04:00
|
|
|
$ cd ..
|
2017-05-22 11:17:49 +03:00
|
|
|
|
2017-10-03 05:10:32 +03:00
|
|
|
#if no-chg
|
2017-05-22 11:17:49 +03:00
|
|
|
profiler extension could be loaded before other extensions
|
|
|
|
|
|
|
|
$ cat > fooprof.py <<EOF
|
|
|
|
> from __future__ import absolute_import
|
|
|
|
> import contextlib
|
|
|
|
> @contextlib.contextmanager
|
2018-09-22 00:29:25 +03:00
|
|
|
> def profile(ui, fp, section):
|
2017-05-22 11:17:49 +03:00
|
|
|
> print('fooprof: start profile')
|
|
|
|
> yield
|
|
|
|
> print('fooprof: end profile')
|
|
|
|
> def extsetup(ui):
|
|
|
|
> ui.write('fooprof: loaded\n')
|
|
|
|
> EOF
|
|
|
|
|
|
|
|
$ cat > otherextension.py <<EOF
|
|
|
|
> from __future__ import absolute_import
|
|
|
|
> def extsetup(ui):
|
|
|
|
> ui.write('otherextension: loaded\n')
|
|
|
|
> EOF
|
|
|
|
|
|
|
|
$ hg init b
|
|
|
|
$ cd b
|
|
|
|
$ cat >> .hg/hgrc <<EOF
|
|
|
|
> [extensions]
|
|
|
|
> other = $TESTTMP/otherextension.py
|
|
|
|
> fooprof = $TESTTMP/fooprof.py
|
|
|
|
> EOF
|
|
|
|
|
|
|
|
$ hg root
|
|
|
|
otherextension: loaded
|
|
|
|
fooprof: loaded
|
2017-12-11 06:50:57 +03:00
|
|
|
$TESTTMP/b
|
2017-05-22 11:17:49 +03:00
|
|
|
$ HGPROF=fooprof hg root --profile
|
|
|
|
fooprof: loaded
|
|
|
|
fooprof: start profile
|
|
|
|
otherextension: loaded
|
2017-12-11 06:50:57 +03:00
|
|
|
$TESTTMP/b
|
2017-05-22 11:17:49 +03:00
|
|
|
fooprof: end profile
|
|
|
|
|
|
|
|
$ HGPROF=other hg root --profile 2>&1 | head -n 2
|
|
|
|
otherextension: loaded
|
|
|
|
unrecognized profiler 'other' - ignored
|
|
|
|
|
|
|
|
$ HGPROF=unknown hg root --profile 2>&1 | head -n 1
|
|
|
|
unrecognized profiler 'unknown' - ignored
|
|
|
|
|
|
|
|
$ cd ..
|
2017-10-03 05:10:32 +03:00
|
|
|
#endif
|
2018-09-22 00:29:15 +03:00
|
|
|
|
|
|
|
Test minelapsed config option
|
|
|
|
|
|
|
|
$ hg --profile --config profiling.minelapsed=1000 debugshell -c 'print(1)'
|
|
|
|
1
|
|
|
|
$ hg --profile --config profiling.minelapsed=1 debugshell -c 'import time; time.sleep(1.1)' 2>&1 | grep Sample
|
|
|
|
Sample count: * (glob)
|
2018-09-22 00:29:27 +03:00
|
|
|
|
|
|
|
Test other config sections
|
|
|
|
|
|
|
|
$ hg --config profiling:background.enabled=1 --config profiling:background.output=z debugshell -c '1'
|
|
|
|
unrecognized profiler 'None' - ignored
|
|
|
|
invalid sampling frequency 'None' - ignoring
|
|
|
|
unknown profiler output format: None
|
|
|
|
$ [ -f z ]
|
|
|
|
|
|
|
|
$ hg --profile --config profiling.output=x --config profiling:background.enabled=1 --config profiling:background.output=y debugshell -c '1'
|
|
|
|
$ [ -f x ]
|
|
|
|
$ [ -f y ]
|
|
|
|
[1]
|
2018-09-27 03:36:39 +03:00
|
|
|
|
|
|
|
Test statprof will not take at least frequency time.
|
|
|
|
|
|
|
|
>>> import time
|
|
|
|
>>> open('start', 'w').write('%s' % time.time())
|
|
|
|
|
|
|
|
$ hg --profile --config profiling.output=z --config profiling.type=stat --config profiling.freq=0.02 debugshell -c 'a=1'
|
|
|
|
|
|
|
|
>>> import time
|
|
|
|
>>> time.time() - float(open('start').read()) < 50
|
|
|
|
True
|