Bazaar

Branching on local disk works but bzr hangs using bzr network protocol

Asked by Jemsquash

I have created a test repository to test bazaar as a suitable tool to replace our current revision control tool. Unfortunately bzr hangs when I try to create a branch using the bzr protocol:

bash-3.2$ bzr branch bzr://localhost:8090 staging2
/ [=============================== ] Copying content texts 3/5

Is as far as it gets. The log file in "My Documents" reveals no error.

The server console reveals no problems:
bash-3.2$ bzr serve --port 8090 --directory .
listening on port: 8090

If I branch using the local disk I get no problems:
bash-3.2$ bzr branch /temp/bzrMergeTest/bzrTestBranch staging
Branched 8 revision(s).

This has happened with 1.8 and 1.9. I have not tried it with previous versions. The repository is about 1.3 gigs. bzr check reveals no errors.

Question information

Language:
English Edit question
Status:
Solved
For:
Bazaar Edit question
Assignee:
No assignee Edit question
Solved by:
John A Meinel
Solved:
Last query:
Last reply:
Revision history for this message
Martin Pool (mbp) said : 		#1

Could you please re-run the command as

bzr -Dhpss branch bzr://localhost:8090 staging2

and post the content from ~/.bzr.log

Revision history for this message
Jemsquash (james-stewart) said : 		#2

I ran the client from a different computer to make sure that there was nothing strange about client and server being on the same computer but got the same result, the console output become frozen with the following:
C:\temp>bzr branch bzr://PC19714:8090 stagingRemote -Dhpss
| [=============================== ] Copying content texts 3/5

.bzr.log from remote client computer:

this is a debug log for diagnosing/reporting problems in bzr
you can delete or truncate this file, or include sections in
bug reports to https://bugs.launchpad.net/bzr/+filebug

