Slowness of test suite on Win32 (renaming is slow, renaming dirs is slooooooow)

[John Arbash Meinel]

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

I've been doing a bit of dev using Windows, and I noticed the test suites being
really slow (again).

I decided to spend a little bit of time looking at it, and this is what I found.
~    38            0      1.1634      0.0029  bzrlib.lockdir:204(_attempt_lock)
~    90            0      0.2653      0.0129   bzrlib.osutils:196(fancy_rename)
~  +180            0      0.2099      0.2099   +<nt.rename>
~    84            0      1.6530      0.0025   bzrlib.transport.local:378(rename)
~   +84            0      1.6337      1.6337   +<nt.rename>

This specific test, create a tree, holds a lock on it, commits a few times,
sprouts it to another tree, then merges it back. So it is creating a
Tree+Branch+Repo, 1 commit, sprout, 1 commit in sprout, merge back to parent,
and commit.

So about 3 commits, and 2 initializations.

I was pretty surprised that this little amount of work resulted in 38 actual
locks being opened, and 84 directory renames. Part of the reason is that with
packs calling Repo.lock_write() doesn't actually hold the lock on disk. Instead
every 'commit_write_group()' takes out a new one and releases it as soon as the
pack-names is updated.

So doing:

tree.lock_write()
try:
~  tree.commit()
~  tree.commit()
~  tree.fetch()
~  tree.commit()
finally:
~  tree.unlock()

Actually has to grab the disk lock 4 times. Same thing for doing a 'fetch()', or
any other operation that actually updates the repository.

I can't say *why* doing an os.rename() on a directory costs about 20ms each. It
seems to be confirmed by:

$ python -m timeit -s 'import os' \
~  "os.mkdir('1'); os.rename('1', '2'); os.rmdir('2')"
10 loops, best of 3: 19 msec per loop

On my Linux machine this is:
10000 loops, best of 3: 188 usec per loop

or approximately 100 times faster.
Renaming a file is significantly faster:
$ python -m timeit -s 'import os' \
~  "open('1', 'wb').close(); os.rename('1', '2'); os.rmdir('2')"
100 loops, best of 3: 2.99 msec per loop
versus
10000 loops, best of 3: 183 usec per loop

I don't think we need to tune our actual code for this. Most command-line level
operations should only take out a single write lock to do their work, and then
finish. The test suite is just being penalized because it is doing multiple
logical ops, generally as part of setting things up. It might be nice if there
was a way to say "I'm setting things up, don't commit anything to disk yet."

Anyway, because of the os.rename() issue, it means every minor commit has at
least 40ms of overhead (we rename into place, and then out again). More if you
don't hold the lock so that tree.lock_write() and branch.lock_write() *also*
have to grab disk locks.

Maybe just switching over more tests to the in-memory stuff when possible.

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

iD8DBQFH4rjEJdeBCYSNAAMRArVAAJwOzctxR2a2+S10+QMULAVRGtQdrQCgkRR5
PZm4mUzgO6G0q/I9ZY1ZIps=
=EIWY
-----END PGP SIGNATURE-----