Branch.lock_read() rather expensive
John Arbash Meinel
john at arbash-meinel.com
Sat Oct 15 08:11:46 BST 2005
I'm working on updating the changeset plugin to work with the latest
bzr.dev code. In the process I came across something I didn't expect. I
have some code which uses common_ancestor and get_intervening_revisions
(both of which use revision_graph).
What I found was that quite a bit of time was taken up, just in
lock_read(). I figured part of this is because nothing takes out a read
lock beforehand, so it takes out 1 read lock for each revision it parses.
To prove this, I wrapped the common_ancestor() call with a lock/unlock
statement, and this is what I found
Without extra lock/unlock:
$ time bzr cset
real 0m5.201s
user 0m4.178s
sys 0m0.641s
$ bzr --profile cset
> Ordered by: cumulative time
> List reduced from 196 to 20 due to restriction <20>
>
> ncalls tottime percall cumtime percall filename:lineno(function)
> 1 0.000 0.000 5.329 5.329 commands.py:258(run_argv)
> 1 0.002 0.002 5.329 5.329 __init__.py:82(run)
> 1 0.000 0.000 5.323 5.323 gen_changeset.py:385(show_changeset)
> 1 0.000 0.000 5.232 5.232 gen_changeset.py:129(__init__)
> 1 0.006 0.006 5.231 5.231 gen_changeset.py:177(_get_revision_list)
> 3 0.059 0.020 5.159 1.720 revision.py:164(revision_graph)
> 6474 0.161 0.000 5.102 0.001 revision.py:251(get_revision)
> 6482 0.107 0.000 4.943 0.001 branch.py:776(get_revision)
> 6484 0.147 0.000 4.412 0.001 branch.py:755(get_revision_xml_file)
> 1 0.002 0.002 3.490 3.490 revision.py:230(common_ancestor)
> 1 0.000 0.000 3.428 3.428 revision.py:208(combined_graph)
> 6486 0.269 0.000 2.390 0.000 branch.py:351(lock_read)
> 12975 0.181 0.000 2.236 0.000 __init__.py:935(debug)
> 12975 0.230 0.000 1.938 0.000 __init__.py:1055(_log)
> 1 0.000 0.000 1.732 1.732 revision.py:259(get_intervening_revisions)
> 6486 0.191 0.000 1.434 0.000 branch.py:366(unlock)
> 12975 0.144 0.000 0.866 0.000 __init__.py:1048(makeRecord)
> 12975 0.360 0.000 0.721 0.000 __init__.py:206(__init__)
> 6486 0.216 0.000 0.626 0.000 local.py:214(lock_read)
> 6484 0.095 0.000 0.442 0.000 __init__.py:197(__getitem__)
>
>
With extra locking:
$ time bzr cset
real 0m4.086s
user 0m3.222s
sys 0m0.485s
> Ordered by: cumulative time
> List reduced from 196 to 20 due to restriction <20>
>
> ncalls tottime percall cumtime percall filename:lineno(function)
> 1 0.000 0.000 3.920 3.920 commands.py:258(run_argv)
> 1 0.009 0.009 3.920 3.920 __init__.py:82(run)
> 1 0.000 0.000 3.907 3.907 gen_changeset.py:391(show_changeset)
> 1 0.000 0.000 3.815 3.815 gen_changeset.py:129(__init__)
> 1 0.006 0.006 3.814 3.814 gen_changeset.py:177(_get_revision_list)
> 3 0.059 0.020 3.745 1.248 revision.py:164(revision_graph)
> 6474 0.162 0.000 3.687 0.001 revision.py:251(get_revision)
> 6482 0.104 0.000 3.527 0.001 branch.py:776(get_revision)
> 6484 0.140 0.000 3.004 0.000 branch.py:755(get_revision_xml_file)
> 1 0.003 0.003 2.557 2.557 revision.py:230(common_ancestor)
> 1 0.000 0.000 2.498 2.498 revision.py:208(combined_graph)
> 12979 0.177 0.000 2.195 0.000 __init__.py:935(debug)
> 12979 0.228 0.000 1.899 0.000 __init__.py:1055(_log)
> 1 0.000 0.000 1.249 1.249 revision.py:259(get_intervening_revisions)
> 6488 0.080 0.000 1.213 0.000 branch.py:351(lock_read)
> 6488 0.075 0.000 1.139 0.000 branch.py:366(unlock)
> 12979 0.130 0.000 0.838 0.000 __init__.py:1048(makeRecord)
> 12979 0.356 0.000 0.708 0.000 __init__.py:206(__init__)
> 6484 0.095 0.000 0.515 0.000 __init__.py:197(__getitem__)
> 6470 0.096 0.000 0.420 0.000 xml.py:63(read_revision)
>
As shown here, I saved 1.4 seconds (20%) just by adding the master lock.
But still the 6488 calls to lock_read and unlock accound for a large
portion of the time. Of the 4 total seconds, 1 second is spent in each,
for 50% of the time spent just counting up and down.
I was able to cut it down even more, just by commenting out the mutter()
statements:
$ time ./bzr cset
real 0m3.701s
user 0m3.259s
sys 0m0.442s
> Ordered by: cumulative time
> List reduced from 196 to 20 due to restriction <20>
>
> ncalls tottime percall cumtime percall filename:lineno(function)
> 1 0.000 0.000 1.706 1.706 commands.py:258(run_argv)
> 1 0.002 0.002 1.706 1.706 __init__.py:82(run)
> 1 0.000 0.000 1.683 1.683 gen_changeset.py:391(show_changeset)
> 1 0.000 0.000 1.593 1.593 gen_changeset.py:129(__init__)
> 1 0.006 0.006 1.593 1.593 gen_changeset.py:177(_get_revision_list)
> 3 0.050 0.017 1.524 0.508 revision.py:172(revision_graph)
> 6474 0.148 0.000 1.474 0.000 revision.py:259(get_revision)
> 6482 0.097 0.000 1.327 0.000 branch.py:776(get_revision)
> 1 0.002 0.002 1.078 1.078 revision.py:238(common_ancestor)
> 1 0.000 0.000 1.018 1.018 revision.py:216(combined_graph)
> 6484 0.135 0.000 0.684 0.000 branch.py:755(get_revision_xml_file)
> 6470 0.092 0.000 0.546 0.000 xml.py:63(read_revision)
> 1 0.000 0.000 0.507 0.507 revision.py:267(get_intervening_revisions)
> 6484 0.087 0.000 0.473 0.000 __init__.py:197(__getitem__)
> 6491 0.203 0.000 0.305 0.000 local.py:68(get)
> 6470 0.115 0.000 0.251 0.000 xml5.py:169(_unpack_revision)
> 6470 0.144 0.000 0.203 0.000 xml.py:73(_read_element)
> 6470 0.087 0.000 0.114 0.000 revision.py:44(__init__)
> 6500 0.069 0.000 0.101 0.000 local.py:51(abspath)
> 6484 0.052 0.000 0.081 0.000 text.py:55(_relpath)
>
Which is unexpected, because I don't have DEBUG logging setup, and
nothing seems to be written out to the ~/.bzr.log I thought that
logging.debug() was supposed to be cheap if that level was not enabled.
Though it also seems like this might be --profile's fault, because the
raw time with and without mutter isn't as different.
I'm guessing that the common_ancestor,revision_graph, and
get_intervening_revisions() are too expensive as it is, but I thought I
would point out a fairly major performance issue.
Notice that the raw read time for the xml is only about 0.5s even with
the extra muttering.
John
=:->
PS> This is all done on my fast machine (2.4GHz P4) not my slow Celeron
450MHz.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: signature.asc
Type: application/pgp-signature
Size: 256 bytes
Desc: OpenPGP digital signature
Url : https://lists.ubuntu.com/archives/bazaar/attachments/20051015/a639fa23/attachment.pgp
More information about the bazaar
mailing list