This is an archive of the discontinued Mercurial Phabricator instance.

Differential D6522

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

Authored by durin42 on Jun 12 2019, 5:06 PM.

Details

Reviewers
None
Group Reviewers
hg-reviewers
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.

Diff Detail

Repository
rHG Mercurial
Lint
Lint Skipped
Unit
Unit Tests Skipped

Event Timeline

durin42 created this revision.Jun 12 2019, 5:06 PM
durin42 updated this revision to Diff 15601.Jun 19 2019, 4:25 PM
durin42 updated this revision to Diff 16102.Aug 1 2019, 2:35 PM
durin42 updated this revision to Diff 16300.Aug 23 2019, 5:05 PM
martinvonz added a subscriber: martinvonz.Sep 3 2019, 2:00 PM

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).

martinvonz added a comment.Sep 3 2019, 2:17 PM

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

durin42 added a comment.Sep 23 2019, 3:22 PM
In D6522#99543, @martinvonz wrote:

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).

I believe the narrowmatcher was taking noticeable time for some of my tests.

durin42 updated this revision to Diff 16594.Sep 23 2019, 3:25 PM
durin42 abandoned this revision.Oct 15 2019, 10:59 AM

Revision Contents
Changeset List

PathPackages
Mmercurial/commands.py (28 lines)
Mmercurial/context.py (19 lines)
Mmercurial/dirstate.py (101 lines)
Mmercurial/localrepo.py (33 lines)

Diff 16594

mercurial/commands.py

show += ui.quiet and (states[:4] + ['clean']) or states show += ui.quiet and (states[:4] + ['clean']) or states
if not show: if not show:
if ui.quiet: if ui.quiet:
show = states[:4] show = states[:4]
else: else:
show = states[:5] show = states[:5]
with util.timedcm('scmutil.match'):
m = scmutil.match(ctx2, pats, opts) m = scmutil.match(ctx2, pats, opts)
with util.timedcm('repo.status (terse=%r)', terse):
if terse: if terse:
# we need to compute clean and unknown to terse # we need to compute clean and unknown to terse
stat = repo.status(ctx1.node(), ctx2.node(), m, stat = repo.status(ctx1.node(), ctx2.node(), m,
'ignored' in show or 'i' in terse, 'ignored' in show or 'i' in terse,
clean=True, unknown=True, clean=True, unknown=True,
listsubrepos=opts.get('subrepos')) listsubrepos=opts.get('subrepos'))
with util.timedcm('cmdutil.terse'):
stat = cmdutil.tersedir(stat, terse) stat = cmdutil.tersedir(stat, terse)
else: else:
stat = repo.status(ctx1.node(), ctx2.node(), m, stat = repo.status(ctx1.node(), ctx2.node(), m,
'ignored' in show, 'clean' in show, 'ignored' in show, 'clean' in show,
'unknown' in show, opts.get('subrepos')) 'unknown' in show, opts.get('subrepos'))
changestates = zip(states, pycompat.iterbytestr('MAR!?IC'), stat) changestates = zip(states, pycompat.iterbytestr('MAR!?IC'), stat)
if (opts.get('all') or opts.get('copies') if (opts.get('all') or opts.get('copies')
or ui.configbool('ui', 'statuscopies')) and not opts.get('no_status'): or ui.configbool('ui', 'statuscopies')) and not opts.get('no_status'):
copy = copies.pathcopies(ctx1, ctx2, m) copy = copies.pathcopies(ctx1, ctx2, m)
ui.pager('status') ui.pager('status')

mercurial/context.py

