Comment 4 for bug 740759

Revision history for this message
John A Meinel (jameinel) wrote :

Some analysis
Overall time under lsprof on this VM was 1.4s (run_argv_aliases), parse_args took a surprising 100ms, and _setup_outf 50ms.

Going deep into the code, the bulk of the time is:

           1 0 0.7240 0.0000 bzrlib.bzrdir:2076(make_directory)
          +1 0 0.7240 0.0002 +lp.codehosting.vfs.transport:314(mkdir)

Which breaks down into:

           2 0 0.7411 0.0001 lp.codehosting.vfs.branchfs:505(mkdir)
          +2 0 0.4761 0.0002 +lp.codehosting.vfs.transport:105(_getUnderylingTransportAndPath)
          +2 0 0.2485 0.0000 +twisted.internet.defer:300(addErrback)
          +2 0 0.0164 0.0000 +twisted.internet.defer:290(addCallback)

Which breaks down further as:

           3 0 0.6480 0.0002 lp.codehosting.vfs.transport:105(_getUnderylingTransportAndPath)
          +3 0 0.0002 0.0001 +lp.codehosting.vfs.transport:99(_abspath)
          +3 0 0.6476 0.0001 +lp.codehosting.vfs.branchfs:392(translateVirtualPath)
           3 0 0.6476 0.0001 lp.codehosting.vfs.branchfs:392(translateVirtualPath)
          +3 0 0.1682 0.0007 +twisted.internet.defer:271(addCallbacks)
          +3 0 0.4791 0.0002 +lp.codehosting.vfs.branchfsclient:124(translatePath)
          +3 0 0.0003 0.0000 +twisted.internet.defer:300(addErrback)

           3 0 0.4791 0.0002 lp.codehosting.vfs.branchfsclient:124(translatePath)
          +2 0 0.4784 0.0002 +lp.services.twistedsupport.xmlrpc:47(callRemote)
          +3 0 0.0002 0.0002 +lp.codehosting.vfs.branchfsclient:83(_getFromCache)
          +2 0 0.0004 0.0000 +twisted.internet.defer:290(addCallback)
          +1 0 0.0000 0.0000 +twisted.internet.defer:53(succeed)

           3 0 0.4663 0.0001 lp.services.twistedsupport.xmlrpc:34(callRemote)
          +3 0 0.0001 0.0001 +<getattr>
          +3 0 0.4661 0.0000 +xmlrpclib:1198(__call__)

And what do you know, the xmlrpc service rears its ugly head again. Looking at it from a different aggregate:

           3 0 0.7262 0.0002 lp.services.twistedsupport.xmlrpc:47(callRemote)
          +3 0 0.7260 0.0004 +twisted.internet.defer:112(maybeDeferred)
          +1 0 0.0000 0.0000 +socket:274(__del__)

So all the time seems to be spent in the XMLRPC calls. The next steps seem to be figuring out why the XMLRPC calls are so expensive.