Patchwork D6522: tracing: add many more timedcm() calls throughout the codebase

login
register
mail settings
Submitter phabricator
Date June 12, 2019, 9:08 p.m.
Message ID <differential-rev-PHID-DREV-ednewua5fezxxuiqb3jd-req@mercurial-scm.org>
Download mbox | patch
Permalink /patch/40465/
State New
Headers show

Comments

phabricator - June 12, 2019, 9:08 p.m.
durin42 created this revision.
Herald added subscribers: mercurial-devel, mjpieters.
Herald added a reviewer: hg-reviewers.

REVISION SUMMARY
  I've been trying to understand where time goes in `hg status` and this helped
  me get a sense of things. I'm happy to try and split this up if it's too
  confusing, but I felt like it was fine as-is since all the changes are the
  same.

REPOSITORY
  rHG Mercurial

REVISION DETAIL
  https://phab.mercurial-scm.org/D6522

AFFECTED FILES
  mercurial/commands.py
  mercurial/context.py
  mercurial/dirstate.py
  mercurial/localrepo.py

CHANGE DETAILS




To: durin42, #hg-reviewers
Cc: mjpieters, mercurial-devel
phabricator - Sept. 3, 2019, 6 p.m.
martinvonz added a comment.


  > I've been trying to understand where time goes in hg status and this helped
  > me get a sense of things.
  
  Do you remember which of these were slow? You have instrumented the matcher creation quite a bit and I wouldn't have thought that would take very long (except when the matcher is very complex).

REPOSITORY
  rHG Mercurial

CHANGES SINCE LAST ACTION
  https://phab.mercurial-scm.org/D6522/new/

REVISION DETAIL
  https://phab.mercurial-scm.org/D6522

To: durin42, #hg-reviewers
Cc: martinvonz, mjpieters, mercurial-devel
phabricator - Sept. 3, 2019, 6:17 p.m.
martinvonz added a comment.


  `test-check-*.t` were unhappy with some of the changes in this stack (including in this patch). Can you fix those and update?

REPOSITORY
  rHG Mercurial

CHANGES SINCE LAST ACTION
  https://phab.mercurial-scm.org/D6522/new/

REVISION DETAIL
  https://phab.mercurial-scm.org/D6522

To: durin42, #hg-reviewers
Cc: martinvonz, mjpieters, mercurial-devel

Patch

diff --git a/mercurial/localrepo.py b/mercurial/localrepo.py
--- a/mercurial/localrepo.py
+++ b/mercurial/localrepo.py
@@ -1290,7 +1290,10 @@ 
         if repository.NARROW_REQUIREMENT not in self.requirements:
             return matchmod.always()
         include, exclude = self.narrowpats
-        return narrowspec.match(self.root, include=include, exclude=exclude)
+        with util.timedcm(
+            'construct narrowmatcher with %d includes and %d excludes',
+            len(include), len(exclude)):
+            return narrowspec.match(self.root, include=include, exclude=exclude)
 
     @storecache(narrowspec.FILENAME)
     def _narrowmatch(self):
@@ -1298,7 +1301,10 @@ 
             return matchmod.always()
         narrowspec.checkworkingcopynarrowspec(self)
         include, exclude = self.narrowpats
-        return narrowspec.match(self.root, include=include, exclude=exclude)
+        with util.timedcm(
+            'construct narrowmatcher with %d includes and %d excludes',
+            len(include), len(exclude)):
+            return narrowspec.match(self.root, include=include, exclude=exclude)
 
     def narrowmatch(self, match=None, includeexact=False):
         """matcher corresponding the the repo's narrowspec
@@ -1309,15 +1315,19 @@ 
         If `includeexact` is True, then any exact matches from `match` will
         be included even if they're outside the narrowspec.
         """
-        if match:
-            if includeexact and not self._narrowmatch.always():
-                # do not exclude explicitly-specified paths so that they can
-                # be warned later on
-                em = matchmod.exact(match.files())
-                nm = matchmod.unionmatcher([self._narrowmatch, em])
-                return matchmod.intersectmatchers(match, nm)
-            return matchmod.intersectmatchers(match, self._narrowmatch)
-        return self._narrowmatch
+        with util.timedcm('localrepo.narrowmatch'):
+            if match:
+                with util.timedcm('compose narrowmatcher with other matcher'):
+                    if includeexact and not self._narrowmatch.always():
+                        # do not exclude explicitly-specified paths so that they can
+                        # be warned later on
+                        em = matchmod.exact(match.files())
+                        nm = matchmod.unionmatcher([self._narrowmatch, em])
+                        with util.timedcm('actual intersection'):
+                            return matchmod.intersectmatchers(match, nm)
+                    with util.timedcm('actual intersection no includeexact'):
+                        return matchmod.intersectmatchers(match, self._narrowmatch)
+            return self._narrowmatch
 
     def setnarrowpats(self, newincludes, newexcludes):
         narrowspec.save(self, newincludes, newexcludes)
