bzr too slow

[Erik Bågfors]

2006/1/10, John Arbash Meinel <john at arbash-meinel.com>:
> Denys Duchier wrote:
> > John Arbash Meinel <john at arbash-meinel.com> writes:
> >
> >
> >>It could be a few things. At one point, the hash-cache wasn't properly
> >>flushing to disk, so it was having to read all files over again.
> >>I thought Aaron submitted a fix for this, and it had been pulled in.
> >
> >
> > but now the hashcache gets written on _every_ unlock operation, regardless of
> > whether the lock is actually being released. what you'd really want to do is
> > write it at the _last_ unlock.
> >
> > Cheers,
> >
> > --Denys
>
> Well, that could certainly be a problem. But it isn't entirely true. It
> only does so if the hash-cache says it is unclean. (If a file being read
> had a new stat result).
> Which means if you have never done a 'bzr status' before, it probably
> will write a few too many times.
> But after that, it will only happen when there have been actual changes
> detected. Which seems reasonable.

On a new branch.

: [bagfors at zyrgelkwyt]$ ; time bzr st

real    13m30.754s
user    9m43.387s
sys     0m8.334s

: [bagfors at zyrgelkwyt]$ ; time bzr st

real    0m5.468s
user    0m3.067s
sys     0m0.232s

That seams to be the case.  The first time it take ages, but the
second is OK (still slower than I'd like but....).....

Another thing that take a little too long is merges.

[ardome at ardweb3 ardome]$ time bzr merge
All changes applied successfully.

real    2m33.340s
user    2m25.480s
sys     0m2.240s


This was just a few commits, and no conflicts or anything. Not many
lines changed at all.


Here is the output from the profile on a new branch (this took a long
time, I went to lunch while waiting :) )


   Ordered by: cumulative time
   List reduced from 161 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.952    5.952 commands.py:211(run_argv)
        1    0.000    0.000    5.952    5.952 commands.py:542(ignore_pipe)
        1    0.007    0.007    5.952    5.952 builtins.py:122(run)
        1    0.001    0.001    5.446    5.446 status.py:27(show_status)
        1    0.285    0.285    3.727    3.727 delta.py:144(compare_trees)
     5418    0.094    0.000    2.830    0.001 branch.py:75(decorated)
    10826    0.169    0.000    2.623    0.000 inventory.py:568(_read_tree_state)
        4    0.202    0.050    1.276    0.319 xml5.py:114(_unpack_inventory)
        3    0.001    0.000    1.027    0.342 workingtree.py:181(__init__)
        3    0.000    0.000    1.023    0.341
workingtree.py:810(read_working_inventory)
        3    0.007    0.002    1.023    0.341 xml.py:53(read_inventory)
    24580    0.408    0.000    0.951    0.000 xml5.py:133(_unpack_entry)
     5417    0.142    0.000    0.927    0.000 workingtree.py:908(unlock)
        2    0.000    0.000    0.914    0.457 status.py:131(list_paths)
        1    0.038    0.038    0.795    0.795 workingtree.py:655(iter_conflicts)
     6146    0.037    0.000    0.738    0.000
workingtree.py:657(<generator expression>)
     5413    0.333    0.000    0.726    0.000 hashcache.py:194(write)
     5413    0.070    0.000    0.719    0.000 workingtree.py:321(get_file_sha1)
    29262    0.490    0.000    0.702    0.000 inventory.py:997(id2path)
     6146    0.035    0.000    0.701    0.000 workingtree.py:443(list_files)


Here is the output from profile on a branch that has run bzr status already.

         608928 function calls (581377 primitive calls) in 5.886 CPU seconds

   Ordered by: cumulative time
   List reduced from 156 to 20 due to restriction <20>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.000    0.000    5.886    5.886 commands.py:211(run_argv)
        1    0.000    0.000    5.886    5.886 commands.py:542(ignore_pipe)
        1    0.008    0.008    5.886    5.886 builtins.py:122(run)
        1    0.001    0.001    5.373    5.373 status.py:27(show_status)
        1    0.410    0.410    2.948    2.948 delta.py:144(compare_trees)
     5418    0.078    0.000    1.616    0.000 branch.py:75(decorated)
        3    0.004    0.001    1.603    0.534 workingtree.py:181(__init__)
    10826    0.347    0.000    1.565    0.000 inventory.py:568(_read_tree_state)
        4    0.317    0.079    1.223    0.306 xml5.py:114(_unpack_inventory)
        2    0.000    0.000    1.098    0.549 branch.py:1045(working_tree)
        2    0.000    0.000    1.001    0.500 status.py:131(list_paths)
        1    0.013    0.013    0.941    0.941 branch.py:1035(basis_tree)
        3    0.000    0.000    0.926    0.309
workingtree.py:810(read_working_inventory)
        3    0.008    0.003    0.926    0.309 xml.py:53(read_inventory)
    29262    0.668    0.000    0.875    0.000 inventory.py:997(id2path)
        1    0.057    0.057    0.865    0.865 workingtree.py:655(iter_conflicts)
    24580    0.301    0.000    0.798    0.000 xml5.py:133(_unpack_entry)
     6146    0.055    0.000    0.790    0.000
workingtree.py:657(<generator expression>)
     6146    0.035    0.000    0.735    0.000 workingtree.py:443(list_files)
32965/6146    0.349    0.000    0.699    0.000 workingtree.py:455(descend)


Hope it helps.

Regards,
Erik - suffering from the heat in Sydney....