Comment 10 for bug 740759

I re-ran this test on a VM that had a bit better perf characteristics, just to make sure that wasn't the specific issue.

'time echo hello | ssh' took 242ms
'time cat initialize_bzrdir_ex.txt | ssh' took 877ms

Which corresponds well with lp-serve taking 664ms in 'run_argv_aliases'

What surprises me a lot, is the slowest function is this:
          29 0 0.4081 0.2940 twisted.python.failure:416(__getstate__)
      +34492 0 0.1141 0.0235 +twisted.python.reflect:557(safe_repr)
         +11 0 0.0000 0.0000 +<method 'copy' of 'dict' objects>
        2680 0 0.1329 0.1329 <method 'recv' of '_socket.socket' objects>

We still have this:
          48 0 0.5155 0.0003 lp.codehosting.vfs.branchfs:392(translateVirtualPath)
         +48 0 0.3116 0.0011 +twisted.internet.defer:271(addCallbacks)
           6 0 0.1432 0.0001 lp.services.twistedsupport.xmlrpc:34(callRemote)
          +6 0 0.0001 0.0001 +<getattr>
          +6 0 0.1430 0.0000 +xmlrpclib:1198(__call__)

So of the 664ms to actually initialize, 515ms of it is spent in translateVirtualPath. However, of that time, 410ms is actually spent handling failure.__getstate__
35k calls to safe_repr sure seems like a lot for 29 calls to the function. It hints that exception handling in twisted is really quite expensive. Though I'm sure --lsprof exacerbates this.

It does say that the xmlrpc calls cost 143ms of the 600ms.

Without --lsprof, from outside I see 161ms to 'echo hello' and 671ms to 'initialize_on_transport_ex', so 510ms to actually do the initialization.

That says lsprof doesn't have all that much overhead. Considering it is only 510ms to 660ms with lsprof active.

Being a bit more invasive, and logging lp.services.twistedsupport.xmlrpc.BlockingProxy to log how long the xmlrpc request takes, without running --lsprof, I get:

0.029 hpss request: [140370829006592] BzrDirFormat.initialize_ex_1.16 'Bazaar-NG
[ 5073] 2011-03-24 15:19:01.447 INFO: method: translatePath took 0.025s
[ 5073] 2011-03-24 15:19:01.560 INFO: method: createBranch took 0.057s
[ 5073] 2011-03-24 15:19:01.583 INFO: method: translatePath took 0.022s
[ 5073] 2011-03-24 15:19:01.632 INFO: method: translatePath took 0.021s
[ 5073] 2011-03-24 15:19:01.681 INFO: method: translatePath took 0.018s
[ 5073] 2011-03-24 15:19:01.917 INFO: method: translatePath took 0.012s
0.543 creating repository in lp-78465616:///~jameinel/%2Bjunk/x/.bzr.

Which is 514ms to run initialize_ex. 155ms of that is spent in XMLRPC calls.

Compare that to openssh directly:

Thu 2011-03-24 15:22:46 +0100
0.032 bazaar version: 2.1.1
0.032 bzr arguments: [u'serve', u'--inet', u'--directory=/', u'--allow-writes']
...
0.113 hpss request: [139780618553088] BzrDirFormat.initialize_ex_1.16 'Bazaar-NG m
0.143 creating repository in filtered-41417872:///~jameinel/%2Bjunk/x/.bzr/.

Which says it takes 30ms to actually perform the action.