Slow branch creation with cold disk cache

[Sidnei da Silva]

Creating a new branch with a cold disk cache takes a long time. Profiling information attached.

[Sidnei da Silva (sidnei)]

Second attachment is the same profiling but with hot disk cache, right after the first one was taken.

[Martin Pool (mbp)]

A brief look shows most of the time spent in writelines, suggesting that we're blocking trying to write the tree out. It is a bit surprising that we seem to be blocking writing when we ought to be able to just hand it off to the kernel. It could be interesting to run this under perf or strace to see just where the time goes.

[John A Meinel (jameinel)]

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

Martin Pool wrote:
> A brief look shows most of the time spent in writelines, suggesting that
> we're blocking trying to write the tree out. It is a bit surprising
> that we seem to be blocking writing when we ought to be able to just
> hand it off to the kernel. It could be interesting to run this under
> perf or strace to see just where the time goes.
>

writelines is a C extension (part of file) that iterates and calls
fwrite (roughly) on the strings it gets. (They don't actually have to be
lines).

IIRC Groupcompress is returning chunks that are fulltexts wrapped in a
list, so it should be hung sending data to the OS.

If you want a quick hack test, you could try changing it to
write(content[0]), but I don't expect it to be any better.

John
=:->

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

iEYEARECAAYFAkxEengACgkQJdeBCYSNAAPOpQCg0whJHhONqmgkzxWZePp4/f9T
/pEAn04MqqskAKAmA55rDoOWaLbPN2eV
=wI/w
-----END PGP SIGNATURE-----

[Martin Pool (mbp)]

On 19 July 2010 18:16, John A Meinel <email address hidden> wrote:
> writelines is a C extension (part of file) that iterates and calls
> fwrite (roughly) on the strings it gets. (They don't actually have to be
> lines).
>
> IIRC Groupcompress is returning chunks that are fulltexts wrapped in a
> list, so it should be hung sending data to the OS.
>
> If you want a quick hack test, you could try changing it to
> write(content[0]), but I don't expect it to be any better.

writelines is where the lsprof trace bottoms out, I guess because it
can't see inside the extension. We could try using strace or perf.

I'm a bit surprised that so much of the time is in there and read
barely shows up. Perhaps it is something about sidnei's laptop.

--
Martin

[Jonathan Lange (jml)]

Private link: https://devpad.canonical.com/~jml/20100720-bzr-checkout.strace

$ bzr cbranch db-devel fix-conflicts-yet-again
^\** SIGQUIT received, entering debuggerile contents 5260/7248
** Type 'c' to continue or 'q' to stop the process
** Or SIGQUIT again to quit (and possibly dump core)
> /usr/lib/python2.6/dist-packages/bzrlib/breakin.py(41)_debug()
-> signal.signal(_breakin_signal_number, _debug)
(Pdb) bt
  /usr/bin/bzr(142)<module>()
-> exit_val = bzrlib.commands.main()
  /usr/lib/python2.6/dist-packages/bzrlib/commands.py(1133)main()
-> ret = run_bzr_catch_errors(argv)
  /usr/lib/python2.6/dist-packages/bzrlib/commands.py(1148)run_bzr_catch_errors()
-> return exception_to_return_code(run_bzr, argv)
  /usr/lib/python2.6/dist-packages/bzrlib/commands.py(853)exception_to_return_code()
-> return the_callable(*args, **kwargs)
  /usr/lib/python2.6/dist-packages/bzrlib/commands.py(1055)run_bzr()
-> ret = run(*run_argv)
  /usr/lib/python2.6/dist-packages/bzrlib/plugins/bzrtools/command.py(13)run_argv_aliases()
-> commands.Command.run_argv_aliases(self, argv, alias_argv)
  /usr/lib/python2.6/dist-packages/bzrlib/commands.py(661)run_argv_aliases()
-> return self.run_direct(**all_cmd_args)
  /usr/lib/python2.6/dist-packages/bzrlib/commands.py(665)run_direct()
-> return self._operation.run_simple(*args, **kwargs)
  /usr/lib/python2.6/dist-packages/bzrlib/cleanup.py(122)run_simple()
