statprof: separate functions and "line", assume 4 digit line numbers Previously, the profile output looked like this (I've removed many lines that are mostly inconsequential): ``` | 100.0% 0.02s hg: <module> line 43: dispatch.run() | 100.0% 0.02s dispatch.py: run line 115: status = dispatch(req) | 100.0% 0.02s dispatch.py: _runcatchfunc line 432: return _dispatch(req) \ 50.0% 0.01s dispatch.py: _dispatch line 1228: return runcommand( | 50.0% 0.01s dispatch.py: runcommand line 883: ret = _runcommand(ui, optio... | 50.0% 0.01s dispatch.py: _runcommand line 1240: return cmdfunc() | 50.0% 0.01s localrepo.py: __getitem__ line 1670: quick_access = self._quick_... | 50.0% 0.01s localrepo.py: _quick_access_changeidline 1650: return self._quick_access_c... | 50.0% 0.01s localrepo.py: __get__ line 179: return getattr(unfi, self.n... | 50.0% 0.01s util.py: __get__ line 1747: result = self.func(obj) | 50.0% 0.01s localrepo.py: _quick_access_changeid_wcline 1611: cl = self.unfiltered().chan... | 50.0% 0.01s localrepo.py: __get__ line 110: return super(_basefilecache... | 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m... | 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 783: | 50.0% 0.01s <frozen importlib._bootstrap>: _call_with_frames_removedline 219: | 50.0% 0.01s changelog.py: <module> line 376: class changelog(revlog.revl... | 50.0% 0.01s util.py: __getattribute__line 245: self.__spec__.loader.exec_m... | 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_moduleline 779: | 50.0% 0.01s <frozen importlib._bootstrap_external>: get_codeline 868: | 50.0% 0.01s <frozen importlib._bootstrap_external>: path_statsline 1012: | 50.0% 0.01s <frozen importlib._bootstrap_external>: _path_statline 87: ``` This has a few problems, though I'm only addressing some of them. 1. If the stuff before "line ###" is long, there's no separation between the function name and the "line" string. 2. If the stuff before "line ###" is really long, there's excessive separation between the "line" string and the line number. 3. We frequently have 4-digit line numbers, the code on the right wasn't dynamically indented and ended up quite messy looking. To solve these problems, I've added a ", " prefix before "line" iff it would otherwise not have any separation such as spaces. I've added a 'max' so that we never use a negative width (which is the cause of problem #2 above), and I've added a default assumption of 4 digit line numbers (but again using a 'max' so this shouldn't cause problems if we go beyond that. With these changes, it now looks like this: ``` | 100.0% 0.02s hg: <module> line 43: dispatch.run() | 100.0% 0.02s dispatch.py: run line 115: status = dispatch(req) | 100.0% 0.02s dispatch.py: _runcatchfunc line 432: return _dispatch(req) \ 50.0% 0.01s dispatch.py: _dispatch line 1228: return runcommand( | 50.0% 0.01s dispatch.py: runcommand line 883: ret = _runcommand(ui, optio... | 50.0% 0.01s dispatch.py: _runcommand line 1240: return cmdfunc() | 50.0% 0.01s localrepo.py: __getitem__ line 1670: quick_access = self._quick_... | 50.0% 0.01s localrepo.py: _quick_access_changeid, line 1650: return self._quick_access_c... | 50.0% 0.01s localrepo.py: __get__ line 179: return getattr(unfi, self.n... | 50.0% 0.01s util.py: __get__ line 1747: result = self.func(obj) | 50.0% 0.01s localrepo.py: _quick_access_changeid_wc, line 1611: cl = self.unfiltered().chan... | 50.0% 0.01s localrepo.py: __get__ line 110: return super(_basefilecache... | 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m... | 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_module, line 783: | 50.0% 0.01s <frozen importlib._bootstrap>: _call_with_frames_removed, line 219: | 50.0% 0.01s changelog.py: <module> line 376: class changelog(revlog.revl... | 50.0% 0.01s util.py: __getattribute__, line 245: self.__spec__.loader.exec_m... | 50.0% 0.01s <frozen importlib._bootstrap_external>: exec_module, line 779: | 50.0% 0.01s <frozen importlib._bootstrap_external>: get_code, line 868: | 50.0% 0.01s <frozen importlib._bootstrap_external>: path_stats, line 1012: | 50.0% 0.01s <frozen importlib._bootstrap_external>: _path_stat, line 87: ``` Differential Revision: https://phab.mercurial-scm.org/D9511

     1

test --time

     2

     3

  $ hg --time help -q help 2>&1 | grep time > /dev/null

     4

  $ hg init a

     5

  $ cd a

     6

     7

Function to check that statprof ran

     8

  $ statprofran () {

     9

  >   egrep 'Sample count:|No samples recorded' > /dev/null

    10

  > }

    11

    12

test --profile

    13

    14

  $ hg st --profile 2>&1 | statprofran

    15

    16

Abreviated version

    17

    18

  $ hg st --prof 2>&1 | statprofran

    19

    20

In alias

    21

    22

  $ hg --config "alias.profst=status --profile" profst 2>&1 | statprofran

    23

    24

#if lsprof

    25

    26

  $ prof='hg --config profiling.type=ls --profile'

    27

    28

  $ $prof st 2>../out

    29

  $ grep CallCount ../out > /dev/null || cat ../out

    30

    31

  $ $prof --config profiling.output=../out st

    32

  $ grep CallCount ../out > /dev/null || cat ../out

    33

    34

  $ $prof --config profiling.output=blackbox --config extensions.blackbox= st

    35

  $ grep CallCount .hg/blackbox.log > /dev/null || cat .hg/blackbox.log

    36

    37

  $ $prof --config profiling.format=text st 2>../out

    38

  $ grep CallCount ../out > /dev/null || cat ../out

    39

    40

  $ echo "[profiling]" >> $HGRCPATH

    41

  $ echo "format=kcachegrind" >> $HGRCPATH

    42

    43

  $ $prof st 2>../out

    44

  $ grep 'events: Ticks' ../out > /dev/null || cat ../out

    45

    46

  $ $prof --config profiling.output=../out st

    47

  $ grep 'events: Ticks' ../out > /dev/null || cat ../out

    48

    49

#endif

    50

    51

#if lsprof serve

    52

    53

Profiling of HTTP requests works

    54

    55

  $ $prof --config profiling.format=text --config profiling.output=../profile.log serve -d -p $HGPORT --pid-file ../hg.pid -A ../access.log

    56

  $ cat ../hg.pid >> $DAEMON_PIDS

    57

  $ hg -q clone -U http://localhost:$HGPORT ../clone

    58

    59

A single profile is logged because file logging doesn't append

    60

  $ grep CallCount ../profile.log | wc -l

    61

  \s*1 (re)

    62

    63

#endif

    64

    65

Install an extension that can sleep and guarantee a profiler has time to run

    66

    67

  $ cat >> sleepext_with_a_long_filename.py << EOF

    68

  > import time

    69

  > from mercurial import registrar

    70

  > cmdtable = {}

    71

  > command = registrar.command(cmdtable)

    72

  > @command(b'sleep', [], b'hg sleep')

    73

  > def sleep_for_at_least_one_stat_cycle(ui, *args, **kwargs):

    74

  >     time.sleep(0.1)

    75

  > EOF

    76

    77

  $ cat >> $HGRCPATH << EOF

    78

  > [extensions]

    79

  > sleep = `pwd`/sleepext_with_a_long_filename.py

    80

  > EOF

    81

    82

statistical profiler works

    83

    84

  $ hg --profile sleep 2>../out

    85

  $ cat ../out | statprofran

    86

    87

Various statprof formatters work

    88

    89

  $ hg --profile --config profiling.statformat=byline sleep 2>../out || cat ../out

    90

  $ grep -v _path_stat ../out | head -n 3

    91

    %   cumulative      self          

    92

   time    seconds   seconds  name    

    93

  * sleepext_with_a_long_filename.py:*:sleep_for_at_least_one_stat_cycle (glob)

    94

  $ cat ../out | statprofran

    95

    96

  $ hg --profile --config profiling.statformat=bymethod sleep 2>../out || cat ../out

    97

  $ head -n 1 ../out

    98

    %   cumulative      self          

    99

  $ cat ../out | statprofran

   100

   101

  $ hg --profile --config profiling.statformat=hotpath sleep 2>../out || cat ../out

   102

  $ cat ../out | statprofran

   103

  $ grep sleepext_with_a_long_filename.py ../out

   104

  .* [0-9.]+%  [0-9.]+s  sleepext_with_a_long_filename.py:\s*sleep_for_at_least_one_stat_cycle, line 7:    time\.sleep.* (re)

   105

   106

  $ hg --profile --config profiling.statformat=json sleep 2>../out || cat ../out

   107

  $ cat ../out

   108

  \[\[-?\d+.* (re)

   109

   110

statprof can be used as a standalone module

   111

   112

  $ "$PYTHON" -m mercurial.statprof hotpath

   113

  must specify --file to load

   114

  [1]

   115

   116

  $ cd ..

   117

   118

#if no-chg

   119

profiler extension could be loaded before other extensions

   120

   121

  $ cat > fooprof.py <<EOF

   122

  > from __future__ import absolute_import

   123

  > import contextlib

   124

  > import sys

   125

  > @contextlib.contextmanager

   126

  > def profile(ui, fp):

   127

  >     print('fooprof: start profile')

   128

  >     sys.stdout.flush()

   129

  >     yield

   130

  >     print('fooprof: end profile')

   131

  >     sys.stdout.flush()

   132

  > def extsetup(ui):

   133

  >     ui.write(b'fooprof: loaded\n')

   134

  > EOF

   135

   136

  $ cat > otherextension.py <<EOF

   137

  > from __future__ import absolute_import

   138

  > def extsetup(ui):

   139

  >     ui.write(b'otherextension: loaded\n')

   140

  > EOF

   141

   142

  $ hg init b

   143

  $ cd b

   144

  $ cat >> .hg/hgrc <<EOF

   145

  > [extensions]

   146

  > other = $TESTTMP/otherextension.py

   147

  > fooprof = $TESTTMP/fooprof.py

   148

  > EOF

   149

   150

  $ hg root

   151

  otherextension: loaded

   152

  fooprof: loaded

   153

  $TESTTMP/b

   154

  $ HGPROF=fooprof hg root --profile

   155

  fooprof: loaded

   156

  fooprof: start profile

   157

  otherextension: loaded

   158

  $TESTTMP/b

   159

  fooprof: end profile

   160

   161

  $ HGPROF=other hg root --profile 2>&1 | head -n 2

   162

  otherextension: loaded

   163

  unrecognized profiler 'other' - ignored

   164

   165

  $ HGPROF=unknown hg root --profile 2>&1 | head -n 1

   166

  unrecognized profiler 'unknown' - ignored

   167

   168

  $ cd ..

   169

#endif