"hg push" hangs for one minute (exactly one minute)

Thu Apr 28 12:50:07 UTC 2022

On 4/28/22 12:59 AM, Anton Shestakov wrote:
> There are also --debug and --profile, maybe they can help. Although
> some parts of the push process may not have debug logging, and
> profiling is for when you wish to delve into source code.
>
> I suspect there's something in the setup of the network or network
> file system, because 1 minute looks like a net IO timeout. But it
> could also be a timeout for waiting for a file lock, --profile should
> show it if that's the case.
>
Thanks for the options. Bingo.

Twice it does:
     ... pause for 30 seconds ...
     evoext-cache: error while saving new data: database is locked

And this, at the end of profile, looks telling
Note: the lines with the "_trysave" are displayed in red.

| 99.4% 60.29s  localrepo.py:   wrapper            line 237: return 
orig(repo.unfiltered...
  \ 49.6% 30.11s  stablerangecache.py: updatecaches line 532: 
super(stablerangerepo, self...
    | 49.6% 30.11s  localrepo.py:   wrapper         line 237: return 
orig(repo.unfiltered...
    | 49.6% 30.08s  obsdiscovery.py: updatecaches   line 645: 
self.obsstore.rangeobshashc...
    | 49.6% 30.08s  obsdiscovery.py: save           line 538: 
self._save(repo)
    | 49.6% 30.08s  obsdiscovery.py: _save          line 550: return 
self._trysave(repo)
    | 49.6% 30.07s  obsdiscovery.py: _trysave       line 607: 
self._ondiskcachekey = self...
  \ 49.5% 30.06s  stablerangecache.py: updatecaches line 531: 
self.stablerange.save(self)
    | 49.5% 30.06s  stablerangecache.py: save       line 406: 
self._save(repo)
    | 49.5% 30.06s  stablerangecache.py: _save      line 287: return 
self._trysave(repo)
    | 49.5% 30.06s  stablerangecache.py: _trysave   line 348: 
con.execute(_updatemeta, meta)

$ hg --profile --debug push
pushing to /z/repos/jvi-dev/jvi
query 1; heads
searching for changes
all remote heads known locally
listing keys for "phases"
listing keys for "namespaces"
listing keys for "namespaces"
checking for updated bookmarks
listing keys for "bookmarks"
no changes found
bundle2-output-bundle: "HG20", 3 parts total
bundle2-output-part: "replycaps" 224 bytes payload
bundle2-output-part: "check:phases" 1032 bytes payload
bundle2-output-part: "obsmarkers" streamed payload
bundle2-input-bundle: with-transaction
bundle2-input-part: "replycaps" supported
bundle2-input-part: total payload size 224
bundle2-input-part: "check:phases" supported
bundle2-input-part: total payload size 1032
bundle2-input-part: "obsmarkers" supported
bundle2-input-part: total payload size 96848
bundle2-input-bundle: 3 parts total
evoext-cache: error while saving new data: database is locked
evoext-cache: error while saving new data: database is locked
bundle2-output-bundle: "HG20", 1 parts total
bundle2-output-part: "reply:obsmarkers" (params: 0 advisory) empty payload
bundle2-input-bundle: no-transaction
bundle2-input-part: "reply:obsmarkers" (params: 0 advisory) supported
bundle2-input-bundle: 1 parts total
listing keys for "phases"
| 100.0% 60.67s  hg:             <module>          line 61:   dispatch.run()
| 100.0% 60.67s  dispatch.py:    run               line 144: status = 
dispatch(req)
| 100.0% 60.67s  dispatch.py:    dispatch          line 250: status = 
_rundispatch(req)
| 100.0% 60.67s  dispatch.py:    _rundispatch      line 294: ret = 
_runcatch(req) or 0
| 100.0% 60.67s  dispatch.py:    _runcatch         line 470: return 
_callcatch(ui, _runc...
| 100.0% 60.67s  dispatch.py:    _callcatch        line 480: return 
scmutil.callcatch(ui...
| 100.0% 60.67s  scmutil.py:     callcatch         line 153: return func()
| 100.0% 60.67s  dispatch.py:    _runcatchfunc     line 460: return 
_dispatch(req)
| 99.9% 60.61s  dispatch.py:    _dispatch          line 1273: return 
runcommand(
| 99.9% 60.61s  dispatch.py:    runcommand         line 918: ret = 
_runcommand(ui, optio...
| 99.9% 60.61s  dispatch.py:    _runcommand        line 1285: return 
cmdfunc()
| 99.9% 60.61s  dispatch.py:    <lambda>           line 1271: d = 
lambda: util.checksigna...
| 99.9% 60.61s  util.py:        check              line 1887: return 
func(*args, **kwargs)
| 99.9% 60.61s  util.py:        check              line 1887: return 
func(*args, **kwargs)
| 99.9% 60.61s  __init__.py:    pushoutgoingwrap   line 1353: return 
orig(ui, repo, *args...
| 99.9% 60.61s  util.py:        check              line 1887: return 
func(*args, **kwargs)
| 99.9% 60.61s  util.py:        check              line 1887: return 
func(*args, **kwargs)
| 99.9% 60.61s  flow.py:        wrappush           line 94: return 
orig(repo, remote, *...
| 99.9% 60.61s  util.py:        check              line 1887: return 
func(*args, **kwargs)
| 99.9% 60.58s  commands.py:    push               line 5787: pushop = 
exchange.push(
| 99.9% 60.58s  __init__.py:    push               line 578: return 
orig(repo, *args, **...
| 99.9% 60.58s  util.py:        inner              line 95: return 
f(*args, **kwargs)
| 99.9% 60.58s  gitrepo.py:     exchangepush       line 231: return orig(
| 99.7% 60.51s  exchange.py:    push               line 475: 
_pushbundle2(pushop)
| 99.7% 60.51s  exchange.py:    _pushbundle2       line 1152: reply = 
e.callcommand(
| 99.7% 60.51s  localrepo.py:   callcommand        line 284: result = 
fn(**pycompat.strk...
| 99.7% 60.50s  localrepo.py:   unbundle           line 410: ret = 
exchange.unbundle(sel...
| 99.5% 60.39s  exchange.py:    unbundle           line 2712: 
lockandtr[2].close()
| 99.5% 60.39s  transaction.py: _active            line 39: return 
func(self, *args, **...
| 99.4% 60.32s  transaction.py: close              line 629: 
self._postclosecallback[cat...
| 99.4% 60.30s  localrepo.py:   updater            line 2785: 
repo.updatecaches(tr)
| 99.4% 60.30s  localrepo.py:   wrapper            line 237: return 
orig(repo.unfiltered...
| 99.4% 60.30s  obscache.py:    updatecaches       line 484: 
super(obscacherepo, self).u...
| 99.4% 60.30s  localrepo.py:   wrapper            line 237: return 
orig(repo.unfiltered...
| 99.4% 60.30s  firstmergecache.py: updatecaches   line 64: 
super(firstmergecacherepo, ...
| 99.4% 60.30s  localrepo.py:   wrapper            line 237: return 
orig(repo.unfiltered...
| 99.4% 60.29s  depthcache.py:  updatecaches       line 91: 
super(depthcacherepo, self)...
| 99.4% 60.29s  localrepo.py:   wrapper            line 237: return 
orig(repo.unfiltered...
| 99.4% 60.29s  stablesort.py:  updatecaches       line 971: 
super(stablesortrepo, self)...
| 99.4% 60.29s  localrepo.py:   wrapper            line 237: return 
orig(repo.unfiltered...
  \ 49.6% 30.11s  stablerangecache.py: updatecaches line 532: 
super(stablerangerepo, self...
    | 49.6% 30.11s  localrepo.py:   wrapper         line 237: return 
orig(repo.unfiltered...
    | 49.6% 30.08s  obsdiscovery.py: updatecaches   line 645: 
self.obsstore.rangeobshashc...
    | 49.6% 30.08s  obsdiscovery.py: save           line 538: 
self._save(repo)
    | 49.6% 30.08s  obsdiscovery.py: _save          line 550: return 
self._trysave(repo)
    | 49.6% 30.07s  obsdiscovery.py: _trysave       line 607: 
self._ondiskcachekey = self...
  \ 49.5% 30.06s  stablerangecache.py: updatecaches line 531: 
self.stablerange.save(self)
    | 49.5% 30.06s  stablerangecache.py: save       line 406: 
self._save(repo)
    | 49.5% 30.06s  stablerangecache.py: _save      line 287: return 
self._trysave(repo)
    | 49.5% 30.06s  stablerangecache.py: _trysave   line 348: 
con.execute(_updatemeta, meta)
---
Sample count: 41622
Total time: 15.030000 seconds (60.670000 wall)