Bazaar

Merge lp:~spiv/bzr/debug-flag-relock into lp:bzr

  1. debug-flag-relock
  2. Merge into bzr.dev
Proposed by Andrew Bennetts
Status: Merged
Merged at revision: not available
Proposed branch: lp:~spiv/bzr/debug-flag-relock
Merge into: lp:bzr
Diff against target: 231 lines
7 files modified
NEWS (+4/-0)
bzrlib/branch.py (+6/-1)
bzrlib/help_topics/en/debug-flags.txt (+5/-3)
bzrlib/lock.py (+21/-0)
bzrlib/remote.py (+6/-2)
bzrlib/repofmt/pack_repo.py (+7/-0)
bzrlib/repository.py (+4/-1)
To merge this branch: bzr merge lp:~spiv/bzr/debug-flag-relock
Reviewer Review Type Date Requested Status
Martin Pool Approve
John A Meinel Approve
Vincent Ladeuil Pending
Review via email: mp+12972@code.launchpad.net

This proposal supersedes a proposal from 2009-10-07.

To post a comment you must log in.
Revision history for this message
Andrew Bennetts (spiv) wrote : Posted in a previous version of this proposal

This is an idea I had while looking at bug 389413. It adds a -Drelock debug flag to make noise about cases where we probably should take more care to just hold one lock rather than locking/unlocking/locking-again.

Here's some sample output:

$ ./bzr diff -c 4148 . -Drelock > /dev/null
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again

Hopefully that gives some idea of how much we can improve :)

