poor progress indication during inter-format fetch

Bug #346540 reported by David Reitter
2
Affects Status Importance Assigned to Milestone
Bazaar
Confirmed
Medium
Unassigned

Bug Description

During a merge I am currently attempting, the progress bar is not showing any progress (even though the Python process is at near 100% CPU).

This is what I'm doing:

~/Projects/Bazaar-Playground/import-from-cvs/emacs$ bzr merge ../../emacs-dl/emacs/trunk
[| ] Transferring:Walking content. 96742/96968

I'm including partial output of fs_usage below, showing that it seems to be accessing the same file over and over again.

I then interrupted the merge; the stack trace is shown below.

18:54:52 read 0.000008 Python
18:54:52 close 0.000014 Python
18:54:55 open nd/emacs-dl/emacs/.bzr/repository/packs/322a537764ca187dbbc4fbdcfcd52772.pack 0.000034 Python
18:54:55 fstat 0.000005 Python
18:54:55 lseek 0.000002 Python
18:54:55 lseek 0.000001 Python
18:54:55 read 0.000016 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000008 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000008 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000005 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 close 0.000012 Python
18:54:55 open nd/emacs-dl/emacs/.bzr/repository/packs/322a537764ca187dbbc4fbdcfcd52772.pack 0.000047 Python
18:54:55 fstat 0.000006 Python
18:54:55 lseek 0.000002 Python
18:54:55 lseek 0.000001 Python
18:54:55 read 0.000022 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000008 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000008 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000008 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000009 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000009 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000008 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000007 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000006 Python
18:54:55 read 0.000008 Python
18:54:55 lseek 0.000002 Python
18:54:55 read 0.000007 Python

