Slow clone due to missing/invalid entries in tags cache

[Pierre-Yves David]

On 4/20/21 5:41 PM, Kim Randell via Mercurial wrote:
> Hi,
> 
> We have encountered a problem with hg clone taking a long time when the source repository has missing/invalid entries in the tags cache (I don't know how this corruption occurred, unfortunately). This manifested as a long period after the copy stage where Mercurial was consuming a lot of CPU, but not reporting any output. Tested on hg 5.7.1 on both Windows and Ubuntu.
> 
> I diagnosed the issue by running:
> 
> hg clone -U --profile <source> <dest>
> 
> which produced the following output:
> 
> | 100.0% 1506.39s  hg:             <module>        line 59:   dispatch.run()
> | 100.0% 1506.39s  dispatch.py:    _rundispatch    line 289:  ret = _runcatch(req) or 0
> | 100.0% 1506.39s  dispatch.py:    _callcatch      line 475:  return scmutil.callcatch(ui...
> | 100.0% 1506.39s  scmutil.py:     callcatch       line 155:  return func()
> | 100.0% 1506.39s  dispatch.py:    _runcatchfunc   line 455:  return _dispatch(req)
> | 100.0% 1506.38s  commands.py:    clone           line 1938: depth=opts.get(b'depth') or...
> | 97.8% 1473.61s  hg.py:          clone            line 1048: destrepo.updatecaches(full=...
> | 97.8% 1473.61s  localrepo.py:   wrapper          line 200:  return orig(repo.unfiltered...
> | 97.8% 1473.38s  localrepo.py:   updatecaches     line 2712: tagsmod.fnoderevs(self.ui, ...
> | 97.8% 1473.30s  tags.py:        fnoderevs        line 94:   fnodes = _getfnodes(ui, rep...
> | 97.8% 1473.27s  tags.py:        _getfnodes       line 498:  fnode = fnodescache.getfnod...
> | 97.1% 1462.32s  tags.py:        getfnode         line 793:  fnode = mctx.readfast().get...
> | 96.0% 1446.90s  manifest.py:    readfast         line 2090: return self.read()
>   \ 81.8% 1231.67s  manifest.py:    read            line 2075: self._data = manifestdict(t...
>     | 81.5% 1227.69s  manifest.py:    __init__      line 474:  self._lm = _lazymanifest(data)
>   \  8.4% 126.57s  manifest.py:    read             line 2072: text = store.revision(self....
>     |  8.3% 124.85s  manifest.py:    revision       line 1804: return self._revlog.revisio...
>     |  8.2% 123.52s  revlog.py:      revision       line 1848: return self._revisiondata(n...
>     |  6.6% 100.14s  revlog.py:      _revisiondata  line 1874: rev, rawtext, validated = s...
>   \  5.7% 85.28s  manifest.py:    read              line 2074: store.fulltextcache[self._n...
> 
> This led me to look at the output of hg debugtagscache, which reported most entries as missing/invalid. Running hg debugupdatecaches successfully fixed these entries and subsequent clones were much faster.
> 
> Would it be possible to do one or more of the following?
> 
> 1. Warn about this problem on the client when hg clone is run.
> 2. Fix this problem on the server when hg clone is run. I was wondering if this changeset might do that: https://www.mercurial-scm.org/repo/hg/rev/9a31f65381ae (but I don't think it has arrived in a release yet - is 5.7.2 due soon? https://www.mercurial-scm.org/wiki/WhatsNew seems to be out of date)
> 3. Report problems with this or any other cache when hg verify is run.

Mercurial 5.7 has become more aggressive about warming this cache, which 
is why you had so many "missing" entry before. However the 1500s cache 
warming time is definitely more brutal than what I would expect.

How many revisions does your repository have ? Can you share the output 
of the following commands:

$ hg debugformat

$ hg debugrevlog --manifest

$ hg debugrevlog .hgtags

Thanks !

-- 
Pierre-Yves David