view mercurial/lsprofcalltree.py @ 46018:8b0a3ff5ed12

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

"""
lsprofcalltree.py - lsprof output which is readable by kcachegrind

Authors:
    * David Allouche <david <at> allouche.net>
    * Jp Calderone & Itamar Shtull-Trauring
    * Johan Dahlin

This software may be used and distributed according to the terms
of the GNU General Public License, incorporated herein by reference.
"""

from __future__ import absolute_import

from . import pycompat


def label(code):
    if isinstance(code, str):
        # built-in functions ('~' sorts at the end)
        return b'~' + pycompat.sysbytes(code)
    else:
        return b'%s %s:%d' % (
            pycompat.sysbytes(code.co_name),
            pycompat.sysbytes(code.co_filename),
            code.co_firstlineno,
        )


class KCacheGrind(object):
    def __init__(self, profiler):
        self.data = profiler.getstats()
        self.out_file = None

    def output(self, out_file):
        self.out_file = out_file
        out_file.write(b'events: Ticks\n')
        self._print_summary()
        for entry in self.data:
            self._entry(entry)

    def _print_summary(self):
        max_cost = 0
        for entry in self.data:
            totaltime = int(entry.totaltime * 1000)
            max_cost = max(max_cost, totaltime)
        self.out_file.write(b'summary: %d\n' % max_cost)

    def _entry(self, entry):
        out_file = self.out_file

        code = entry.code
        if isinstance(code, str):
            out_file.write(b'fi=~\n')
        else:
            out_file.write(b'fi=%s\n' % pycompat.sysbytes(code.co_filename))

        out_file.write(b'fn=%s\n' % label(code))

        inlinetime = int(entry.inlinetime * 1000)
        if isinstance(code, str):
            out_file.write(b'0 %d\n' % inlinetime)
        else:
            out_file.write(b'%d %d\n' % (code.co_firstlineno, inlinetime))

        # recursive calls are counted in entry.calls
        if entry.calls:
            calls = entry.calls
        else:
            calls = []

        if isinstance(code, str):
            lineno = 0
        else:
            lineno = code.co_firstlineno

        for subentry in calls:
            self._subentry(lineno, subentry)

        out_file.write(b'\n')

    def _subentry(self, lineno, subentry):
        out_file = self.out_file
        code = subentry.code
        out_file.write(b'cfn=%s\n' % label(code))
        if isinstance(code, str):
            out_file.write(b'cfi=~\n')
            out_file.write(b'calls=%d 0\n' % subentry.callcount)
        else:
            out_file.write(b'cfi=%s\n' % pycompat.sysbytes(code.co_filename))
            out_file.write(
                b'calls=%d %d\n' % (subentry.callcount, code.co_firstlineno)
            )

        totaltime = int(subentry.totaltime * 1000)
        out_file.write(b'%d %d\n' % (lineno, totaltime))