Sat 2009-03-21 18:46:52 -0400
0.039 bzr arguments: [u'merge', u'../../emacs-dl/emacs/trunk']
0.062 looking for plugins in /Users/dr/.bazaar/plugins
0.192 looking for plugins in /Library/Python/2.5/site-packages/bzrlib/plugins
0.192 Plugin name loom already loaded
0.192 Plugin name rebase already loaded
0.487 opening working tree '/Users/dr/Projects/Bazaar-Playground/import-from-cvs/emacs'
1.137 Using fetch logic to copy between KnitPackRepository('file:///Users/dr/Projects/Bazaar-Playground/emacs-dl/emacs/.bzr/repository/')(<RepositoryFormatKnitPack1>) and KnitPackRepository('file:///Users/dr/Projects/Bazaar-Playground/import-from-cvs/emacs/.bzr/repository/')(<RepositoryFormatKnitPack6RichRoot>)
1.138 fetch up to rev {cvs-1:gm-20090322005547-zhb9p6545uay2wm8}
718.235 Traceback (most recent call last):
  File "/Library/Python/2.5/site-packages/bzrlib/commands.py", line 716, in exception_to_return_code
    return the_callable(*args, **kwargs)
  File "/Library/Python/2.5/site-packages/bzrlib/commands.py", line 911, in run_bzr
    ret = run(*run_argv)
  File "/Library/Python/2.5/site-packages/bzrlib/commands.py", line 547, in run_argv_aliases
    return self.run(**all_cmd_args)
  File "/Library/Python/2.5/site-packages/bzrlib/plugins/qbzr/lib/commands.py", line 632, in run
    return bzrlib.builtins.cmd_merge.run(self, *args, **kw)
  File "/Library/Python/2.5/site-packages/bzrlib/builtins.py", line 3420, in run
    location, revision, remember, possible_transports, pb)
  File "/Library/Python/2.5/site-packages/bzrlib/builtins.py", line 3527, in _get_merger_from_branch
    other_revision_id, base_revision_id, other_branch, base_branch)
  File "/Library/Python/2.5/site-packages/bzrlib/merge.py", line 204, in from_revision_ids
    merger.set_other_revision(other, other_branch)
  File "/Library/Python/2.5/site-packages/bzrlib/merge.py", line 345, in set_other_revision
    self._maybe_fetch(other_branch, self.this_branch, self.other_rev_id)
  File "/Library/Python/2.5/site-packages/bzrlib/merge.py", line 362, in _maybe_fetch
    target.fetch(source, revision_id)
  File "/Library/Python/2.5/site-packages/bzrlib/decorators.py", line 192, in write_locked
    result = unbound(self, *args, **kwargs)
  File "/Library/Python/2.5/site-packages/bzrlib/branch.py", line 495, in fetch
    pb=nested_pb)
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 1133, in fetch
    find_ghosts=find_ghosts, fetch_spec=fetch_spec)
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 2640, in fetch
    pb=pb, find_ghosts=find_ghosts)
  File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 103, in __init__
    self.__fetch()
  File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 130, in __fetch
    self._fetch_everything_for_search(search, pp)
  File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 156, in _fetch_everything_for_search
    stream, from_format, [])
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 3618, in insert_stream
    return self._locked_insert_stream(stream, src_format)
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 3628, in _locked_insert_stream
    for substream_type, substream in stream:
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 3783, in get_stream
    for _ in self._generate_root_texts(revs):
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 3752, in _generate_root_texts
    self.from_repository).generate_root_texts(revs)
  File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 258, in generate_root_texts
    revs, parent_map, graph)
  File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 232, in _find_root_ids
    for tree in self.iter_rev_trees(revs):
  File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 223, in iter_rev_trees
    for tree in self.source.revision_trees(revs[:100]):
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 1865, in revision_trees
    for inv in inventories:
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 1730, in _iter_inventories
    yield self.deserialise_inventory(revision_id, text)
  File "/Library/Python/2.5/site-packages/bzrlib/repository.py", line 1752, in deserialise_inventory
    entry_cache=self._inventory_entry_cache)
  File "/Library/Python/2.5/site-packages/bzrlib/xml_serializer.py", line 80, in read_inventory_from_string
    entry_cache=entry_cache)
  File "/Library/Python/2.5/site-packages/bzrlib/xml5.py", line 57, in _unpack_inventory
    ie = unpack_entry(e, entry_cache=entry_cache)
  File "/Library/Python/2.5/site-packages/bzrlib/xml8.py", line 434, in _unpack_entry
    return cached_ie.copy()
  File "/Library/Python/2.5/site-packages/bzrlib/inventory.py", line 502, in copy
    other = InventoryFile(self.file_id, self.name, self.parent_id)
  File "/Library/Python/2.5/site-packages/bzrlib/inventory.py", line 538, in __init__
    super(InventoryFile, self).__init__(file_id, name, parent_id)
KeyboardInterrupt

718.244 return code 3

Revision history for this message
David Reitter (david-reitter) wrote :

I'd like to add another, probably related case.
I decided to merge just the latest revisions, that is, just 22 revisions:

~/Projects/Bazaar-Playground/import-from-cvs/emacs$ bzr merge ../../emacs-dl/emacs/trunk -r 96946.. -v
[\ ] Transferring:Walking content. 96968/96968

When it appears to be done "walking content", it basically appears to freeze. Again, it's working hard, but neither the progress bar nor anything else is changing.

The indication of completed revisions is misleading - obviously there is much more to "walking the content", because otherwise it'd be done by now.

(I also don't understand why merging 22 revisions is taking forever.)

Revision history for this message
Robert Collins (lifeless) wrote : Re: [Bug 346540] [NEW] merge: progress bar doesn't change for a long time

On Sat, 2009-03-21 at 22:59 +0000, davidswelt wrote:
> Public bug reported:
>
> During a merge I am currently attempting, the progress bar is not
> showing any progress (even though the Python process is at near 100%
> CPU).
>
> This is what I'm doing:
>
> ~/Projects/Bazaar-Playground/import-from-cvs/emacs$ bzr merge ../../emacs-dl/emacs/trunk
> [| ] Transferring:Walking content. 96742/96968

> File "/Library/Python/2.5/site-packages/bzrlib/fetch.py", line 258, in generate_root_texts
> revs, parent_map, graph)

