Re: Locks on the Bzr repository

[Jason Rumney <jasonr@gnu.org>]

  On 20/8/2010 12:24 AM, Eli Zaretskii wrote:
>> From: Stefan Monnier<monnier@iro.umontreal.ca>
>> Date: Thu, 19 Aug 2010 17:40:29 +0200
>>
>> Could it be that bzr grabs the lock when you do "bzr commit" and keep it
>> held for as long as you're editing the commit message?
> Maybe so, but why would it take Jason 28 minutes and 50-odd seconds to
> edit a commit message?
>
> I suspect the culprit is network traffic, but Jason should be able to
> tell more by looking at his .bzr.log file, where each operation is
> logged together with its timing.

Here are the commits I performed today:

The first one went quite smoothly but took about 8 minutes.

Thu 2010-08-19 22:50:16 +0800
0.058  bazaar version: 2.1.1
0.058  bzr arguments: [u'commit', u'-m', u"(w32_wnd_proc): Don't check 
context before initializing.\n", u'src/ChangeLog', u'src/w32fns.c']
0.086  looking for plugins in /home/jasonr/.bazaar/plugins
0.086  looking for plugins in 
/usr/lib/python2.6/dist-packages/bzrlib/plugins
0.159  encoding stdout as osutils.get_user_encoding() 'UTF-8'
0.225  opening working tree '/home/jasonr/bzr/emacs/trunk'
0.303  ssh implementation is OpenSSH
28.204  preparing to commit
[22809] 2010-08-19 22:51:09.255 INFO: Committing to: 
sftp://jasonr@bzr.savannah.gnu.org/srv/bzr/emacs/trunk/
52.688  Selecting files for commit with filter [u'src/ChangeLog', 
u'src/w32fns.c']
[22809] 2010-08-19 22:51:09.326 INFO: modified src/ChangeLog
[22809] 2010-08-19 22:51:09.344 INFO: modified src/w32fns.c
52.990  Using fetch logic to copy between 
CHKInventoryRepository('file:///home/jasonr/bzr/emacs/.bzr/repository/')(RepositoryFormat2a()) 
and 
CHKInventoryRepository('sftp://jasonr@bzr.savannah.gnu.org/srv/bzr/emacs/.bzr/repository/')(RepositoryFormat2a())
52.990  fetch up to rev {jasonr@gnu.org-20100819145109-17tqfx1uylo95ras}
[22809] 2010-08-19 22:58:21.431 INFO: Committed revision 101137.
487.501  return code 0


The second attempt failed, perhaps due to Stefan breaking the lock (as 
it failed in unlock self.confirm):

Thu 2010-08-19 23:07:28 +0800
0.052  bazaar version: 2.1.1
0.053  bzr arguments: [u'commit', u'-m', u'(set_frame_menubar): Remove 
call to undefined function.\n', u'src/ChangeLog', u'src/w32menu.c']
0.084  looking for plugins in /home/jasonr/.bazaar/plugins
0.085  looking for plugins in 
/usr/lib/python2.6/dist-packages/bzrlib/plugins
0.246  encoding stdout as osutils.get_user_encoding() 'UTF-8'
0.301  opening working tree '/home/jasonr/bzr/emacs/trunk'
0.606  ssh implementation is OpenSSH
29.123  preparing to commit
[23356] 2010-08-19 23:08:28.093 INFO: Committing to: 
sftp://jasonr@bzr.savannah.gnu.org/srv/bzr/emacs/trunk/
59.322  Selecting files for commit with filter [u'src/ChangeLog', 
u'src/w32menu.c']
[23356] 2010-08-19 23:08:28.202 INFO: modified src/ChangeLog
[23356] 2010-08-19 23:08:28.225 INFO: modified src/w32menu.c
59.631  Using fetch logic to copy between 
CHKInventoryRepository('file:///home/jasonr/bzr/emacs/.bzr/repository/')(RepositoryFormat2a()) 
and 
CHKInventoryRepository('sftp://jasonr@bzr.savannah.gnu.org/srv/bzr/emacs/.bzr/repository/')(RepositoryFormat2a())
59.631  fetch up to rev {jasonr@gnu.org-20100819150828-w2hw9ic7u7z9hfqp}
470.146  Raising exception with args ('Server connection dropped: ',)
470.146  Error suppressed by only_raises:
470.164  Traceback (most recent call last):
   File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 
222, in wrapped
     return unbound(*args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 319, 
in unlock
     self.confirm()
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 415, 
in confirm
     info = self.peek()
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 438, 
in peek
     info = self._read_info_file(self._held_info_path)
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 428, 
in _read_info_file
     return self._parse_info(self.transport.get_bytes(path))
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 435, in get_bytes
     f = self.get(relpath)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 431, in get
     failure_exc=errors.ReadError)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 721, in _translate_io_exception
     raise e
SSHException: Server connection dropped:

470.167  Error suppressed by only_raises:
470.208  Traceback (most recent call last):
   File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 
222, in wrapped
     return unbound(*args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 319, 
in unlock
     self.confirm()
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 415, 
in confirm
     info = self.peek()
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 438, 
in peek
     info = self._read_info_file(self._held_info_path)
   File "/usr/lib/python2.6/dist-packages/bzrlib/lockdir.py", line 428, 
in _read_info_file
     return self._parse_info(self.transport.get_bytes(path))
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 435, in get_bytes
     f = self.get(relpath)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 425, in get
     f = self._get_sftp().file(path, mode='rb')
   File "/usr/lib/pymodules/python2.6/paramiko/sftp_client.py", line 
245, in open
     t, msg = self._request(CMD_OPEN, filename, imode, attrblock)
   File "/usr/lib/pymodules/python2.6/paramiko/sftp_client.py", line 
627, in _request
     num = self._async_request(type(None), t, *arg)
   File "/usr/lib/pymodules/python2.6/paramiko/sftp_client.py", line 
649, in _async_request
     self._send_packet(t, str(msg))
   File "/usr/lib/pymodules/python2.6/paramiko/sftp.py", line 172, in 
_send_packet
     self._write_all(out)
   File "/usr/lib/pymodules/python2.6/paramiko/sftp.py", line 136, in 
_write_all
     n = self.sock.send(out)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/ssh.py", line 
194, in send
     return self.__socket.send(data)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/ssh.py", line 
665, in send
     return os.write(self.proc.stdin.fileno(), data)
OSError: [Errno 32] Broken pipe

470.313  Traceback (most recent call last):
   File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 853, 
in exception_to_return_code
     return the_callable(*args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 
1055, in run_bzr
     ret = run(*run_argv)
   File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 661, 
in run_argv_aliases
     return self.run_direct(**all_cmd_args)
   File "/usr/lib/python2.6/dist-packages/bzrlib/commands.py", line 665, 
in run_direct
     return self._operation.run_simple(*args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/cleanup.py", line 122, 
in run_simple
     self.cleanups, self.func, *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/cleanup.py", line 156, 
in _do_with_cleanups
     result = func(*args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/builtins.py", line 
3138, in run
     exclude=safe_relpath_files(tree, exclude))
   File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 
194, in write_locked
     result = unbound(self, *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/workingtree_4.py", line 
197, in commit
     result = WorkingTree3.commit(self, message, revprops, *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 
194, in write_locked
     result = unbound(self, *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/mutabletree.py", line 
225, in commit
     *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/commit.py", line 257, 
in commit
     possible_master_transports=possible_master_transports)
   File "/usr/lib/python2.6/dist-packages/bzrlib/cleanup.py", line 118, 
in run
     self.cleanups, self.func, self, *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/cleanup.py", line 156, 
in _do_with_cleanups
     result = func(*args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/commit.py", line 420, 
in _commit
     self.branch.repository, new_revno, self.rev_id)
   File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 924, 
in import_last_revision_info
     self.set_last_revision_info(revno, revid)
   File "/usr/lib/python2.6/dist-packages/bzrlib/decorators.py", line 
194, in write_locked
     result = unbound(self, *args, **kwargs)
   File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 2508, 
in set_last_revision_info
     if self._get_append_revisions_only():
   File "/usr/lib/python2.6/dist-packages/bzrlib/branch.py", line 2691, 
in _get_append_revisions_only
     value = self.get_config().get_user_option('append_revisions_only')
   File "/usr/lib/python2.6/dist-packages/bzrlib/config.py", line 187, 
in get_user_option
     return self._get_user_option(option_name)
   File "/usr/lib/python2.6/dist-packages/bzrlib/config.py", line 733, 
in _get_user_option
     value = source()._get_user_option(option_name)
   File "/usr/lib/python2.6/dist-packages/bzrlib/config.py", line 406, 
in _get_user_option
     value = self._get_parser().get_value(section, option_name)
   File "/usr/lib/python2.6/dist-packages/bzrlib/config.py", line 997, 
in _get_parser
     return self._config._get_configobj()
   File "/usr/lib/python2.6/dist-packages/bzrlib/config.py", line 1505, 
in _get_configobj
     return ConfigObj(self._get_config_file(), encoding='utf-8')
   File "/usr/lib/python2.6/dist-packages/bzrlib/config.py", line 1500, 
in _get_config_file
     return StringIO(self._transport.get_bytes(self._filename))
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 435, in get_bytes
     f = self.get(relpath)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/sftp.py", 
line 425, in get
     f = self._get_sftp().file(path, mode='rb')
   File "/usr/lib/pymodules/python2.6/paramiko/sftp_client.py", line 
245, in open
     t, msg = self._request(CMD_OPEN, filename, imode, attrblock)
   File "/usr/lib/pymodules/python2.6/paramiko/sftp_client.py", line 
627, in _request
     num = self._async_request(type(None), t, *arg)
   File "/usr/lib/pymodules/python2.6/paramiko/sftp_client.py", line 
649, in _async_request
     self._send_packet(t, str(msg))
   File "/usr/lib/pymodules/python2.6/paramiko/sftp.py", line 172, in 
_send_packet
     self._write_all(out)
   File "/usr/lib/pymodules/python2.6/paramiko/sftp.py", line 136, in 
_write_all
     n = self.sock.send(out)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/ssh.py", line 
194, in send
     return self.__socket.send(data)
   File "/usr/lib/python2.6/dist-packages/bzrlib/transport/ssh.py", line 
665, in send
     return os.write(self.proc.stdin.fileno(), data)
OSError: [Errno 32] Broken pipe

470.314  return code 3

By the time I'd tried again and failed due to my own stale locks (I'm 
not sure why - did bzr revive them after the above failure?), and then 
an out of date tree; updated the tree with Stefan's changes; and  
finally committed successfully, it had taken me 50 minutes to commit a 2 
line change!