bzr log -v is slow

Hi Pelle,

Could you try running 'bzr pack' in the branch you were trying this in and seeing if that makes any difference?

Thanks,

Dan

Hi,

there is no perceivable change after running bzr pack.
--
Pelle Johansson

9 jul 2008 kl. 13.42 skrev Daniel Watkins:

> Hi Pelle,
>
> Could you try running 'bzr pack' in the branch you were trying this in
> and seeing if that makes any difference?
>
>
> Thanks,
>
> Dan
>
> --
> bzr log -v takes forever
> https://bugs.launchpad.net/bugs/246891
> You received this bug notification because you are a direct subscriber
> of the bug.
>
> Status in Bazaar Version Control System: New
>
> Bug description:
> I've used tailor to convert the netbsd src module to a bazaar
> branch, but only the last 1000 revisions. When I run bzr log -v on
> this branch, it hangs perceivably forever. If I wait long enough
> though, the first few entries are displayed (and then the command
> continues to hang).
> bzr log without -v works fine.
>
> I could upload the .bzr dir if requested, but it's 481 MB as a tgz,
> so it's quite big. I could also help if given some directions (I
> know next to nothing about python, much less bazaar internals).
>
> $ bzr --version
> Bazaar (bzr) 1.5
> Python interpreter: /opt/local/bin/python2.5 2.5.2
> Python standard library: /opt/local/lib/python2.5
> bzrlib: /opt/local/lib/python2.5/site-packages/bzrlib
>
> Installed via macports on my MacBook Pro running Leopard.
>
> Backtrace from sending SIGQUIT (ie not a very scientific way of
> finding the spot):
> (Pdb) bt
> /opt/local/bin/bzr(102)<module>()
> -> exit_val = bzrlib.commands.main(sys.argv)
> /opt/local/lib/python2.5/site-packages/bzrlib/commands.py(837)main()
> -> ret = run_bzr_catch_errors(argv)
> /opt/local/lib/python2.5/site-packages/bzrlib/
> commands.py(846)run_bzr_catch_errors()
> -> return run_bzr(argv)
> /opt/local/lib/python2.5/site-packages/bzrlib/
> commands.py(797)run_bzr()
> -> ret = run(*run_argv)
> /opt/local/lib/python2.5/site-packages/bzrlib/
> commands.py(499)run_argv_aliases()
> -> return self.run(**all_cmd_args)
> /opt/local/lib/python2.5/site-packages/bzrlib/
> commands.py(807)ignore_pipe()
> -> result = func(*args, **kwargs)
> /opt/local/lib/python2.5/site-packages/bzrlib/builtins.py(1774)run()
> -> limit=limit)
> /opt/local/lib/python2.5/site-packages/bzrlib/log.py(185)show_log()
> -> start_revision, end_revision, search, limit)
> /opt/local/lib/python2.5/site-packages/bzrlib/log.py(232)_show_log()
> -> branch.repository, view_revisions, generate_delta):
> /opt/local/lib/python2.5/site-packages/bzrlib/
> log.py(315)_iter_revisions()
> -> deltas))
> /opt/local/lib/python2.5/site-packages/bzrlib/
> repository.py(1133)get_deltas_for_revisions()
> -> yield trees[revision.revision_id].changes_from(old_tree)
> /opt/local/lib/python2.5/site-packages/bzrlib/
> tree.py(93)changes_from()
> -> want_unversioned=want_unversioned,
> /opt/local/lib/python2.5/site-packages/bzrlib/
> decorators.py(127)read_locked()
> -> return unbound(self, *args, **kwargs)
> /opt/local/lib/python2.5/site-packages/bzrlib/tree.py(734)compare()
> -> want_unversioned=want_unversioned)
> /opt/local/lib/python2.5/site-packages/bzrlib/
> delta.py(217)_compare_trees()
> -> want_unversioned=want_unversioned):
> /opt/local/lib/python2.5/site-packages...

Hrm, sorry, I does seem to be a little bit faster, I get about 10 log messages about every 4 minutes now. Still unusably slow though.

It seems tailor was using a separately installed bazaar 1.2 due to importing the python lib directly. I am however using 1.5 for testing, and bzr upgrade did not want to do anything.

