Mercurial > hg
view tests/test-profile.t @ 47802:de2e04fe4897
hgwebdir: avoid systematic full garbage collection
Forcing a systematic full garbage collection upon each request
can serioulsy harm performance. This is reported as
https://bz.mercurial-scm.org/show_bug.cgi?id=6075
With this change we're performing the full collection according
to a new setting, `experimental.web.full-garbage-collection-rate`.
The default value is 1, which doesn't change the behavior and will
allow us to test on real use cases. If the value is 0, no full garbage
collection occurs.
Regardless of the value of the setting, a partial garbage collection
still occurs upon each request (not attempting to collect objects from
the oldest generation). This should be enough to take care of
reference cycles that have been created by the last request
(assessment of this requires changing the setting, not to be 1).
In my experience chasing memory leaks in Mercurial servers,
the full collection never reclaimed any memory, but this is with
Python 3 and biased towards small repositories.
On the other hand, as explained in the Python developer docs [1],
frequent full collections are very harmful in terms of performance if
lots of objects survive the collection, and hence stay in the
oldest generation. Note that `gc.collect()` is indeed trying to
collect the oldest generation [2]. This happens usually in two cases:
- unwanted lingering objects (i.e., an actual memory leak that
the GC cannot do anything about). Sadly, we have lots of those
these days.
- desireable long-term objects, typically in caches (not inner caches
carried by repositories, which should be collected with them). This
is a subject of interest for the Heptapod project.
In short, the flat rate that this change still permits is
probably a bad idea in most cases, and the default value can
be tweaked later on (or even be set to 0) according to experiments
in the wild.
The test is inspired from test-hgwebdir-paths.py
[1] https://devguide.python.org/garbage_collector/#collecting-the-oldest-generation
[2] https://docs.python.org/3/library/gc.html#gc.collect
Differential Revision: https://phab.mercurial-scm.org/D11204
author | Georges Racinet <georges.racinet@octobus.net> |
---|---|
date | Tue, 20 Jul 2021 17:20:19 +0200 |
parents | dc3f7aa15423 |
children | 42d2b31cee0b |
line wrap: on
line source
test --time $ hg --time help -q help 2>&1 | grep time > /dev/null $ hg init a $ cd a Function to check that statprof ran $ statprofran () { > egrep 'Sample count:|No samples recorded' > /dev/null > } test --profile $ hg st --profile 2>&1 | statprofran Abreviated version $ hg st --prof 2>&1 | statprofran In alias $ hg --config "alias.profst=status --profile" profst 2>&1 | statprofran #if lsprof $ prof () { > hg --config profiling.type=ls --profile $@ > } $ prof st 2>../out $ grep CallCount ../out > /dev/null || cat ../out $ prof --config profiling.output=../out st $ grep CallCount ../out > /dev/null || cat ../out $ prof --config profiling.output=blackbox --config extensions.blackbox= st $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log $ prof --config profiling.format=text st 2>../out $ grep CallCount ../out > /dev/null || cat ../out $ echo "[profiling]" >> $HGRCPATH $ echo "format=kcachegrind" >> $HGRCPATH $ prof st 2>../out $ grep 'events: Ticks' ../out > /dev/null || cat ../out $ prof --config profiling.output=../out st $ grep 'events: Ticks' ../out > /dev/null || cat ../out #endif #if lsprof serve Profiling of HTTP requests works $ prof --config profiling.format=text --config profiling.output=../profile.log serve -d -p $HGPORT --pid-file ../hg.pid -A ../access.log $ 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) #endif Install an extension that can sleep and guarantee a profiler has time to run $ cat >> sleepext_with_a_long_filename.py << EOF > import time > from mercurial import registrar > cmdtable = {} > command = registrar.command(cmdtable) > @command(b'sleep', [], b'hg sleep') > def sleep_for_at_least_one_stat_cycle(ui, *args, **kwargs): > t = time.time() # don't use time.sleep because we need CPU time > while time.time() - t < 0.5: > pass > EOF $ cat >> $HGRCPATH << EOF > [extensions] > sleep = `pwd`/sleepext_with_a_long_filename.py > EOF statistical profiler works $ hg --profile sleep 2>../out $ cat ../out | statprofran Various statprof formatters work $ hg --profile --config profiling.statformat=byline sleep 2>../out || cat ../out $ grep -v _path_stat ../out | head -n 3 % cumulative self time seconds seconds name * sleepext_with_a_long_filename.py:*:sleep_for_at_least_one_stat_cycle (glob) $ cat ../out | statprofran $ hg --profile --config profiling.statformat=bymethod sleep 2>../out || cat ../out $ head -n 1 ../out % cumulative self $ cat ../out | statprofran Windows real time tracking is broken, only use CPU #if no-windows $ hg --profile --config profiling.time-track=real --config profiling.statformat=hotpath sleep 2>../out || cat ../out $ cat ../out | statprofran $ grep sleepext_with_a_long_filename.py ../out | head -n 1 .* [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) #endif $ hg --profile --config profiling.time-track=cpu --config profiling.statformat=hotpath sleep 2>../out || cat ../out $ cat ../out | statprofran $ grep sleepext_with_a_long_filename.py ../out | head -n 1 .* [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) $ hg --profile --config profiling.statformat=json sleep 2>../out || cat ../out $ cat ../out \[\[-?\d+.* (re) statprof can be used as a standalone module $ "$PYTHON" -m mercurial.statprof hotpath must specify --file to load [1] $ cd .. #if no-chg profiler extension could be loaded before other extensions $ cat > fooprof.py <<EOF > from __future__ import absolute_import > import contextlib > import sys > @contextlib.contextmanager > def profile(ui, fp): > print('fooprof: start profile') > sys.stdout.flush() > yield > print('fooprof: end profile') > sys.stdout.flush() > def extsetup(ui): > ui.write(b'fooprof: loaded\n') > EOF $ cat > otherextension.py <<EOF > from __future__ import absolute_import > def extsetup(ui): > ui.write(b'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 $TESTTMP/b $ HGPROF=fooprof hg root --profile fooprof: loaded fooprof: start profile otherextension: loaded $TESTTMP/b 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 .. #endif