Loop of wt.commit() slows down

[John A Meinel]

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

I was trying to investigate bug #494406, so I write a quick script that did:

wt = workingtree.WorkingTree.open('.')
wt.lock_write()
for i in xrange(1000):
  tstart = time.clock()
  x = wt.commit('test')
  tend = time.clock()
  pb.update('commit [last:%.3fs]' % (tend - tstart,), i, 1000)

When monitoring the commit times, the first few are quite fast, but
eventually slow down until it reaches a 'steady state':

commit [last:0.654s]
commit [last:0.739s]
commit [last:0.857s]
commit [last:1.030s]
commit [last:1.112s]
commit [last:1.270s]
commit [last:1.334s]
commit [last:1.524s]
commit [last:1.741s]
commit [last:1.974s]
commit [last:1.699s]
commit [last:1.775s]
commit [last:2.017s]
commit [last:2.551s]
commit [last:3.414s]
commit [last:3.502s]
commit [last:3.528s]
commit [last:3.691s]
commit [last:3.711s]
commit [last:3.918s]
commit [last:3.189s]

So the first commits take less than 1s, but then we 'settle down' to
around 3-4s per commit.

This is a checkout of a 'bzr://' connection to localhost. Both sides are
running bzr.dev 4889.

What is even stranger is that if I interrupt the loop. Unlock the
working tree, open a new wt, break lock, and start again, I get the same
results. The first few commits are quite fast, then it slows down
considerably.

Actually, it goes even further, if I just call 'wt.unlock();
wt.lock_write()' then the next commit is quite fast. (back to 0.6s).
Such that holding the write lock ends up being slower at a loop of
commits than not holding the write lock and letting commit itself take
out the lock.

If I get rid of the original wt.lock_write() outside the loop, I then get:
0.721s
0.570s
0.558s
0.574s
0.640s
0.609s
0.627s
0.684s
0.792s

(IOW it stays fast.)

Under lsprof, the dominant time is:
1 0 3.9612 0.0082 bzrlib.graph:157(get_parent_map)
and
260 0 3.9263 3.9263 <method 'recv' of '_socket.socket' objects>

This seems to be under a call to:

3.96s _check_out_of_date_tree
3.96s + has_revision
3.96s + has_revisions
3.96s + remote:1340(get_parent_map)
...

The 'has_revision' check is being done, because if the first parent of
the working tree is a ghost in the repository, it then sets the
new_revno to 1 rather than being old_revno + 1.

I don't quite understand the specifics of why get_parent_map() gets
slower and slower if you hold a write lock open for an extended period
of time. My guess is that something is being cached. Perhaps that when
you hold a write lock it slowly pages in the whole history to return
more and more bits? ~3s seems like it would be ~ the time for a
get_parent_map() call across the entire history of bzrlib. (Especially
in this test branch where I've added a few k more new revisions.)

  affects bzr
  status confirmed
  importance medium
  tags performance hpss

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAksijzMACgkQJdeBCYSNAAOETwCgtbo+UzqftCMe+gAju3sNnl1x
pWEAn2wt+SbzojW0PDvZ5soQwAFCzBS3
=IrwJ
-----END PGP SIGNATURE-----

[John A Meinel (jameinel)]

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

> (IOW it stays fast.)

In contrast, if you use a local checkout the time is approx 120ms for
each commit if you don't hold the lock, and 80ms if you do hold the lock.

You can also see that the number of bytes transmitted over the wire
becomes quite high per commit (1MB/commit sort of thing), versus 5kB or
so otherwise.

It all points to something about get_parent_map() returning a lot more
data than we would care to receive. Probably because it thinks we are
walking the ancestry, when we are actually just walking the last
committed revision.

John
=:->

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAksimMkACgkQJdeBCYSNAAP3HgCeKi2QCKpqhJOrgLDYp58oNKyh
njcAoMMlCIPlmU+sNXVr1TV/Cni1anTT
=qpBn
-----END PGP SIGNATURE-----