'bzr branch -r -XXX foo bar' slow for long histories

John Arbash Meinel john at arbash-meinel.com
Tue Mar 18 20:36:44 GMT 2008


-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Robert Collins wrote:
...
>>
>> Well, introducing the CachingParentsProvider in the first place was an enormous
>> win for the places I was using it. So I'll have to agree.
>>
>> Looking at --lsprof, we spend say 12s in _lookup_by... and only about 6s in
>> _parse_lines. That was for something like 350k calls to _lookup_by and 6k calls
>> to _parse_lines.
> 
> So, rather than caching the parents twice (GraphIndex,
> CachingParentsProvider), lets just debug GraphIndex. 
> 
> 
> 350/6 ~= 59, so 12s:6s in 59:1, or lookup_by is about 6 times faster
> than the parsing itself, but used way more frequently.
> 
> -Rob


This is snippets from a "bzr log --limit 10" on the emacs repo with bzr.dev:

       1  53.169   0.000 bzrlib.commands:459(run_argv_aliases)

  350299  14.942   5.437 bzrlib.index:567(_lookup_keys_via_location)
 +350311   2.484   1.928 +bzrlib.index:384(_resolve_references)
 +700598   6.408   1.245 +bzrlib.index:949(_read_and_parse)

  350268  38.952   4.319 bzrlib.knit:1759(iter_parents)

  700598   6.408   1.245 bzrlib.index:949(_read_and_parse)
   +3370   3.607   0.036 +bzrlib.index:733(_parse_region)
   +3369   1.324   0.022 +bzrlib.transport:646(readv)

    3372   3.246   2.203 bzrlib.index:861(_parse_lines)

  700604  26.233   4.143 bzrlib.index:1059(iter_entries)

  350268  38.952   4.319 bzrlib.knit:1759(iter_parents)
 +350268  12.706   1.788 +bzrlib.knit:1599(_get_entries)

  175135  18.806   1.144 bzrlib.knit:1620(_present_keys)
 +350268  17.662   1.792 +bzrlib.knit:1599(_get_entries)

       1  18.224   0.000 bzrlib.repofmt.knitrepo:198(get_revision_graph)

   87568  23.835   0.515
bzrlib.repository:1615(iter_reverse_revision_history)
  +87567  23.182   0.355 +bzrlib.knit:1200(get_parents)
  +87567  22.826   0.897 +bzrlib.knit:1839(get_parents)
 +175134  21.929   2.176 +bzrlib.knit:1759(iter_parents)


None of this is going through the CachingParentsProvider because it is
all direct calls on Index.get_parents/iter_parents, etc.

However, if I switch it over to my get_revision_graph fix (now in
bzr.dev), along with my iter_reverse_history fix (which only switches
over to using Graph and sharing the CachingParentsProvider).


       1  30.4299   0.0000 bzrlib.commands:459(run_argv_aliases)

   87599   7.0573   1.2726 bzrlib.index:567(_lookup_keys_via_location)
  +87611   0.5920   0.4667 +bzrlib.index:384(_resolve_references)
 +175198   5.0010   0.3398 +bzrlib.index:949(_read_and_parse)

    3372   2.8953   1.9586 bzrlib.index:861(_parse_lines)

       1   2.9573   0.2612 bzrlib.repofmt.pack_repo:1933(get_revision_graph)

   87568  18.0165   0.5892
bzrlib.repository:1617(iter_reverse_revision_history)
  +87567  17.2992   1.4111 +bzrlib.graph:109(get_parent_map)

   87568  14.9596   1.9108 bzrlib.repofmt.pack_repo:1909(get_parent_map)
 +175135   9.7348   0.9728 +bzrlib.index:1059(iter_entries)
  +87568   2.7429   0.4941 +bzrlib.repofmt.pack_repo:1328(ensure_loaded)

   87571   2.7444   0.4942 bzrlib.repofmt.pack_repo:1328(ensure_loaded)
  +87571   1.7424   0.6484 +bzrlib.repofmt.pack_repo:1173(all_packs)

  175136  17.5470   1.6589 bzrlib.graph:109(get_parent_map)
  +87568  14.9596   1.9108 +bzrlib.repofmt.pack_repo:1909(get_parent_map)


So one point... why does ensure_loaded have to call all_packs
regardless. Would this be an appropriate fix:

=== modified file 'bzrlib/repofmt/pack_repo.py'
- --- bzrlib/repofmt/pack_repo.py 2008-03-14 10:55:37 +0000
+++ bzrlib/repofmt/pack_repo.py 2008-03-18 19:28:51 +0000
@@ -1337,8 +1337,8 @@
                 name = key[0]
                 self._names[name] = self._parse_index_sizes(value)
                 self._packs_at_load.add((key, value))
- -        # populate all the metadata.
- -        self.all_packs()
+            # populate all the metadata.
+            self.all_packs()

     def _parse_index_sizes(self, value):
         """Parse a string of index sizes."""


Some notes...

1) The changes end up accessing the parents list about 1/2 as much.
(CachingParentsProvider.get_parent_map() is called 175k times instead of
350k times from the original form.)

2) Caching them in a dict causes them to be 17.5 - 14.95 = 2.5

So to get 87.5k parents from disk costs us 15s, returning 87.5k from a
memory dict costs 2.5s, or about 6x faster.

3) Each call into _lookup_keys_via_location triggers 1 call into
_resolve_references and 2 calls into _read_and_parse.

Both of those calls happen even if we have the nodes in memory (I
think). It may be trivial and realize that there are no ranges.

We don't spend a lot of time in open() seek() and read(). Though I have
an interesting workaround that is able to save about 10% of the time by
caching the files in an LRUCache.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.6 (GNU/Linux)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org

iD8DBQFH4CfcJdeBCYSNAAMRApdWAJ9R5goOIMMn3xcPb2dGVS1C9XwfygCgiW0z
3XMlN76NIkg37qhs3bUCgP4=
=Qkdx
-----END PGP SIGNATURE-----



More information about the bazaar mailing list