Note: There are a few cases of duplicates in user autocompletion which are being worked on.

Pulling with Mercurial 3.1 takes several minutes

RESOLVED FIXED

Status

Developer Services
Mercurial: hg.mozilla.org
RESOLVED FIXED
3 years ago
3 years ago

People

(Reporter: botond, Assigned: gps)

Tracking

Details

(URL)

(Reporter)

Description

3 years ago
I recently upgraded my Mercurial version from 2.7 to 3.1, and as a result the time required to complete a 'pull -u' operation from mozilla-central or mozilla-inbound has increased dramatically.

After displaying the "added X changesets with Y changes to Z lines" message, Mercurial hangs, using close to 100% CPU, for several minutes before completing the operation.

I reported this issue on IRC, and :gps asked that I enable the "blackbox" extension and post a log the next time this happens. It just happened, taking over 5 minutes, and here is the log:

2014/09/04 22:24:09 botond> pull -u
2014/09/04 22:24:16 botond> updated served branch cache in 0.1398 seconds
2014/09/04 22:24:16 botond> wrote served branch cache with 38 labels and 39 nodes
2014/09/04 22:30:35 botond> 132 incoming changes - new heads: b6f79b0ae7c3
2014/09/04 22:30:36 botond> resolved 39 tags cache entries from 1 manifests in 0.1906 seconds
2014/09/04 22:30:36 botond> writing tags cache file with 39 heads and 166 tags
2014/09/04 22:30:36 botond> updated None branch cache in 0.1387 seconds
2014/09/04 22:30:36 botond> wrote None branch cache with 38 labels and 85 nodes
2014/09/04 22:30:37 botond> pull -u exited 0 after 388.02 seconds

I've never had this problem with Mercurial 2.7.

This issue effectively blocks me from upgrading my Mercurial client, which in turn blocks me from using Mozilla hg extensions such as 'bzpush' or 'firefoxtree' that require a recent Mercurial client.

Please let me know if there is any other information I can provide to help resolve this, and/or if I should file a Mercurial bug.
(Assignee)

Comment 1

3 years ago
This smells like a problem I fixed in upstream:

http://www.selenic.com/pipermail/mercurial-devel/2014-July/060277.html

Please post the results of the following:

$ hg --time log -r 'roots(0::tip)' --template ' '
(Assignee)

Updated

3 years ago
Flags: needinfo?(botond)
(Reporter)

Comment 2