diff --git a/mercurial/dirstate.py b/mercurial/dirstate.py
--- a/mercurial/dirstate.py
+++ b/mercurial/dirstate.py
@@ -911,7 +911,9 @@ 
                 if nd != '':
                     skip = '.hg'
                 try:
-                    entries = listdir(join(nd), stat=True, skip=skip)
+                    with util.timedcm(b'listdir(%s, stat=True, skip=%s)',
+                                      nd, pycompat.bytestr(skip)):
+                        entries = listdir(join(nd), stat=True, skip=skip)
                 except OSError as inst:
                     if inst.errno in (errno.EACCES, errno.ENOENT):
                         match.bad(self.pathto(nd),
@@ -1058,55 +1060,56 @@ 
         # - match.traversedir does something, because match.traversedir should
         #   be called for every dir in the working dir
         full = listclean or match.traversedir is not None
-        for fn, st in self.walk(match, subrepos, listunknown, listignored,
-                                full=full).iteritems():
-            if not dcontains(fn):
-                if (listignored or mexact(fn)) and dirignore(fn):
-                    if listignored:
-                        iadd(fn)
-                else:
-                    uadd(fn)
-                continue
+        with util.timedcm('dirstate.status self.walk'):
+            for fn, st in self.walk(match, subrepos, listunknown, listignored,
+                                    full=full).iteritems():
+                if not dcontains(fn):
+                    if (listignored or mexact(fn)) and dirignore(fn):
+                        if listignored:
+                            iadd(fn)
+                    else:
+                        uadd(fn)
+                    continue
 
-            # This is equivalent to 'state, mode, size, time = dmap[fn]' but not
-            # written like that for performance reasons. dmap[fn] is not a
-            # Python tuple in compiled builds. The CPython UNPACK_SEQUENCE
-            # opcode has fast paths when the value to be unpacked is a tuple or
-            # a list, but falls back to creating a full-fledged iterator in
-            # general. That is much slower than simply accessing and storing the
-            # tuple members one by one.
-            t = dget(fn)
-            state = t[0]
-            mode = t[1]
-            size = t[2]
-            time = t[3]
+                # This is equivalent to 'state, mode, size, time = dmap[fn]' but not
+                # written like that for performance reasons. dmap[fn] is not a
+                # Python tuple in compiled builds. The CPython UNPACK_SEQUENCE
+                # opcode has fast paths when the value to be unpacked is a tuple or
+                # a list, but falls back to creating a full-fledged iterator in
+                # general. That is much slower than simply accessing and storing the
+                # tuple members one by one.
+                t = dget(fn)
+                state = t[0]
+                mode = t[1]
+                size = t[2]
+                time = t[3]
 
-            if not st and state in "nma":
-                dadd(fn)
-            elif state == 'n':
-                if (size >= 0 and
-                    ((size != st.st_size and size != st.st_size & _rangemask)
-                     or ((mode ^ st.st_mode) & 0o100 and checkexec))
-                    or size == -2 # other parent
-                    or fn in copymap):
+                if not st and state in "nma":
+                    dadd(fn)
+                elif state == 'n':
+                    if (size >= 0 and
+                        ((size != st.st_size and size != st.st_size & _rangemask)
+                         or ((mode ^ st.st_mode) & 0o100 and checkexec))
+                        or size == -2 # other parent
+                        or fn in copymap):
+                        madd(fn)
+                    elif (time != st[stat.ST_MTIME]
+                          and time != st[stat.ST_MTIME] & _rangemask):
+                        ladd(fn)
+                    elif st[stat.ST_MTIME] == lastnormaltime:
+                        # fn may have just been marked as normal and it may have
+                        # changed in the same second without changing its size.
+                        # This can happen if we quickly do multiple commits.
+                        # Force lookup, so we don't miss such a racy file change.
+                        ladd(fn)
+                    elif listclean:
+                        cadd(fn)
+                elif state == 'm':
                     madd(fn)
-                elif (time != st[stat.ST_MTIME]
-                      and time != st[stat.ST_MTIME] & _rangemask):
-                    ladd(fn)
-                elif st[stat.ST_MTIME] == lastnormaltime:
-                    # fn may have just been marked as normal and it may have
-                    # changed in the same second without changing its size.
-                    # This can happen if we quickly do multiple commits.
-                    # Force lookup, so we don't miss such a racy file change.
-                    ladd(fn)
-                elif listclean:
-                    cadd(fn)
-            elif state == 'm':
-                madd(fn)
-            elif state == 'a':
-                aadd(fn)
-            elif state == 'r':
-                radd(fn)
+                elif state == 'a':
+                    aadd(fn)
+                elif state == 'r':
+                    radd(fn)
 
         return (lookup, scmutil.status(modified, added, removed, deleted,
                                        unknown, ignored, clean))
diff --git a/mercurial/context.py b/mercurial/context.py
--- a/mercurial/context.py
+++ b/mercurial/context.py
@@ -367,11 +367,14 @@ 
             reversed = True
             ctx1, ctx2 = ctx2, ctx1
 
-        match = self._repo.narrowmatch(match)
-        match = ctx2._matchstatus(ctx1, match)
+        with util.timedcm('context.status narrowmatch'):
+            match = self._repo.narrowmatch(match)
+        with util.timedcm('context.status _matchstatus'):
+            match = ctx2._matchstatus(ctx1, match)
         r = scmutil.status([], [], [], [], [], [], [])
-        r = ctx2._buildstatus(ctx1, r, match, listignored, listclean,
-                              listunknown)
+        with util.timedcm('context.status _buildstatus'):
+            r = ctx2._buildstatus(ctx1, r, match, listignored, listclean,
+                                  listunknown)
 
         if reversed:
             # Reverse added and removed. Clear deleted, unknown and ignored as
@@ -1550,8 +1553,9 @@ 
         subrepos = []
         if '.hgsub' in self:
             subrepos = sorted(self.substate)
-        cmp, s = self._repo.dirstate.status(match, subrepos, ignored=ignored,
-                                            clean=clean, unknown=unknown)
+        with util.timedcm('_dirstatestatus dirstate.status'):
+            cmp, s = self._repo.dirstate.status(
+                match, subrepos, ignored=ignored, clean=clean, unknown=unknown)
 
         # check for any possibly clean files
         fixup = []
@@ -1639,7 +1643,8 @@ 
         building a new manifest if self (working directory) is not comparing
         against its parent (repo['.']).
         """
-        s = self._dirstatestatus(match, listignored, listclean, listunknown)
+        with util.timedcm('_buildstatus _dirstatestatus call'):
+            s = self._dirstatestatus(match, listignored, listclean, listunknown)
         # Filter out symlinks that, in the case of FAT32 and NTFS filesystems,
         # might have accidentally ended up with the entire contents of the file
         # they are supposed to be linking to.
diff --git a/mercurial/commands.py b/mercurial/commands.py
--- a/mercurial/commands.py
+++ b/mercurial/commands.py
@@ -5484,19 +5484,21 @@ 
         else:
             show = states[:5]
 
-    m = scmutil.match(ctx2, pats, opts)
-    if terse:
-        # we need to compute clean and unknown to terse
-        stat = repo.status(ctx1.node(), ctx2.node(), m,
-                           'ignored' in show or 'i' in terse,
-                            clean=True, unknown=True,
-                            listsubrepos=opts.get('subrepos'))
-
-        stat = cmdutil.tersedir(stat, terse)
-    else:
-        stat = repo.status(ctx1.node(), ctx2.node(), m,
-                           'ignored' in show, 'clean' in show,
-                           'unknown' in show, opts.get('subrepos'))
+    with util.timedcm('scmutil.match'):
+        m = scmutil.match(ctx2, pats, opts)
+    with util.timedcm('repo.status (terse=%r)', terse):
+        if terse:
+            # we need to compute clean and unknown to terse
+            stat = repo.status(ctx1.node(), ctx2.node(), m,
+                               'ignored' in show or 'i' in terse,
+                                clean=True, unknown=True,
+                                listsubrepos=opts.get('subrepos'))
+            with util.timedcm('cmdutil.terse'):
+                stat = cmdutil.tersedir(stat, terse)
+        else:
+            stat = repo.status(ctx1.node(), ctx2.node(), m,
+                               'ignored' in show, 'clean' in show,
+                               'unknown' in show, opts.get('subrepos'))
 
     changestates = zip(states, pycompat.iterbytestr('MAR!?IC'), stat)