Analysis: Time spent in committing in a checkout

[Robert Collins]

On Fri, 2006-09-08 at 20:35 -0500, John Arbash Meinel wrote:
> I'm trying out using a checkout of a Launchpad branch. My ping time is
> approx 100ms, so 'bzr commit' is rather slow. I thought I would
> investigate what steps are involved, which might shed some light as to
> why that is. I did a --lsprof of a simple commit which only changes one
> file. And then tried to break down what was going on.
> 
> 
> To start with --lsprof says that the total time spent is 24s.
> 
> 
> From the top-down, we spend all that time in commit(), with this being
> the basic breakdown:
> 
>   8.65s bzrlib.repository:243(fetch)
>   6.77s bzrlib.commit:349(_check_bound_branch)
>   3.31s bzrlib.repository:2028(commit)
>   1.80s bzrlib.commit:391(_cleanup)
>   1.18s bzrlib.commit:444(_gather_parents)
>   0.69s bzrlib.branch:310(last_revision)
> 
> There is also:
>   1.00s bzrlib.decorators:48(write_locked)
> But unfortunately, our @needs_write_locked stuff makes it difficult to
> follow certain code paths.

FWIW, I find it easy enough to follow, because for 4 needs_write_lock
calls, if theres 4 children, there are 4 outer callers which match with
the children.


> I also wonder if we could get Paramiko to allow some of this stuff to be
> pipelined. Like when taking a lock, a whole lot of that could be a big
> pipeline that can be stalled at any time, but we don't really need to
> sync until we read the contents of the final lock directory. I realize
> opening a file in sftp is a required sync point, since you need the file
> handle before you can read or write anything.

It would be nice. In fact optimally it would look something like:
send mkdir branch-lock-temp
send create-file branch-lock-info
send mkdir repo-lock-temp
send create-file repo-lock-info
<-waiting->
either send branch-lock-info-content
 or send repo-lock-info-content
 followed by a file-close immediately
when we send the repo-lock-info file-close send rename of the lockdir
immediately.
when we send the branch-lock-info file-close if the repo lock has not
failed, send rename immediately.
<-waiting->
both complete: locked
branch completes, repo fails: no locks taken at the object level (undo
the branch lock)
repo completes, branch fails: repo is locked, branch fail, and will undo
the repo lock)

But while this is trivial to write in an event driven fashion, I dont
see how to write it cleanly in bzr today.

-Rob



> Now, to make a change to a single file, we actually update 8 revision
> control files. 4 index files, and 4 data files. (text.*, inventory.*,
> revisions.*, and signatures.*).
> 
> This is 8 append_bytes() calls, which takes 3.1s (less than the time it
> takes to lock and unlock the remote directory) Each one takes *almost*
> 400ms, which in round trips would be:
>   1) Open a file handle
>   2) Stat the remote file to determine its length
>   3) write out the contents and close
> 
> 
> Some other times are rather surprising considering the branch involved
> is very small, and doesn't have much history. I think some of this is
> --lsprof penalizing function calls, though.
> 
> We have to do 4 knit joins (as described above). The interesting stats are:
>      4  5.6062  0.1274   bzrlib.knit:1560(join)
> +21453  0.2398  0.1607   +bzrlib.knit:509(has_version)
>     +4  0.4071  0.1089   +bzrlib.versionedfile:307(get_graph)
>     +4  1.6765  0.0048   +bzrlib.tsort:27(topo_sort)
>   +152  0.0017  0.0011   +bzrlib.knit:872(get_parents_with_ghosts)
>     +8  0.0036  0.0002   +bzrlib.knit:1454(read_records_iter_raw)
>     +4  3.1369  0.0002   +bzrlib.knit:384(_add_raw_records)
> 
> 
> I already sent a patch for this. Since I think we are accessing too many
> inventory records, which causes topo_sort to take too long.
> 
> So, I didn't finish the analysis before I need to stop for the night.
> But I have the lsprof results in case anyone else is interested.
> 
> Another place that I think could benefit is in the _KnitIndex.__init__
> function. We do a fp = transport.get()
> to get the file contents, and then a fp.readline(), followed by
> fp.readlines().
> 
> I have the feeling that this is causing 2 round trips to the server.
> Looking at the paramiko code. readline() defaults to using a 8K buffer
> for the read requests.
> 
> Where this benefits us is if the index was corrupt, we wouldn't have to
> read the entire file. (Which would matter if we somehow got a 600MB bad
> index file because someone copied it into place.)
> 
> However, I think the common case is that index files are just fine, and
> it seems a shame to punish them so strongly. (Because of the potential
> worst-case behavior of a bad file put in place of a .kndx, I'm not 100%
> about this, but I'm 95%).
> 
> John
> =:->
> 
-- 
GPG key available at: <http://www.robertcollins.net/keys.txt>.
-------------- next part --------------
A non-text attachment was scrubbed...
Name: not available
Type: application/pgp-signature
Size: 191 bytes
Desc: This is a digitally signed message part
Url : https://lists.ubuntu.com/archives/bazaar/attachments/20060911/5a1eb708/attachment.pgp