3 years ago
(In reply to Gregory Szorc [:gps] (away Sep 10 through 27) from comment #1)
> Please post the results of the following:
> 
> $ hg --time log -r 'roots(0::tip)' --template ' '

~/dev/mozilla/inbound > hg --time log -r 'roots(0::tip)' --template ' '

time: real 1.140 secs (user 1.080+0.000 sys 0.040+0.000)
Flags: needinfo?(botond)
(Assignee)

Comment 3

3 years ago
I can reproduce this locally. I'm tracking it down.
Assignee: nobody → gps
Status: NEW → ASSIGNED
(Assignee)

Comment 4

3 years ago
Effing lazy revsets. I thought I fixed this in time for 3.1 with http://selenic.com/repo/hg/rev/f486001f9d6f

---

$ HGRCPATH=/dev/null ~/src/hg/hg clone -U http://localhost:8000/ mc2 --time --traceback
requesting all changes
adding changesets
adding manifests
adding file changes
added 203669 changesets with 1150559 changes to 180816 files
^Ctransaction abort!
rollback completed
Traceback (most recent call last):
  File "/home/gps/src/hg/mercurial/dispatch.py", line 138, in _runcatch
    return _dispatch(req)
  File "/home/gps/src/hg/mercurial/dispatch.py", line 820, in _dispatch
    cmdpats, cmdoptions)
  File "/home/gps/src/hg/mercurial/dispatch.py", line 600, in runcommand
    ret = _runcommand(ui, options, cmd, d)
  File "/home/gps/src/hg/mercurial/dispatch.py", line 911, in _runcommand
    return checkargs()
  File "/home/gps/src/hg/mercurial/dispatch.py", line 882, in checkargs
    return cmdfunc()
  File "/home/gps/src/hg/mercurial/dispatch.py", line 817, in <lambda>
    d = lambda: util.checksignature(func)(ui, *args, **cmdoptions)
  File "/home/gps/src/hg/mercurial/util.py", line 550, in check
    return func(*args, **kwargs)
  File "/home/gps/src/hg/mercurial/commands.py", line 1331, in clone
    branch=opts.get('branch'))
  File "/home/gps/src/hg/mercurial/hg.py", line 402, in clone
    destpeer.local().clone(srcpeer, heads=revs, stream=stream)
  File "/home/gps/src/hg/mercurial/localrepo.py", line 1731, in clone
    return self.pull(remote, heads)
  File "/home/gps/src/hg/mercurial/localrepo.py", line 1579, in pull
    return exchange.pull (self, remote, heads, force)
  File "/home/gps/src/hg/mercurial/exchange.py", line 568, in pull
    _pullphase(pullop)
  File "/home/gps/src/hg/mercurial/exchange.py", line 665, in _pullphase
    _pullapplyphases(pullop, remotephases)
  File "/home/gps/src/hg/mercurial/exchange.py", line 683, in _pullapplyphases
    pullop.pulledsubset)
  File "/home/gps/src/hg/mercurial/phases.py", line 289, in advanceboundary
    phcache.advanceboundary(repo, targetphase, nodes)
  File "/home/gps/src/hg/mercurial/phases.py", line 225, in advanceboundary
    'roots((%ln::) - (%ln::%ln))', olds, olds, nodes))
  File "/home/gps/src/hg/mercurial/phases.py", line 224, in <genexpr>
    roots = set(ctx.node() for ctx in repo.set(
  File "/home/gps/src/hg/mercurial/localrepo.py", line 474, in set
    for r in self.revs(expr, *args):
  File "/home/gps/src/hg/mercurial/localrepo.py", line 467, in revs
    return m(self, revset.spanset(self))
  File "/home/gps/src/hg/mercurial/revset.py", line 2062, in mfunc
    return getset(repo, subset, tree)
  File "/home/gps/src/hg/mercurial/revset.py", line 237, in getset
    s = methods[x[0]](repo, subset, *x[1:])
  File "/home/gps/src/hg/mercurial/revset.py", line 304, in func
    return symbols[a[1]](repo, subset, b)
  File "/home/gps/src/hg/mercurial/revset.py", line 1475, in roots
    s = getset(repo, spanset(repo), x).set()
  File "/home/gps/src/hg/mercurial/revset.py", line 2383, in set
    return set([r for r in self])
  File "/home/gps/src/hg/mercurial/revset.py", line 2347, in __iter__
    if cond(x):
  File "/home/gps/src/hg/mercurial/revset.py", line 2418, in <lambda>
    return orderedlazyset(self, lambda r: r not in x,
  File "/home/gps/src/hg/mercurial/revset.py", line 2341, in __contains__
    c[x] = x in self._subset and self._condition(x)
KeyboardInterrupt
interrupted!
time: real 378.580 secs (user 311.470+0.000 sys 53.370+0.000)
(Assignee)

Comment 5

3 years ago
$ hg log -r 'roots((0::) - 0::tip)' -T ' ' --time

time: real 375.880 secs (user 344.720+0.000 sys 30.990+0.010)

2.7 does much better:

time: real 0.950 secs (user 0.820+0.000 sys 0.140+0.000)
(Assignee)

Comment 6

3 years ago
This is almost certainly http://bz.selenic.com/show_bug.cgi?id=4352.

I can't believe this one slipped past me.
(Assignee)

Comment 7

3 years ago
I submitted some patches to upstream and requested they be uplifted for 3.1.2.

http://www.selenic.com/pipermail/mercurial-devel/2014-September/061432.html

I don't think there is any value in keeping this bug opened. Please follow updates in Mercurial land.
Status: ASSIGNED → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → FIXED
(Reporter)

Comment 8

3 years ago
(In reply to Gregory Szorc [:gps] (away Sep 10 through 27) from comment #7)
> I submitted some patches to upstream and requested they be uplifted for
> 3.1.2.
> 
> http://www.selenic.com/pipermail/mercurial-devel/2014-September/061432.html

Thanks!
Product: Release Engineering → Developer Services
You need to log in before you can comment on or make changes to this bug.