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.
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) .vfs.transport: 314(mkdir)
+1 0 0.7240 0.0002 +lp.codehosting
Which breaks down into:
2 0 0.7411 0.0001 lp.codehosting. vfs.branchfs: 505(mkdir) .vfs.transport: 105(_getUnderyl ingTransportAnd Path) internet. defer:300( addErrback) internet. defer:290( addCallback)
+2 0 0.4761 0.0002 +lp.codehosting
+2 0 0.2485 0.0000 +twisted.
+2 0 0.0164 0.0000 +twisted.
Which breaks down further as:
3 0 0.6480 0.0002 lp.codehosting. vfs.transport: 105(_getUnderyl ingTransportAnd Path) .vfs.transport: 99(_abspath) .vfs.branchfs: 392(translateVi rtualPath) vfs.branchfs: 392(translateVi rtualPath) internet. defer:271( addCallbacks) .vfs.branchfscl ient:124( translatePath) internet. defer:300( addErrback)
+3 0 0.0002 0.0001 +lp.codehosting
+3 0 0.6476 0.0001 +lp.codehosting
3 0 0.6476 0.0001 lp.codehosting.
+3 0 0.1682 0.0007 +twisted.
+3 0 0.4791 0.0002 +lp.codehosting
+3 0 0.0003 0.0000 +twisted.
3 0 0.4791 0.0002 lp.codehosting. vfs.branchfscli ent:124( translatePath) twistedsupport. xmlrpc: 47(callRemote) .vfs.branchfscl ient:83( _getFromCache) internet. defer:290( addCallback) internet. defer:53( succeed)
+2 0 0.4784 0.0002 +lp.services.
+3 0 0.0002 0.0002 +lp.codehosting
+2 0 0.0004 0.0000 +twisted.
+1 0 0.0000 0.0000 +twisted.
3 0 0.4663 0.0001 lp.services. twistedsupport. xmlrpc: 34(callRemote) 1198(__ call__)
+3 0 0.0001 0.0001 +<getattr>
+3 0 0.4661 0.0000 +xmlrpclib:
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) internet. defer:112( maybeDeferred) 274(__del_ _)
+3 0 0.7260 0.0004 +twisted.
+1 0 0.0000 0.0000 +socket:
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.