^ this indicates the the branch you are merging from is in a
non-rich-root format, but the one you are in, is in a rich root format,
so its actually doing on the fly data conversion, which is moderately
slow.

-Rob

Revision history for this message
Robert Collins (lifeless) wrote : Re: [Bug 346540] Re: merge: progress bar doesn't change for a long time

On Sat, 2009-03-21 at 23:17 +0000, davidswelt wrote:
> I'd like to add another, probably related case.
> I decided to merge just the latest revisions, that is, just 22 revisions:
>
> ~/Projects/Bazaar-Playground/import-from-cvs/emacs$ bzr merge ../../emacs-dl/emacs/trunk -r 96946.. -v
> [\ ] Transferring:Walking content. 96968/96968
>
> When it appears to be done "walking content", it basically appears to
> freeze. Again, it's working hard, but neither the progress bar nor
> anything else is changing.
>
> The indication of completed revisions is misleading - obviously there is
> much more to "walking the content", because otherwise it'd be done by
> now.
>
> (I also don't understand why merging 22 revisions is taking forever.)

It's converting 97K revisions to the same format from the look of it - I
suspect you have parallel imports with different history or some such
thing.

This is something probably much better discussed on e.g. #bzr, or the
<email address hidden> mailing list - I suspect you have confused
set of branches rather than merge doing the wrong thing.

Certainly our progress bar in 1.13 is less than desirable during the
pulling-of-data phase, this is getting fixed during 1.14, and was only
made the way it was in 1.13 to get a many-times improvement in push and
pull times (ranging from 2:1 to 1000:1 depending on the scenario
involved).

-Rob

Revision history for this message
David Reitter (david-reitter) wrote : Re: [Bug 346540] [NEW] merge: progress bar doesn't change for a long time

On Mar 21, 2009, at 7:17 PM, Robert Collins wrote:
> ^ this indicates the the branch you are merging from is in a
> non-rich-root format, but the one you are in, is in a rich root
> format,
> so its actually doing on the fly data conversion, which is moderately
> slow.

OK, makes sense, but the progress bar is still broken.

Based on your advice, I'm converting the repository, but as it turns
out, it gets stuck again at some revision:

  bzr upgrade --1.9-rich-root
starting upgrade of file:///Users/dr/Projects/Bazaar-Playground/emacs-dl/emacs/
making backup of file:///Users/dr/Projects/Bazaar-Playground/emacs-dl/emacs/.bzr
   to file:///Users/dr/Projects/Bazaar-Playground/emacs-dl/emacs/backup.bzr
starting repository conversion
[##############/ ] Copying content into
repository.:Transferring:Walking content. 96745/96968

It's been sitting there more minutes now...

That revision isn't particularly spectacular...

bzr log -r 96746
------------------------------------------------------------
revno: 96746
committer: lektu
branch nick: HEAD
timestamp: Mon 2009-03-09 14:36:54 +0000
message:
   Fix typos in comment.

So, I don't know what else to try. Perhaps I'll branch the parent
repository again, (or I'll send our migration back to sleep for
another month.)

Martin Pool (mbp)
summary: - merge: progress bar doesn't change for a long time
+ poor progress indication during inter-format fetch
tags: added: progress
Changed in bzr:
importance: Undecided → Medium
status: New → Confirmed
Martin Pool (mbp)
tags: added: fetch
Jelmer Vernooij (jelmer)
tags: added: check-for-breezy
To post a comment you must log in.
This report contains Public information  
Everyone can see this information.

Other bug subscribers

Remote bug watches

Bug watches keep track of this bug in other bug trackers.