branching: merge with stable

mercurial/profiling.py

@@ -1,340 +1,357
 # profiling.py - profiling functions
 #
 # Copyright 2016 Gregory Szorc <[e-mail]>
 #
 # This software may be used and distributed according to the terms of the
 # GNU General Public License version 2 or any later version.
 
 
 import contextlib
 import os
 import signal
 import subprocess
+import sys
 
 from .i18n import _
 from .pycompat import (
     open,
 )
 from . import (
     encoding,
     error,
     extensions,
     pycompat,
     util,
 )
 
 
 def _loadprofiler(ui, profiler):
     """load profiler extension. return profile method, or None on failure"""
     extname = profiler
     extensions.loadall(ui, whitelist=[extname])
     try:
         mod = extensions.find(extname)
     except KeyError:
         return None
     else:
         return getattr(mod, 'profile', None)
 
 
 @contextlib.contextmanager
 def lsprofile(ui, fp):
     format = ui.config(b'profiling', b'format')
     field = ui.config(b'profiling', b'sort')
     limit = ui.configint(b'profiling', b'limit')
     climit = ui.configint(b'profiling', b'nested')
 
     if format not in [b'text', b'kcachegrind']:
         ui.warn(_(b"unrecognized profiling format '%s' - Ignored\n") % format)
         format = b'text'
 
     try:
         from . import lsprof
     except ImportError:
         raise error.Abort(
             _(
                 b'lsprof not available - install from '
                 b'http://codespeak.net/svn/user/arigo/hack/misc/lsprof/'
             )
         )
     p = lsprof.Profiler()