# then we'd be done. But the special case of the above call means we # then we'd be done. But the special case of the above call means we
# just copy the manifest of the parent. # just copy the manifest of the parent.
reversed = False reversed = False
if (not isinstance(ctx1, changectx) if (not isinstance(ctx1, changectx)
and isinstance(ctx2, changectx)): and isinstance(ctx2, changectx)):
reversed = True reversed = True
ctx1, ctx2 = ctx2, ctx1 ctx1, ctx2 = ctx2, ctx1
with util.timedcm('context.status narrowmatch'):
match = self._repo.narrowmatch(match) match = self._repo.narrowmatch(match)
with util.timedcm('context.status _matchstatus'):
match = ctx2._matchstatus(ctx1, match) match = ctx2._matchstatus(ctx1, match)
r = scmutil.status([], [], [], [], [], [], []) r = scmutil.status([], [], [], [], [], [], [])
with util.timedcm('context.status _buildstatus'):
r = ctx2._buildstatus(ctx1, r, match, listignored, listclean, r = ctx2._buildstatus(ctx1, r, match, listignored, listclean,
listunknown) listunknown)
if reversed: if reversed:
# Reverse added and removed. Clear deleted, unknown and ignored as # Reverse added and removed. Clear deleted, unknown and ignored as
# these make no sense to reverse. # these make no sense to reverse.
r = scmutil.status(r.modified, r.removed, r.added, [], [], [], r = scmutil.status(r.modified, r.removed, r.added, [], [], [],
r.clean) r.clean)
if listsubrepos: if listsubrepos:
# Even if the wlock couldn't be grabbed, clear out the list. # Even if the wlock couldn't be grabbed, clear out the list.
self._repo.clearpostdsstatus() self._repo.clearpostdsstatus()
def _dirstatestatus(self, match, ignored=False, clean=False, unknown=False): def _dirstatestatus(self, match, ignored=False, clean=False, unknown=False):
'''Gets the status from the dirstate -- internal use only.''' '''Gets the status from the dirstate -- internal use only.'''
subrepos = [] subrepos = []
if '.hgsub' in self: if '.hgsub' in self:
subrepos = sorted(self.substate) subrepos = sorted(self.substate)
cmp, s = self._repo.dirstate.status(match, subrepos, ignored=ignored, with util.timedcm('_dirstatestatus dirstate.status'):
clean=clean, unknown=unknown) cmp, s = self._repo.dirstate.status(
match, subrepos, ignored=ignored, clean=clean, unknown=unknown)
# check for any possibly clean files # check for any possibly clean files
fixup = [] fixup = []
if cmp: if cmp:
modified2, deleted2, fixup = self._checklookup(cmp) modified2, deleted2, fixup = self._checklookup(cmp)
s.modified.extend(modified2) s.modified.extend(modified2)
s.deleted.extend(deleted2) s.deleted.extend(deleted2)
listunknown): listunknown):
"""build a status with respect to another context """build a status with respect to another context
This includes logic for maintaining the fast path of status when This includes logic for maintaining the fast path of status when
comparing the working directory against its parent, which is to skip comparing the working directory against its parent, which is to skip
building a new manifest if self (working directory) is not comparing building a new manifest if self (working directory) is not comparing
against its parent (repo['.']). against its parent (repo['.']).
""" """
with util.timedcm('_buildstatus _dirstatestatus call'):
s = self._dirstatestatus(match, listignored, listclean, listunknown) s = self._dirstatestatus(match, listignored, listclean, listunknown)
# Filter out symlinks that, in the case of FAT32 and NTFS filesystems, # Filter out symlinks that, in the case of FAT32 and NTFS filesystems,
# might have accidentally ended up with the entire contents of the file # might have accidentally ended up with the entire contents of the file
# they are supposed to be linking to. # they are supposed to be linking to.
s.modified[:] = self._filtersuspectsymlink(s.modified) s.modified[:] = self._filtersuspectsymlink(s.modified)
if other != self._repo['.']: if other != self._repo['.']:
s = super(workingctx, self)._buildstatus(other, s, match, s = super(workingctx, self)._buildstatus(other, s, match,
listignored, listclean, listignored, listclean,
listunknown) listunknown)

mercurial/dirstate.py