Possibly we should have a more generic hook point for lock/unlock operations so that tests can assert "object X is only locked once", similar to the existing HPSS effort tests... but this seems cheap and useful. (The existing hook points for lockdir lock_acquired/lock_released would only catch lock_write, not lock_read, so they aren't sufficient for this case.)

Revision history for this message
Martin Pool (mbp) wrote : Posted in a previous version of this proposal

That sounds good.

I think note() may not be the best interface to call because the ui
changes turn it into something more like "display a message to the
user" and you wouldn't want popup dialogs for each hit. But maybe
that's the best one for now and I can change it later.

So I think it's actually an idea for me to add a kind of 'loud mutter'
rather than a change for you.

The duplication is ugly though - I think you should put this into a
(possibly mixed in) base class.

--
Martin <http://launchpad.net/~mbp/>

Revision history for this message
Vincent Ladeuil (vila) wrote : Posted in a previous version of this proposal

More a tweak really.

You lost your 'manner' for --strict-locks in reordering the help messages.

review: Needs Fixing
Revision history for this message
Andrew Bennetts (spiv) wrote :

I've removed the duplication with a mixin, and fixed the 'manner' glitch in debug-flags.txt.

p.s.:
$ ./bzr -Drelock push
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
Using saved push location: lp:~spiv/bzr/debug-flag-relock
BzrBranch7('file:///home/andrew/warthogs/bzr/debug-flag-relock/') was read locked again
CHKInventoryRepository('file:///home/andrew/warthogs/bzr/.bzr/repository/') was read locked again
Pushed up to revision 4734.
HPSS calls: 23 (2 vfs) SmartSSHClientMedium(connected=False, username=u'spiv', host='bazaar.launchpad.net', port=None)

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

-----BEGIN PGP SIGNED MESSAGE-----
Hash: SHA1

Andrew Bennetts wrote:
> Andrew Bennetts has proposed merging lp:~spiv/bzr/debug-flag-relock into lp:bzr.
>
> Requested reviews:
> Martin Pool (mbp):
> Vincent Ladeuil (vila)
>
>

So do I understand correctly that this is only triggered when an object
*loses* the lock and then re-acquires it?

So doing:

foo.lock_read()
foo.lock_read()
foo.unlock()
foo.unlock()

would not trigger it, but

foo.lock_read()
foo.unlock()
foo.lock_read()
foo.unlock()

would.

I agree that we should probably have a hook, or some sort of mechanism
for testing this, as it is worthwhile to test. Perhaps you could have a
global state in "lock" like our "symbol_versioning.warn" functionality?

 review: approve

Subject to Martin/Vincent's vote, since they reviewed first.

John
=:->
-----BEGIN PGP SIGNATURE-----
Version: GnuPG v1.4.9 (Cygwin)
Comment: Using GnuPG with Mozilla - http://enigmail.mozdev.org/

iEYEARECAAYFAkrMmdwACgkQJdeBCYSNAAPRFwCgrTbQAjq8SDggQnngugjdyEpk
odkAoIaGHnfDPa0nYVkn6zVPgQekcLcS
=UHav
-----END PGP SIGNATURE-----

review: Approve
Revision history for this message
Andrew Bennetts (spiv) wrote :

John A Meinel wrote:
[...]
> So doing:
>
> foo.lock_read()
> foo.lock_read()
> foo.unlock()
> foo.unlock()
>
> would not trigger it, but
>
> foo.lock_read()
> foo.unlock()
> foo.lock_read()
> foo.unlock()
>
> would.

That's correct.

> I agree that we should probably have a hook, or some sort of mechanism
> for testing this, as it is worthwhile to test. Perhaps you could have a
> global state in "lock" like our "symbol_versioning.warn" functionality?

You mean so that tests can assert “X was locked once”, rather than so that
we can test this debug flag? I think that would be nice, but it's probably
best to let whoever writes the first test along those lines (quite possibly
me!) do that refactoring. i.e. I think it's easy to add this sort of thing
later, and that it is best to add this sort of thing when it will actually
be used so we know we got the API right.

-Andrew.

Revision history for this message
Martin Pool (mbp) :
review: Approve

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'NEWS'
2--- NEWS 2009-10-08 16:15:00 +0000
3+++ NEWS 2009-10-08 22:56:11 +0000
4@@ -202,6 +202,10 @@
5 Internals
6 *********
7
8+* Added ``-Drelock`` debug flag. It will ``note`` a message every time a
9+ repository or branch object is unlocked then relocked the same way.
10+ (Andrew Bennetts)
11+
12 * ``BTreeLeafParser.extract_key`` has been tweaked slightly to reduce
13 mallocs while parsing the index (approx 3=>1 mallocs per key read).
14 This results in a 10% speedup while reading an index.
15
16=== modified file 'bzrlib/branch.py'
17--- bzrlib/branch.py 2009-09-30 07:02:41 +0000
18+++ bzrlib/branch.py 2009-10-08 22:56:11 +0000
19@@ -49,6 +49,7 @@
20 from bzrlib.decorators import needs_read_lock, needs_write_lock, only_raises
21 from bzrlib.hooks import HookPoint, Hooks
22 from bzrlib.inter import InterObject
23+from bzrlib.lock import _RelockDebugMixin
24 from bzrlib import registry
25 from bzrlib.symbol_versioning import (
26 deprecated_in,
27@@ -2079,7 +2080,7 @@
28 _legacy_formats[0].network_name(), _legacy_formats[0].__class__)
29
30
31-class BzrBranch(Branch):
32+class BzrBranch(Branch, _RelockDebugMixin):
33 """A branch stored in the actual filesystem.
34
35 Note that it's "local" in the context of the filesystem; it doesn't
36@@ -2131,6 +2132,8 @@
37 return self.control_files.is_locked()
38
39 def lock_write(self, token=None):
40+ if not self.is_locked():
41+ self._note_lock('w')
42 # All-in-one needs to always unlock/lock.
43 repo_control = getattr(self.repository, 'control_files', None)
44 if self.control_files == repo_control or not self.is_locked():
45@@ -2146,6 +2149,8 @@
46 raise
47
48 def lock_read(self):
49+ if not self.is_locked():
50+ self._note_lock('r')
51 # All-in-one needs to always unlock/lock.
52 repo_control = getattr(self.repository, 'control_files', None)
53 if self.control_files == repo_control or not self.is_locked():
54
55=== modified file 'bzrlib/help_topics/en/debug-flags.txt'
56--- bzrlib/help_topics/en/debug-flags.txt 2009-08-20 05:02:45 +0000
57+++ bzrlib/help_topics/en/debug-flags.txt 2009-10-08 22:56:11 +0000
58@@ -22,16 +22,18 @@
59 -Dhttp Trace http connections, requests and responses.
60 -Dindex Trace major index operations.
61 -Dknit Trace knit operations.
62--Dstrict_locks Trace when OS locks are potentially used in a non-portable
63- manner.
64 -Dlock Trace when lockdir locks are taken or released.
65 -Dprogress Trace progress bar operations.
66 -Dmerge Emit information for debugging merges.
67 -Dno_apport Don't use apport to report crashes.
68--Dunlock Some errors during unlock are treated as warnings.
69 -Dpack Emit information about pack operations.
70+-Drelock Emit a message every time a branch or repository object is
71+ unlocked then relocked the same way.
72 -Dsftp Trace SFTP internals.
73 -Dstream Trace fetch streams.
74+-Dstrict_locks Trace when OS locks are potentially used in a non-portable
75+ manner.
76+-Dunlock Some errors during unlock are treated as warnings.
77 -DIDS_never Never use InterDifferingSerializer when fetching.
78 -DIDS_always Always use InterDifferingSerializer to fetch if appropriate
79 for the format, even for non-local fetches.
80
81=== modified file 'bzrlib/lock.py'
82--- bzrlib/lock.py 2009-07-31 16:51:48 +0000
83+++ bzrlib/lock.py 2009-10-08 22:56:11 +0000
84@@ -518,3 +518,24 @@
85 # We default to using the first available lock class.
86 _lock_type, WriteLock, ReadLock = _lock_classes[0]
87
88+
89+class _RelockDebugMixin(object):
90+ """Mixin support for -Drelock flag.
91+
92+ Add this as a base class then call self._note_lock with 'r' or 'w' when
93+ acquiring a read- or write-lock. If this object was previously locked (and
94+ locked the same way), and -Drelock is set, then this will trace.note a
95+ message about it.
96+ """
97+
98+ _prev_lock = None
99+
100+ def _note_lock(self, lock_type):
101+ if 'relock' in debug.debug_flags and self._prev_lock == lock_type:
102+ if lock_type == 'r':
103+ type_name = 'read'
104+ else:
105+ type_name = 'write'
106+ trace.note('%r was %s locked again', self, type_name)
107+ self._prev_lock = lock_type
108+
109
110=== modified file 'bzrlib/remote.py'
111--- bzrlib/remote.py 2009-10-08 01:50:30 +0000
112+++ bzrlib/remote.py 2009-10-08 22:56:11 +0000
113@@ -619,7 +619,7 @@
114 return self._custom_format._serializer
115
116
117-class RemoteRepository(_RpcHelper):
118+class RemoteRepository(_RpcHelper, lock._RelockDebugMixin):
119 """Repository accessed over rpc.
120
121 For the moment most operations are performed using local transport-backed
122@@ -949,6 +949,7 @@
123 def lock_read(self):
124 # wrong eventually - want a local lock cache context
125 if not self._lock_mode:
126+ self._note_lock('r')
127 self._lock_mode = 'r'
128 self._lock_count = 1
129 self._unstacked_provider.enable_cache(cache_misses=True)
130@@ -974,6 +975,7 @@
131
132 def lock_write(self, token=None, _skip_rpc=False):
133 if not self._lock_mode:
134+ self._note_lock('w')
135 if _skip_rpc:
136 if self._lock_token is not None:
137 if token != self._lock_token:
138@@ -2082,7 +2084,7 @@
139 return self._custom_format.supports_set_append_revisions_only()
140
141
142-class RemoteBranch(branch.Branch, _RpcHelper):
143+class RemoteBranch(branch.Branch, _RpcHelper, lock._RelockDebugMixin):
144 """Branch stored on a server accessed by HPSS RPC.
145
146 At the moment most operations are mapped down to simple file operations.
147@@ -2319,6 +2321,7 @@
148 def lock_read(self):
149 self.repository.lock_read()
150 if not self._lock_mode:
151+ self._note_lock('r')
152 self._lock_mode = 'r'
153 self._lock_count = 1
154 if self._real_branch is not None:
155@@ -2344,6 +2347,7 @@
156
157 def lock_write(self, token=None):
158 if not self._lock_mode:
159+ self._note_lock('w')
160 # Lock the branch and repo in one remote call.
161 remote_tokens = self._remote_lock_write(token)
162 self._lock_token, self._repo_lock_token = remote_tokens
163
164=== modified file 'bzrlib/repofmt/pack_repo.py'
165--- bzrlib/repofmt/pack_repo.py 2009-09-30 07:02:41 +0000
166+++ bzrlib/repofmt/pack_repo.py 2009-10-08 22:56:11 +0000
167@@ -73,6 +73,7 @@
168 )
169 from bzrlib.trace import (
170 mutter,
171+ note,
172 warning,
173 )
174
175@@ -2300,6 +2301,9 @@
176 if self._write_lock_count == 1:
177 self._transaction = transactions.WriteTransaction()
178 if not locked:
179+ if 'relock' in debug.debug_flags and self._prev_lock == 'w':
180+ note('%r was write locked again', self)
181+ self._prev_lock = 'w'
182 for repo in self._fallback_repositories:
183 # Writes don't affect fallback repos
184 repo.lock_read()
185@@ -2312,6 +2316,9 @@
186 else:
187 self.control_files.lock_read()
188 if not locked:
189+ if 'relock' in debug.debug_flags and self._prev_lock == 'r':
190+ note('%r was read locked again', self)
191+ self._prev_lock = 'r'
192 for repo in self._fallback_repositories:
193 repo.lock_read()
194 self._refresh_data()
195
196=== modified file 'bzrlib/repository.py'
197--- bzrlib/repository.py 2009-10-08 01:50:30 +0000
198+++ bzrlib/repository.py 2009-10-08 22:56:11 +0000
199@@ -50,6 +50,7 @@
200 """)
201
202 from bzrlib.decorators import needs_read_lock, needs_write_lock, only_raises
203+from bzrlib.lock import _RelockDebugMixin
204 from bzrlib.inter import InterObject
205 from bzrlib.inventory import (
206 Inventory,
207@@ -856,7 +857,7 @@
208 # Repositories
209
210
211-class Repository(object):
212+class Repository(_RelockDebugMixin):
213 """Repository holding history for one or more branches.
214
215 The repository holds and retrieves historical information including
216@@ -1381,6 +1382,7 @@
217 locked = self.is_locked()
218 result = self.control_files.lock_write(token=token)
219 if not locked:
220+ self._note_lock('w')
221 for repo in self._fallback_repositories:
222 # Writes don't affect fallback repos
223 repo.lock_read()
224@@ -1391,6 +1393,7 @@
225 locked = self.is_locked()
226 self.control_files.lock_read()
227 if not locked:
228+ self._note_lock('r')
229 for repo in self._fallback_repositories:
230 repo.lock_read()
231 self._refresh_data()