-    p.enable(subcalls=True)
+    try:
+        p.enable(subcalls=True)
+    except ValueError as exc:
+        if str(exc) != "Another profiling tool is already active":
+            raise
+        if not hasattr(sys, "monitoring"):
+            raise
+        # python >=3.12 prevent more than one profiler to run at the same
+        # time, tries to improve the report to help the user understand
+        # what is going on.
+        other_tool_name = sys.monitoring.get_tool(sys.monitoring.PROFILER_ID)
+        if other_tool_name == "cProfile":
+            msg = 'cannot recursively call `lsprof`'
+            raise error.Abort(msg) from None
+        else:
+            m = 'failed to start "lsprofile"; another profiler already running: %s'
+            raise error.Abort(_(m) % other_tool_name) from None
     try:
         yield
     finally:
         p.disable()
 
         if format == b'kcachegrind':
             from . import lsprofcalltree
 
             calltree = lsprofcalltree.KCacheGrind(p)
             calltree.output(fp)
         else:
             # format == 'text'
             stats = lsprof.Stats(p.getstats())
             stats.sort(pycompat.sysstr(field))
             stats.pprint(limit=limit, file=fp, climit=climit)
         fp.flush()
 
 
 @contextlib.contextmanager
 def flameprofile(ui, fp):
     try:
         from flamegraph import flamegraph  # pytype: disable=import-error
     except ImportError:
         raise error.Abort(
             _(
                 b'flamegraph not available - install from '
                 b'https://github.com/evanhempel/python-flamegraph'
             )
         )
     # developer config: profiling.freq
     freq = ui.configint(b'profiling', b'freq')
     filter_ = None
     collapse_recursion = True
     thread = flamegraph.ProfileThread(
         fp, 1.0 / freq, filter_, collapse_recursion
     )
     start_time = util.timer()
     try:
         thread.start()
         yield
     finally:
         thread.stop()
         thread.join()
         m = b'Collected %d stack frames (%d unique) in %2.2f seconds.'
         m %= (
             (
                 util.timer() - start_time,
                 thread.num_frames(),
                 thread.num_frames(unique=True),
             ),
         )
         print(m, flush=True)
 
 
 @contextlib.contextmanager
 def statprofile(ui, fp):
     from . import statprof
 
     freq = ui.configint(b'profiling', b'freq')
     if freq > 0:
         # Cannot reset when profiler is already active. So silently no-op.
         if statprof.state.profile_level == 0:
             statprof.reset(freq)
     else:
         ui.warn(_(b"invalid sampling frequency '%s' - ignoring\n") % freq)
 
     track = ui.config(
         b'profiling', b'time-track', pycompat.iswindows and b'cpu' or b'real'
     )
     statprof.start(mechanism=b'thread', track=track)
 
     try:
         yield
     finally:
         data = statprof.stop()
 
         profformat = ui.config(b'profiling', b'statformat')
 
         formats = {
             b'byline': statprof.DisplayFormats.ByLine,
             b'bymethod': statprof.DisplayFormats.ByMethod,
             b'hotpath': statprof.DisplayFormats.Hotpath,
             b'json': statprof.DisplayFormats.Json,
             b'chrome': statprof.DisplayFormats.Chrome,
         }
 
         if profformat in formats:
             displayformat = formats[profformat]
         else:
             ui.warn(_(b'unknown profiler output format: %s\n') % profformat)
             displayformat = statprof.DisplayFormats.Hotpath
 
         kwargs = {}
 
         def fraction(s):
             if isinstance(s, (float, int)):
                 return float(s)
             if s.endswith(b'%'):
                 v = float(s[:-1]) / 100
             else:
                 v = float(s)
             if 0 <= v <= 1:
                 return v
             raise ValueError(s)
 
         if profformat == b'chrome':
             showmin = ui.configwith(fraction, b'profiling', b'showmin', 0.005)
             showmax = ui.configwith(fraction, b'profiling', b'showmax')
             kwargs.update(minthreshold=showmin, maxthreshold=showmax)
         elif profformat == b'hotpath':
             # inconsistent config: profiling.showmin
             limit = ui.configwith(fraction, b'profiling', b'showmin', 0.05)
             kwargs['limit'] = limit
             showtime = ui.configbool(b'profiling', b'showtime')
             kwargs['showtime'] = showtime
 
         statprof.display(fp, data=data, format=displayformat, **kwargs)
         fp.flush()
 
 
 @contextlib.contextmanager
 def pyspy_profile(ui, fp):
     exe = ui.config(b'profiling', b'py-spy.exe')
 
     freq = ui.configint(b'profiling', b'py-spy.freq')
 
     format = ui.config(b'profiling', b'py-spy.format')
 
     fd = fp.fileno()
 
     output_path = "/dev/fd/%d" % (fd)
 
     my_pid = os.getpid()
 
     cmd = [
         exe,
         "record",
         "--pid",
         str(my_pid),
         "--native",
         "--rate",
         str(freq),
         "--output",
         output_path,
     ]
 
     if format:
         cmd.extend(["--format", format])
 
     proc = subprocess.Popen(
         cmd,
         pass_fds={fd},
         stdout=subprocess.PIPE,
     )
 
     _ = proc.stdout.readline()
 
     try:
         yield
     finally:
         os.kill(proc.pid, signal.SIGINT)
         proc.communicate()
 
 
 class profile:
     """Start profiling.
 
     Profiling is active when the context manager is active. When the context
     manager exits, profiling results will be written to the configured output.
     """
 
     def __init__(self, ui, enabled=True):
         self._ui = ui
         self._output = None
         self._fp = None
         self._fpdoclose = True
         self._flushfp = None
         self._profiler = None
         self._enabled = enabled
         self._entered = False
         self._started = False
 
     def __enter__(self):
         self._entered = True
         if self._enabled:
             self.start()
         return self
 
     def start(self):
         """Start profiling.
 
         The profiling will stop at the context exit.
 
         If the profiler was already started, this has no effect."""
         if not self._entered:
             raise error.ProgrammingError(b'use a context manager to start')
         if self._started:
             return
         self._started = True
         profiler = encoding.environ.get(b'HGPROF')
         proffn = None
         if profiler is None:
             profiler = self._ui.config(b'profiling', b'type')
         if profiler not in (b'ls', b'stat', b'flame', b'py-spy'):
             # try load profiler from extension with the same name
             proffn = _loadprofiler(self._ui, profiler)
             if proffn is None:
                 self._ui.warn(
                     _(b"unrecognized profiler '%s' - ignored\n") % profiler
                 )
                 profiler = b'stat'
 
         self._output = self._ui.config(b'profiling', b'output')
 
         try:
             if self._output == b'blackbox':
                 self._fp = util.stringio()
             elif self._output:
                 path = util.expandpath(self._output)
                 self._fp = open(path, b'wb')
             elif pycompat.iswindows:
                 # parse escape sequence by win32print()
                 class uifp:
                     def __init__(self, ui):
                         self._ui = ui
 
                     def write(self, data):
                         self._ui.write_err(data)
 
                     def flush(self):
                         self._ui.flush()
 
                 self._fpdoclose = False
                 self._fp = uifp(self._ui)
             else:
                 self._fpdoclose = False
                 self._fp = self._ui.ferr
                 # Ensure we've flushed fout before writing to ferr.
                 self._flushfp = self._ui.fout
 
             if proffn is not None:
                 pass
             elif profiler == b'ls':
                 proffn = lsprofile
             elif profiler == b'flame':
                 proffn = flameprofile
             elif profiler == b'py-spy':
                 proffn = pyspy_profile
             else:
                 proffn = statprofile
 
             self._profiler = proffn(self._ui, self._fp)
             self._profiler.__enter__()
         except:  # re-raises
             self._closefp()
             raise
 
     def __exit__(self, exception_type, exception_value, traceback):
         propagate = None
         if self._profiler is not None:
             self._uiflush()
             propagate = self._profiler.__exit__(
                 exception_type, exception_value, traceback
             )
             if self._output == b'blackbox':
                 val = b'Profile:\n%s' % self._fp.getvalue()
                 # ui.log treats the input as a format string,
                 # so we need to escape any % signs.
                 val = val.replace(b'%', b'%%')
                 self._ui.log(b'profile', val)
         self._closefp()
         return propagate
 
     def _closefp(self):
         if self._fpdoclose and self._fp is not None:
             self._fp.close()
 
     def _uiflush(self):
         if self._flushfp:
             self._flushfp.flush()

tests/test-profile.t

@@ -1,180 +1,194
 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 () {
   >   grep -E '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
+#if 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
+  $ stats_prof () {
+  >   hg --config profiling.type=stat --profile $@
+  > }
+
+  $ stats_prof \
+  >   --config profiling.format=text \
+  >   --config profiling.output=../profile.log \
+  >  serve -d \
+  >    -p $HGPORT \
+  >    --pid-file ../hg.pid \
+  >    -A ../access.log \
+  >    --errorlog ../error.log
   $ cat ../hg.pid >> $DAEMON_PIDS
   $ hg -q clone -U http://localhost:$HGPORT ../clone
+  $ cat ../error.log
 
 A single profile is logged because file logging doesn't append
-  $ grep CallCount ../profile.log | wc -l
+  $ grep 'Sample count:' ../profile.log | wc -l
+  \s*1 (re)
+  $ grep 'Total time:' ../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
   > 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
   > 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