Tue 2008-11-25 09:57:24 +0900
0.031 bzr arguments: [u'branch', u'bzr://PC19714:8090', u'stagingRemote', u'-Dhpss']
0.031 looking for plugins in C:/Documents and Settings/jastewart/Application Data/bazaar/2.0/plugins
0.031 looking for plugins in C:/vsfz/tools/bazaar/plugins
0.078 bzr-svn: using Subversion 1.5.4 ()
0.094 encoding stdout as sys.stdout encoding 'cp850'
0.125 hpss: Built a new medium: SmartTCPClientMedium
0.125 hpss call: 'BzrDir.open', '.'
0.125 (to bzr://PC19714:8090/)
0.172 result: ('yes',)
0.172 hpss call: 'BzrDir.open_branch', '.'
0.172 (to bzr://PC19714:8090/)
0.172 result: ('ok', '')
0.172 hpss call: 'BzrDir.find_repositoryV2', '.'
0.172 (to bzr://PC19714:8090/)
0.282 result: ('ok', '', 'no', 'no', 'no')
0.282 hpss call: 'Branch.get_stacked_on_url', '.'
0.282 (to bzr://PC19714:8090/)
0.282 result: ('UnstackableBranchFormat', 'Bazaar Branch Format 6 (bzr 0.15)', 'chroot-17549456:///')
0.282 hpss call: 'Branch.last_revision_info', '.'
0.282 (to bzr://PC19714:8090/)
0.298 result: ('ok', '8', 'jastewart@pc19714-20080919023229-l0zjswiwnoi7oexr')
0.298 hpss call: 'get', '/.bzr/branch-format'
0.298 (to bzr://PC19714:8090/)
0.298 result: ('ok',)
0.298 35 body bytes read
0.298 hpss call: 'get', '/.bzr/branch/format'
0.298 (to bzr://PC19714:8090/)
0.298 result: ('ok',)
0.298 34 body bytes read
0.298 hpss call: 'stat', '/.bzr/branch'
0.298 (to bzr://PC19714:8090/)
0.298 result: ('stat', '0', '040777')
0.298 hpss call: 'get', '/.bzr/repository/format'
0.298 (to bzr://PC19714:8090/)
0.298 result: ('ok',)
0.298 49 body bytes read
0.298 hpss call: 'stat', '/.bzr/repository'
0.298 (to bzr://PC19714:8090/)
0.298 result: ('stat', '0', '040777')
0.313 hpss call: 'get', '/.bzr/checkout/format'
0.313 (to bzr://PC19714:8090/)
0.313 result: ('ok',)
0.313 40 body bytes read
0.329 hpss call: 'BzrDir.open_branch', '.'
0.329 (to bzr://PC19714:8090/)
0.329 result: ('ok', '')
0.329 hpss call: 'BzrDir.find_repositoryV2', '.'
0.329 (to bzr://PC19714:8090/)
0.329 result: ('ok', '', 'no', 'no', 'no')
0.329 hpss call: 'Branch.get_stacked_on_url', '.'
0.329 (to bzr://PC19714:8090/)
0.345 result: ('UnstackableBranchFormat', 'Bazaar Branch Format 6 (bzr 0.15)', 'chroot-17549456:///')
0.360 opening SVN RA connection to 'file:///C:/temp'
0.360 Unable to open <bzrlib.transport.local.LocalTransport url=file:///C:/temp/> with Subversion: Unable to open an ra_local session to URL
0.360 opening SVN RA connection to 'file:///C:'
0.360 Unable to open <bzrlib.transport.local.LocalTransport url=file:///C:/> with Subversion: Unable to open an ra_local session to URL
0.360 creating repository in file:///C:/temp/stagingRemote/.bzr/.
0.376 hpss call: 'get', '/.bzr/repository/format'
0.376 (to bzr://PC19714:8090/)
0.376 result: ('ok',)
0.376 49 body bytes read
0.376 hpss call: 'stat', '/.bzr/repository'
0.376 (to bzr://PC19714:8090/)
0.376 result: ('stat', '0', '040777')
0.376 hpss call: 'get', '/.bzr/repository/pack-names'
0.376 (to bzr://PC19714:8090/)
0.376 result: ('ok',)
0.376 220 body bytes read
0.376 Using fetch logic to copy between KnitPackRepository('bzr://PC19714:8090/.bzr/repository/')(<RepositoryFormatKnitPack1>) and KnitPackRepository('file:///C:/temp/stagingRemote/.bzr/repository/')(<RepositoryFormatKnitPack1>)
0.376 hpss call w/readv: 'readv', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.rix'
0.376 5 bytes in readv request
0.376 result: ('readv',)
0.376 240 body bytes read
0.392 hpss call w/readv: 'readv', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.rix'
0.392 5 bytes in readv request
0.392 result: ('readv',)
0.392 508 body bytes read
0.392 hpss call w/readv: 'readv', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.rix'
0.392 5 bytes in readv request
0.392 result: ('readv',)
0.392 177 body bytes read
0.392 hpss call w/readv: 'readv', '/.bzr/repository/packs/09aecbdd1fc3d307c42ebc63e9888f31.pack'
0.392 5 bytes in readv request
0.454 result: ('readv',)
0.454 420 body bytes read
0.454 hpss call w/readv: 'readv', '/.bzr/repository/packs/429b4f2fadbc54844b3b4ba53a9154c4.pack'
0.454 6 bytes in readv request
0.454 result: ('readv',)
0.454 2597 body bytes read
0.454 hpss call w/readv: 'readv', '/.bzr/repository/packs/b784e64ac410bc6cd735190a3491c19d.pack'
0.454 16 bytes in readv request
0.501 result: ('readv',)
0.501 519 body bytes read
0.501 hpss call w/readv: 'readv', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.iix'
0.501 5 bytes in readv request
0.501 result: ('readv',)
0.501 185 body bytes read
0.501 hpss call w/readv: 'readv', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.iix'
0.501 5 bytes in readv request
0.517 result: ('readv',)
0.517 563 body bytes read
0.517 hpss call w/readv: 'readv', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.iix'
0.517 5 bytes in readv request
0.517 result: ('readv',)
0.517 243 body bytes read
0.517 hpss call w/readv: 'readv', '/.bzr/repository/packs/09aecbdd1fc3d307c42ebc63e9888f31.pack'
0.517 15 bytes in readv request
0.564 result: ('readv',)
0.564 213178 body bytes read
0.611 hpss call w/readv: 'readv', '/.bzr/repository/packs/429b4f2fadbc54844b3b4ba53a9154c4.pack'
0.611 17 bytes in readv request
0.689 result: ('readv',)
0.799 1300592 body bytes read
1.081 hpss call w/readv: 'readv', '/.bzr/repository/packs/b784e64ac410bc6cd735190a3491c19d.pack'
1.081 18 bytes in readv request
1.112 result: ('readv',)
1.159 737426 body bytes read
1.363 hpss call w/readv: 'readv', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.tix'
1.363 7 bytes in readv request
1.426 result: ('readv',)
1.426 65536 body bytes read
1.441 hpss call: 'get', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.tix'
1.441 (to bzr://PC19714:8090/)
1.488 result: ('ok',)
1.551 806638 body bytes read
1.645 hpss call w/readv: 'readv', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.tix'
1.645 7 bytes in readv request
1.692 result: ('readv',)
1.692 65536 body bytes read
1.692 hpss call: 'get', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.tix'
1.692 (to bzr://PC19714:8090/)
1.817 result: ('ok',)
2.099 3490462 body bytes read
2.663 hpss call w/readv: 'readv', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.tix'
2.663 7 bytes in readv request
2.726 result: ('readv',)
2.726 65536 body bytes read
2.726 hpss call: 'get', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.tix'
2.726 (to bzr://PC19714:8090/)
2.757 result: ('ok',)
2.820 859936 body bytes read
3.430 hpss call w/readv: 'readv', '/.bzr/repository/packs/09aecbdd1fc3d307c42ebc63e9888f31.pack'
3.430 1273 bytes in readv request
6.657 result: ('readv',)
15.883 107121267 body bytes read
18.514 hpss call w/readv: 'readv', '/.bzr/repository/packs/429b4f2fadbc54844b3b4ba53a9154c4.pack'
18.514 8981 bytes in readv reques

.bzr.log from server computer:

this is a debug log for diagnosing/reporting problems in bzr
you can delete or truncate this file, or include sections in
bug reports to https://bugs.launchpad.net/bzr/+filebug

Tue 2008-11-25 09:56:34 +0900
0.468 bzr arguments: [u'serve', u'--port', u'8090', u'--directory', u'.']
0.468 looking for plugins in C:/Documents and Settings/jastewart/Application Data/bazaar/2.0/plugins
0.468 looking for plugins in C:/vsfz/tools/bazaar/plugins
0.578 bzr-svn: using Subversion 1.5.4 ()
0.625 encoding stdout as

Tue 2008-11-25 10:00:06 +0900
[ 5568] 2008-11-25 10:00:07.161 INFO: tbzrcache running...
[ 5568] 2008-11-25 10:10:41.209 INFO: Client disconnected from pipe - closing connection
[ 5568] 2008-11-25 11:15:47.809 INFO: Client disconnected from pipe - closing connection

Revision history for this message
Jemsquash (james-stewart) said : 		#3

I don't know much about python or bazaar but I have done a bit of debugging in eclipse of the problem. Is there anywhere I can post screenshots?

Unfortunately the repository is of sensitive nature so I cannot give access to it.

Both client and server seem to be blocked on a read. I have to interrupt one (in eclipse) and the kill the other process so that the connection is closed and the app can continue and then get interrupted by the debugger. I then do it the other way around.

Stack trace of client:
_read_bytes [medium.py:850]
read_bytes [medium.py:148]
_read_bytes [medium.py:456]
read_bytes [medium.py:444]
_read_more [message.py:237]
_wait_for_response_args [message.py:224]
read_response_tuple [message.py:258]
_call_and_read_response [client.py:71]
call_with_body_readv_array [client.py:165]
_readv [remote.py:318]
readv [__init__.py:638]
make_readv_reader [pack.py:203]
_do_copy_nodes_graph [pack_repo.py:846]
_copy_nodes_graph [pack_repo.py:825]
_copy_text_texts [pack_repo.py:704]
_create_pack_from_packs [pack_repo.py:740]
pack [pack_repo.py:605]
_pack [repository.py:2856]
fetch [repository.py:2849]
write_locked [decorators.py:192]
fetch [repository.py:3147]
fetch [repository.py:989]
sprout [bzrdir.py:1113]
run [builtins.py:980]
run_argv_aliases [commands.py:539]
run_bzr [commands.py:839]
run_bzr_catch_errors [commands.py:893]
main [commands.py:884]
<module> [bzr.py:130]
run [pydevd.py:655]
<module> [pydevd.py:803]

I added a print statement to protocol.py:
    def _write_structure(self, args):
        self._write_func('s')
        utf8_args = []
        for arg in args:
            if type(arg) is unicode:
                utf8_args.append(arg.encode('utf8'))
            else:
                utf8_args.append(arg)
        print utf8_args
        sys.stdout.flush()
        self._write_prefixed_bencode(utf8_args)

And got the following output of the client:

pydev debugger
['BzrDir.open', '.']
['BzrDir.open_branch', '.']
['BzrDir.find_repositoryV2', '.']
['Branch.get_stacked_on_url', '.']
['Branch.last_revision_info', '.']
['get', '/.bzr/branch-format']
['get', '/.bzr/branch/format']
['stat', '/.bzr/branch']
['get', '/.bzr/repository/format']
['stat', '/.bzr/repository']
['get', '/.bzr/checkout/format']
['BzrDir.open_branch', '.']
['BzrDir.find_repositoryV2', '.']
['Branch.get_stacked_on_url', '.']
['get', '/.bzr/repository/format']
['stat', '/.bzr/repository']
['get', '/.bzr/repository/pack-names']
['readv', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.rix']
['readv', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.rix']
['readv', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.rix']
['readv', '/.bzr/repository/packs/09aecbdd1fc3d307c42ebc63e9888f31.pack']
['readv', '/.bzr/repository/packs/429b4f2fadbc54844b3b4ba53a9154c4.pack']
['readv', '/.bzr/repository/packs/b784e64ac410bc6cd735190a3491c19d.pack']
['readv', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.iix']
['readv', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.iix']
['readv', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.iix']
['readv', '/.bzr/repository/packs/09aecbdd1fc3d307c42ebc63e9888f31.pack']
['readv', '/.bzr/repository/packs/429b4f2fadbc54844b3b4ba53a9154c4.pack']
['readv', '/.bzr/repository/packs/b784e64ac410bc6cd735190a3491c19d.pack']
['readv', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.tix']
['get', '/.bzr/repository/indices/09aecbdd1fc3d307c42ebc63e9888f31.tix']
['readv', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.tix']
['get', '/.bzr/repository/indices/429b4f2fadbc54844b3b4ba53a9154c4.tix']
['readv', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.tix']
['get', '/.bzr/repository/indices/b784e64ac410bc6cd735190a3491c19d.tix']
['readv', '/.bzr/repository/packs/09aecbdd1fc3d307c42ebc63e9888f31.pack']
['readv', '/.bzr/repository/packs/429b4f2fadbc54844b3b4ba53a9154c4.pack']

And for the server:
Stack Trace:
_read_bytes [medium.py:277]
read_bytes [medium.py:148]
_get_line [medium.py:99]
_get_line [medium.py:161]
_build_protocol [medium.py:217]
serve [medium.py:202]
run [threading.py:446]
__bootstrap_inner [threading.py:486]
__bootstrap [threading.py:462]

output:

pydev debugger
listening on port: 8090
['yes']
['ok', '']
['ok', '', 'no', 'no', 'no']
['UnstackableBranchFormat', 'Bazaar Branch Format 6 (bzr 0.15)', 'chroot-12610704:///']
['ok', '8', 'jastewart@pc19714-20080919023229-l0zjswiwnoi7oexr']
['ok']
['ok']
['stat', '0', '040777']
['ok']
['stat', '0', '040777']
['ok']
['ok', '']
['ok', '', 'no', 'no', 'no']
['UnstackableBranchFormat', 'Bazaar Branch Format 6 (bzr 0.15)', 'chroot-12610704:///']
['ok']
['stat', '0', '040777']
['ok']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['readv']
['ok']
['readv']
['ok']
['readv']
['ok']
['readv']
['readv']

Revision history for this message
Best John A Meinel (jameinel) said : 		#4

There is this fix in bzr-1.10 which may be applicable:
* When making a large readv() request over ``bzr+ssh``, break up the
  request into more manageable chunks. Because the RPC is not yet able
  to stream, this helps keep us from buffering too much information at
  once. (John Arbash Meinel)

It is possible that we are requesting most of that 1.3GB and your machine is then going into swap mode trying to buffer the 1GB request before it transmits it over the loopback, and then buffers it in the client. (So you would end up buffering 2GB or so, etc.)

You might try upgrading to 1.10 and see if that fixes this specific problem.

Revision history for this message
Jemsquash (james-stewart) said : 		#5

Thanks John A Meinel, that solved my question.