view tests/test-profile.t @ 47010:76ae43d5b1db stable

repoview: fix memory leak of filtered repo classes

The leak occurs in long-running server processes with
extensions, and is measured at 110kB per request.

Before this change, the contents of the `_filteredrepotypes`
cache are not properly garbage collected, despite it begin
a `WeakKeyDictionary`.

Extensions have a tendency to generate a new repository class
for each `localrepo` instantiation. Server processes based
on `hgwebdir_mod` will instantiate a new `localrepo` for each
HTTP request that involves a repository.

As a result, with a testing process that repeatedly opens a
repository with several extensions activated
(`topic` notably among them), we see a steady increase in
resident memory of 110kB per repository instantiation before this
change. This is also true, if we call `gc.collect()` at each
instantiation, like `hgwebdir_mod` does, or not.

The cause of the leak is that the *values* aren't weak references.
This change uses `weakref.ref` for the values, and this makes
in our measurements the resident size increase drop to 5kB per
repository instantiation, with no explicit call of `gc.collect()`
at all.
There is currently no reason to believe that this remaining leak
of 5kB is related to or even due to Mercurial core.

We've also seen evidence that `ui.ui` instances weren't properly
garbage collected before the change (with the change, they are).
This could explain why the figures are relatively high.

In theory, the collection of weak references could lead to
much more misses in the cache, so we measured the impact on
the original case that was motivation for introducing that cache
in 7e89bd0cfb86 (see also issue5043): `hg convert` of the
mozilla-central repository. The bad news here is that there is a
major memory leak there, both with and without the present changeset.
There were no more cache misses, and we could see no
more memory leak with this change: the resident size after importing
roughly 100000 changesets was at 12.4GB before, and 12.5GB after.
The small increase is mentioned for completeness only, and we
believe that it should be ignored, at least as long as the main
leak isn't fixed. At less than 1% of the main leak, even finding out
whether it is merely noise would be wasteful.

Original context where this was spotted and first mitigated:
  https://foss.heptapod.net/heptapod/heptapod/-/issues/466

The leak reduction was also obtained in Heptapod inner HTTP server,
which amounts to the same as `hgwebdir_mod` for these questions.

The measurements done with Python 3.9, similar figures seen with 3.8.
More work on our side would be needed to give measurements with 2.7,
because of testing server process does not support it.

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):
  >     time.sleep(0.1)
  > 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

  $ hg --profile --config profiling.statformat=hotpath sleep 2>../out || cat ../out
  $ cat ../out | statprofran
  $ grep sleepext_with_a_long_filename.py ../out
  .* [0-9.]+%  [0-9.]+s  sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line 7:    time\.sleep.* (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