-> self.cleanups, self.func, *args, **kwargs)
  /usr/lib/python2.6/dist-packages/bzrlib/cleanup.py(156)_do_with_cleanups()
-> result = func(*args, **kwargs)
  /usr/lib/python2.6/dist-packages/bzrlib/plugins/bzrtools/command_classes.py(426)run()
-> hardlink=hardlink)
  /usr/lib/python2.6/dist-packages/bzrlib/plugins/bzrtools/cbranch.py(59)cbranch()
-> hardlink=hardlink)
  /usr/lib/python2.6/dist-packages/bzrlib/branch.py(1334)create_checkout()
-> hardlink=hardlink)
  /usr/lib/python2.6/dist-packages/bzrlib/bzrdir.py(1616)create_workingtree()
-> accelerator_tree=accelerator_tree, hardlink=hardlink)
  /usr/lib/python2.6/dist-packages/bzrlib/workingtree_4.py(1462)initialize()
-> delta_from_tree=delta_from_tree)
  /usr/lib/python2.6/dist-packages/bzrlib/transform.py(2253)build_tree()
-> delta_from_tree)
  /usr/lib/python2.6/dist-packages/bzrlib/transform.py(2346)_build_tree()
-> accelerator_tree, hardlink)
  /usr/lib/python2.6/dist-packages/bzrlib/transform.py(2402)_create_files()
-> tt.create_file(contents, trans_id)
  /usr/lib/python2.6/dist-packages/bzrlib/transform.py(1198)create_file()
-> f.writelines(contents)
> /usr/lib/python2.6/dist-packages/bzrlib/breakin.py(41)_debug()
-> signal.signal(_breakin_signal_number, _debug)
(Pdb) c
^\** SIGQUIT received, entering debuggerile contents 5394/7248
** Type 'c' to continue or 'q' to stop the process
** Or SIGQUIT again to quit (and possibly dump core)
> /usr/lib/python2.6/dist-packages/bzrlib/breakin.py(41)_debug()
-> signal.signal(_breakin_signal_number, _debug)
(Pdb) bt
  /usr/bin/bzr(142)<module>()
-> exit_val = bzrlib.commands.main()
  ...

[Martin Pool (mbp)]

sidnei was seeing this on a Macbook running ubuntu, with 4Gb and a magnetic disk. jml hit this too running cbranch on his laptop. (So it's probably not specific to that branch.)

strace shows we're writing in 4kB blocks which seems a bit small. Perhaps we should do more, and the filesystem might go a bit faster if we pre-truncated the files to the length we know they're eventually going to be.

We're using an accelerator tree here and at least for the cold cache case it's probably a pessimation: reading a few big pack files is probably better than seeking all over to read the existing files.

writelines is writing the contents of an iterator so what looks like time spent in write encompasses reading.

[Robert Collins (lifeless)]

accelerator trees are definitely a pessimisation in the cold cache
non-hardlink case - we've established that before.

[John A Meinel (jameinel)]

The fix in the associated branch changes code so that it avoids reading the source working tree. Which has a few effects:

1) The overhead in file.writelines() was actually because we were passing out_file.writelines(in_file)
   This in turn was doing for line in in_file: fwrite(line). Though it was doing it in batches of 'read 1000 lines', 'write 1000 lines'.
  The 4096 byte writes were were seeing is because it was calling fwrite(line, ...) which presumably uses a 4k write buffer.
2) avoids all the seeks to read the content of each individual file
3) adds the extract-content-from-disk overhead (CPU overhead) for building the
new working tree when the source tree *is* hot. timing shows that for fully-hot
caches, 1.13s => 2.00s to build bzr.dev (on a specific machine). Cold cache
timing shows as much as 80s => 30s for building a launchpad tree, which seems a
better place to worry about. (reducing the worst case is often more productive
than reducing the best case.)

 For landscape on Sidnei's laptop, the numbers are:
 a) cold-cache, accelerator_tree 40s
 b) cold-cache, no_accelerator_tree 11s
 c) hot-cache, no_accelerator_tree 2.8s
 d) hot-cache, accelerator_tree 1.8s

So we slow down the ideal case by 1.5x (though you can use --files-from to get
that back), but we speed up worse case by 4x.