I've tried upgrading using these formats:
development (though I was not using bzr.dev)
rich-root (took a whooping 11 hours to convert to)
rich-root-pack
back to default (from development)

They all have pretty much the same performance, about 10 log messages every 4th minute.

Does anyone have a clue why it is so slow, is it simply the large number of files?

Pelle Johansson wrote:
> It seems tailor was using a separately installed bazaar 1.2 due to
> importing the python lib directly. I am however using 1.5 for testing,
> and bzr upgrade did not want to do anything.
>
> I've tried upgrading using these formats:
> development (though I was not using bzr.dev)
> rich-root (took a whooping 11 hours to convert to)
> rich-root-pack
> back to default (from development)
>
> They all have pretty much the same performance, about 10 log messages
> every 4th minute.
>
> Does anyone have a clue why it is so slow, is it simply the large number
> of files?
>

Pelle,

Could you try collecting some profiling information for us on this?
Here's the command ...

  bzr --lsprof-file callgrind.out.logv log -v

You don't need to let it finish - you can Ctrl-C after a few minutes
and the profiling file should still be generated.

If you're running on Linux and are curious, you can view the output
file (callgrind.out.logv) using kcachegrind. Otherwise, please attach it
to the bug and we'll take a look.

Thanks,
Ian C.

Finally attached, from an 11 minute run. I forgot to upload it before
my 3 week vacation trip.
--
Pelle Johansson

16 jul 2008 kl. 13.05 skrev Ian Clatworthy:

>
> Pelle,
>
> Could you try collecting some profiling information for us on this?
> Here's the command ...
>
> bzr --lsprof-file callgrind.out.logv log -v

Known issue - our log -v requires work proportional to the number of files in the tree, per revision, to display. Its being worked on but its a structural problem not a command layer problem.

Note that this bug increases the severity of bug #97715 ("bzr log DIR should show changes under DIR"). Ordinarily 'bzr log -v' would be a good workaround for that, but with 'bzr log -v' essentially unuseable on large / deep-history projects [1], there is no workaround for bug #97715.

[1] About 36 hours (by extrapolation -- it hasn't finished yet) for the 94342-revision emacs-merges-ce-master repository, branched (in 1.9 format) from bzr://bzr.notengoamigos.org/emacs-merges-ce/master/, on a machine with dual core 2.2Ghz AMD Opterons w/ 1024 KB cache each, 4GB ram, 2GB swap, reasonably fast SCSI disks, and not a huge amount of other load.

I just did some timings with the development6-rich-root repository format available since 1.14. It helps quite a bit relative to the default pack-0.92 repository format. Timings are with the lp:bzr repository with 4324 revisions in it:

log -v, pack-0.92: 2m34s
log -v, development6-rich-root: 0m46s

To get a development6-rich-root repository I did "bzr upgrade --development6-rich-root" from inside my branch of lp:bzr. Performing the format upgrade took something like four hours, so doing that on a bigger repository like the emacs one can take quite some time.

I would also recommend doing 'bzr pack' after the 'bzr upgrade'. I don't know if it would benefit 'log' very much, but the new format does take advantage of 'bzr pack' to improve its storage efficiency.

Packing takes one hour, and gets log -v time down from 46s to 38s:

$ time ./bzr log -v >& /dev/null
real 0m38.243s
user 0m36.830s
sys 0m1.072s

I'm attaching a profile of doing log -v in this scenario, can be opened using kcachegrind. Running with profiling enabled takes about 73s.

Here's a shell script to set everything up, it runs in about 6h on my system:

#!/bin/bash
set -e
set -x
date
bzr branch lp:bzr bzr-log-v-bench >& /dev/null
cd bzr-log-v-bench
date
time ./bzr log -v >& /dev/null
date
time ./bzr upgrade --development6-rich-root >& /dev/null
date
time ./bzr log -v >& /dev/null
date
time ./bzr pack >& /dev/null
date
time ./bzr log -v >& /dev/null
date
time ./bzr --lsprof-file ./callgrind.out log -v >& /dev/null
date

This is fixed by using the 2a repository format, the default in Bazaar 2.0.x.