'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