if not visitentries: if not visitentries:
continue continue
if visitentries == 'this' or visitentries == 'all': if visitentries == 'this' or visitentries == 'all':
visitentries = None visitentries = None
skip = None skip = None
if nd != '': if nd != '':
skip = '.hg' skip = '.hg'
try: try:
with util.timedcm(b'listdir(%s, stat=True, skip=%s)',
nd, pycompat.bytestr(skip)):
entries = listdir(join(nd), stat=True, skip=skip) entries = listdir(join(nd), stat=True, skip=skip)
except OSError as inst: except OSError as inst:
if inst.errno in (errno.EACCES, errno.ENOENT): if inst.errno in (errno.EACCES, errno.ENOENT):
match.bad(self.pathto(nd), match.bad(self.pathto(nd),
encoding.strtolocal(inst.strerror)) encoding.strtolocal(inst.strerror))
continue continue
raise raise
for f, kind, st in entries: for f, kind, st in entries:
# Some matchers may return files in the visitentries set, # Some matchers may return files in the visitentries set,
copymap = self._map.copymap copymap = self._map.copymap
lastnormaltime = self._lastnormaltime lastnormaltime = self._lastnormaltime
# We need to do full walks when either # We need to do full walks when either
# - we're listing all clean files, or # - we're listing all clean files, or
# - match.traversedir does something, because match.traversedir should # - match.traversedir does something, because match.traversedir should
# be called for every dir in the working dir # be called for every dir in the working dir
full = listclean or match.traversedir is not None full = listclean or match.traversedir is not None
with util.timedcm('dirstate.status self.walk'):
for fn, st in self.walk(match, subrepos, listunknown, listignored, for fn, st in self.walk(match, subrepos, listunknown, listignored,
full=full).iteritems(): full=full).iteritems():
if not dcontains(fn): if not dcontains(fn):
if (listignored or mexact(fn)) and dirignore(fn): if (listignored or mexact(fn)) and dirignore(fn):
if listignored: if listignored:
iadd(fn) iadd(fn)
else: else:
uadd(fn) uadd(fn)
continue continue
# This is equivalent to 'state, mode, size, time = dmap[fn]' but not # This is equivalent to 'state, mode, size, time = dmap[fn]'
# written like that for performance reasons. dmap[fn] is not a # but not written like that for performance
# Python tuple in compiled builds. The CPython UNPACK_SEQUENCE # reasons. dmap[fn] is not a Python tuple in compiled
# opcode has fast paths when the value to be unpacked is a tuple or # builds. The CPython UNPACK_SEQUENCE opcode has fast
# a list, but falls back to creating a full-fledged iterator in # paths when the value to be unpacked is a tuple or a
# general. That is much slower than simply accessing and storing the # list, but falls back to creating a full-fledged
# tuple members one by one. # iterator in general. That is much slower than simply
# accessing and storing the tuple members one by one.
t = dget(fn) t = dget(fn)
state = t[0] state = t[0]
mode = t[1] mode = t[1]
size = t[2] size = t[2]
time = t[3] time = t[3]
if not st and state in "nma": if not st and state in "nma":
dadd(fn) dadd(fn)
elif state == 'n': elif state == 'n':
if (size >= 0 and if (size >= 0 and
((size != st.st_size and size != st.st_size & _rangemask) ((size != st.st_size
and size != st.st_size & _rangemask)
or ((mode ^ st.st_mode) & 0o100 and checkexec)) or ((mode ^ st.st_mode) & 0o100 and checkexec))
or size == -2 # other parent or size == -2 # other parent
or fn in copymap): or fn in copymap):
madd(fn) madd(fn)
elif (time != st[stat.ST_MTIME] elif (time != st[stat.ST_MTIME]
and time != st[stat.ST_MTIME] & _rangemask): and time != st[stat.ST_MTIME] & _rangemask):
ladd(fn) ladd(fn)
elif st[stat.ST_MTIME] == lastnormaltime: elif st[stat.ST_MTIME] == lastnormaltime:
# fn may have just been marked as normal and it may have # fn may have just been marked as normal and
# changed in the same second without changing its size. # it may have changed in the same second
# This can happen if we quickly do multiple commits. # without changing its size. This can happen
# Force lookup, so we don't miss such a racy file change. # if we quickly do multiple commits. Force
# lookup, so we don't miss such a racy file
# change.
ladd(fn) ladd(fn)
elif listclean: elif listclean:
cadd(fn) cadd(fn)
elif state == 'm': elif state == 'm':
madd(fn) madd(fn)
elif state == 'a': elif state == 'a':
aadd(fn) aadd(fn)
elif state == 'r': elif state == 'r':
radd(fn) radd(fn)
return (lookup, scmutil.status(modified, added, removed, deleted, return (lookup, scmutil.status(modified, added, removed, deleted,
unknown, ignored, clean)) unknown, ignored, clean))
def matches(self, match): def matches(self, match):
''' '''
return files in the dirstate (in whatever state) filtered by match return files in the dirstate (in whatever state) filtered by match
''' '''

