Loop of wt.commit() slows down

-----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-----