Startup delay in commands using bzr smart server when bzr-svn plugin installed

  status incomplete

I can't reproduce this problem, at least not on Linux. There is some
overhead in loading bzr-svn, but it shouldn't be 2 seconds (it's 100ms
here). I have no idea why bzr is probing that URL with bzr-svn anyway,
as it should be able to open it using a native bzr format.

Do you get any messages about bzr-svn being loaded when you run "bzr
info bzrtest" ?

We currently have Bazaar installed on 4 Windows machine on our network here and I can reproduce the problem on all of them. Unfortunately I don't have access to a linux machine to test it.

Here is the log for "bzr info bzrtest":

Wed 2009-11-25 13:00:04 +0800
0.078 bzr arguments: [u'info', u'C:\\code\\bzrtest']
0.094 looking for plugins in C:/Documents and Settings/gwhite/Application Data/bazaar/2.0/plugins
0.094 looking for plugins in C:/Program Files/Bazaar/plugins
0.219 encoding stdout as sys.stdout encoding 'cp850'
0.250 opening working tree 'C:/code/bzrtest'
0.266 return code 0

Here's the log for "bzr info bzr://localhost/bzrtest":

Wed 2009-11-25 13:00:06 +0800
0.093 bzr arguments: [u'info', u'bzr://localhost/bzrtest']
0.093 looking for plugins in C:/Documents and Settings/gwhite/Application Data/bazaar/2.0/plugins
0.093 looking for plugins in C:/Program Files/Bazaar/plugins
0.234 encoding stdout as sys.stdout encoding 'cp850'
0.265 bzr-svn: using Subversion 1.5.6 ()
1.953 return code 0

Here's the log for "bzr info bzr://localhost/bzrtest -Dhpss":

Wed 2009-11-25 13:00:41 +0800
0.078 bzr arguments: [u'info', u'bzr://localhost/bzrtest', u'-Dhpss']
0.094 looking for plugins in C:/Documents and Settings/gwhite/Application Data/bazaar/2.0/plugins
0.094 looking for plugins in C:/Program Files/Bazaar/plugins
0.219 encoding stdout as sys.stdout encoding 'cp850'
0.234 hpss: Built a new medium: SmartTCPClientMedium
0.250 bzr-svn: using Subversion 1.5.6 ()
1.859 hpss call: 'BzrDir.open', 'bzrtest/'
1.859 (to bzr://localhost/bzrtest/)
1.859 result: ('yes',)
1.859 hpss call: 'get', '/bzrtest/.bzr/branch-format'
1.859 (to bzr://localhost/bzrtest/)
1.875 result: ('ok',)
1.875 35 body bytes read
1.875 hpss call: 'get', '/bzrtest/.bzr/checkout/format'
1.875 (to bzr://localhost/bzrtest/)
1.875 result: ('ok',)
1.875 40 body bytes read
1.875 hpss call: 'BzrDir.open_branchV2', 'bzrtest/'
1.875 (to bzr://localhost/bzrtest/)
1.875 result: ('branch', 'Bazaar Branch Format 7 (needs bzr 1.6)\n')
1.875 hpss call: 'BzrDir.find_repositoryV3', 'bzrtest/'
1.875 (to bzr://localhost/bzrtest/)
1.875 result: ('ok', '', 'yes', 'no', 'yes', 'Bazaar repository format 2a (needs bzr 1.16 or later)\n')
1.875 hpss call: 'Branch.get_stacked_on_url', 'bzrtest/'
1.875 (to bzr://localhost/bzrtest/)
1.875 result: ('NotStacked',)
1.875 hpss call: 'Repository.is_shared', 'bzrtest/'
1.875 (to bzr://localhost/bzrtest/)
1.875 result: ('no',)
1.906 hpss call: 'Repository.is_shared', 'bzrtest/'
1.906 (to bzr://localhost/bzrtest/)
1.906 result: ('no',)
1.906 hpss call: 'Repository.is_shared', 'bzrtest/'
1.906 (to bzr://localhost/bzrtest/)
1.906 result: ('no',)
1.906 hpss call: 'Branch.get_config_file', 'bzrtest/'
1.906 (to bzr://localhost/bzrtest/)
1.906 result: ('ok',)
1.906 0 body bytes read
1.906 hpss call: 'Branch.get_config_file', 'bzrtest/'
1.906 (to bzr://localhost/bzrtest/)
...

Removing the following line from plugins/svn/__init__.py makes the delay go away:

    BzrDirFormat._control_server_formats.insert(0, format.SvnRemoteFormat)

The comments above that line seem to indicate it's a workaround for some Subversion servers, but a side-effect seems to be that Bazaar will create an instance of SvnRemoteFormat and call probe_transport() even if the user specifies a "bzr://" URL.

I also narrowed done where the delay in probe_transport() is occurring. It eventually calls init_subvertpy(), in which the line "import bzrlib.transport.ssh" is taking approx. 1.5 seconds to run on my machine. Looking at the source for that module indications that it's trying to determine which ssh client to use. I don't have any ssh clients installed - could this be the problem?

After further investigation I found that the startup delay is due to the initialization of Paramiko, which Bazaar uses by default on Windows for SSH. It uses RandomPool from PyCrypto, which takes 1.5 seconds to initialize (see https://bugs.launchpad.net/paramiko/+bug/271791 and https://bugs.launchpad.net/pycrypto/+bug/248522).

bzr-svn encounters this delay when it imports bzrlib.transport.ssh within init_subvertpy().

What this means is that on Windows you get a 1.5 second startup delay for most bzr commands when using these URL types:
* bzr+ssh://
* sftp://

If you have bzr-svn installed you also get the delay for:
* bzr://
* http://
* https://
* svn+http://
* svn+ssh://

There are really two issues here:
1. Having bzr-svn installed causes Bazaar to probe bzr:// (and possibly other) URLs for Subversion.
2. Importing bzrlib.transport.ssh takes 1.5 seconds on Windows (due to Paramiko initialization).

Should I raise separate bugs for these issues? It's really the combination of the two together that makes Bazaar unnecessarily slow on Windows when you're using a smart server.

This has been fixed by bug 497733. Although it's still strange that the Subversion plugin seems to be doing stuff for bzr:// URLs it doesn't seem to have any other side effects (other than polluting the server logs).