mercurial/localrepo.py

""" """
return narrowspec.load(self) return narrowspec.load(self)
@storecache(narrowspec.FILENAME) @storecache(narrowspec.FILENAME)
def _storenarrowmatch(self): def _storenarrowmatch(self):
if repository.NARROW_REQUIREMENT not in self.requirements: if repository.NARROW_REQUIREMENT not in self.requirements:
return matchmod.always() return matchmod.always()
include, exclude = self.narrowpats include, exclude = self.narrowpats
with util.timedcm(
'construct narrowmatcher with %d includes and %d excludes',
len(include), len(exclude)):
return narrowspec.match(self.root, include=include, exclude=exclude) return narrowspec.match(self.root, include=include, exclude=exclude)
@storecache(narrowspec.FILENAME) @storecache(narrowspec.FILENAME)
def _narrowmatch(self): def _narrowmatch(self):
if repository.NARROW_REQUIREMENT not in self.requirements: if repository.NARROW_REQUIREMENT not in self.requirements:
return matchmod.always() return matchmod.always()
narrowspec.checkworkingcopynarrowspec(self) narrowspec.checkworkingcopynarrowspec(self)
include, exclude = self.narrowpats include, exclude = self.narrowpats
with util.timedcm(
'construct narrowmatcher with %d includes and %d excludes',
len(include), len(exclude)):
return narrowspec.match(self.root, include=include, exclude=exclude) return narrowspec.match(self.root, include=include, exclude=exclude)
def narrowmatch(self, match=None, includeexact=False): def narrowmatch(self, match=None, includeexact=False):
"""matcher corresponding the the repo's narrowspec """matcher corresponding the the repo's narrowspec
If `match` is given, then that will be intersected with the narrow If `match` is given, then that will be intersected with the narrow
matcher. matcher.
If `includeexact` is True, then any exact matches from `match` will If `includeexact` is True, then any exact matches from `match` will
be included even if they're outside the narrowspec. be included even if they're outside the narrowspec.
""" """
with util.timedcm('localrepo.narrowmatch'):
if match: if match:
with util.timedcm('compose narrowmatcher with other matcher'):
if includeexact and not self._narrowmatch.always(): if includeexact and not self._narrowmatch.always():
# do not exclude explicitly-specified paths so that they can # do not exclude explicitly-specified paths so
# be warned later on # that they can be warned later on
em = matchmod.exact(match.files()) em = matchmod.exact(match.files())
nm = matchmod.unionmatcher([self._narrowmatch, em]) nm = matchmod.unionmatcher([self._narrowmatch, em])
with util.timedcm('actual intersection'):
return matchmod.intersectmatchers(match, nm) return matchmod.intersectmatchers(match, nm)
return matchmod.intersectmatchers(match, self._narrowmatch) with util.timedcm('actual intersection no includeexact'):
return matchmod.intersectmatchers(
match, self._narrowmatch)
return self._narrowmatch return self._narrowmatch
def setnarrowpats(self, newincludes, newexcludes): def setnarrowpats(self, newincludes, newexcludes):
narrowspec.save(self, newincludes, newexcludes) narrowspec.save(self, newincludes, newexcludes)
self.invalidate(clearfilecache=True) self.invalidate(clearfilecache=True)
def __getitem__(self, changeid): def __getitem__(self, changeid):
if changeid is None: if changeid is None:
return context.workingctx(self) return context.workingctx(self)