Bazaar

Merge lp:~lifeless/bzr/lsprof_lockout into lp:bzr

  1. lsprof_lockout
  2. Merge into bzr.dev
Proposed by Robert Collins
Status: Merged
Approved by: Robert Collins
Approved revision: no longer in the source branch.
Merged at revision: 5332
Proposed branch: lp:~lifeless/bzr/lsprof_lockout
Merge into: lp:bzr
Diff against target: 181 lines (+88/-14)
4 files modified
NEWS (+5/-0)
bzrlib/lsprof.py (+41/-13)
bzrlib/tests/__init__.py (+3/-0)
bzrlib/tests/test_lsprof.py (+39/-1)
To merge this branch: bzr merge lp:~lifeless/bzr/lsprof_lockout
Reviewer Review Type Date Requested Status
Martin Packman (community) Approve
bzr-core Pending
Review via email: mp+29165@code.launchpad.net

Commit message

Make lsprof usage serialise rather than generated corrupted results when used concurrently in a threaded application. Can now cause deadlocks when used reentrantly.

Description of the change

Make lsprof usage serialise rather than generated corrupted results when
used concurrently in a threaded application. Can now cause deadlocks when
used reentrantly.

I wanted to use lsprof in a webapp and realised it would be a terrible
mistake right now :)

Serialising has different characteristics to just profiling-one-thread,
but when you're profiling, locking out other work is usually the right
thing anyway. Note that non-profiling requests won't be locked out, but I
think that that is ok - and best handled by callers if it is in fact
needed.

To post a comment you must log in.
Revision history for this message
Martin Packman (gz) wrote :

The added locking makes sense to me, and tests pass locally (once an unrelated regression was removed). There's still the issue of bug 579185 before threaded profiling is actually much good for anything, but this is a clear prerequisite.

review: Approve
Revision history for this message
Robert Collins (lifeless) wrote :

sent to pqm by email

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'NEWS'
2--- NEWS 2010-06-30 08:35:19 +0000
3+++ NEWS 2010-07-04 06:36:28 +0000
4@@ -166,6 +166,11 @@
5 InterBranch objects that work with multiple permutations to be
6 comprehensively tested. (Robert Collins)
7
8+* ``bzrlib.lsprof.profile`` will no longer silently generate bad threaded
9+ profiles when concurrent profile requests are made. Instead the profile
10+ requests will be serialised. Reentrant requests will now deadlock.
11+ (Robert Collins)
12+
13 * ``bzrlib.knit.KnitSequenceMatcher``, which has been deprecated since
14 2007, has been deleted. Use ``PatienceSequenceMatcher`` from
15 ``bzrlib.patiencediff`` instead. (Andrew Bennetts)
16
17=== modified file 'bzrlib/lsprof.py'
18--- bzrlib/lsprof.py 2009-08-24 21:05:09 +0000
19+++ bzrlib/lsprof.py 2010-07-04 06:36:28 +0000
20@@ -10,6 +10,7 @@
21 import threading
22 from _lsprof import Profiler, profiler_entry
23
24+from bzrlib import errors
25
26 __all__ = ['profile', 'Stats']
27
28@@ -20,6 +21,9 @@
29 raised, pass in a closure that will catch the exceptions and transform them
30 appropriately for your driver function.
31
32+ Important caveat: only one profile can execute at a time. See BzrProfiler
33+ for details.
34+
35 :return: The functions return value and a stats object.
36 """
37 profiler = BzrProfiler()
38@@ -41,8 +45,21 @@
39 To use it, create a BzrProfiler and call start() on it. Some arbitrary
40 time later call stop() to stop profiling and retrieve the statistics
41 from the code executed in the interim.
42+
43+ Note that profiling involves a threading.Lock around the actual profiling.
44+ This is needed because profiling involves global manipulation of the python
45+ interpreter state. As such you cannot perform multiple profiles at once.
46+ Trying to do so will lock out the second profiler unless the global
47+ bzrlib.lsprof.BzrProfiler.profiler_block is set to 0. Setting it to 0 will
48+ cause profiling to fail rather than blocking.
49 """
50
51+ profiler_block = 1
52+ """Serialise rather than failing to profile concurrent profile requests."""
53+
54+ profiler_lock = threading.Lock()
55+ """Global lock used to serialise profiles."""
56+
57 def start(self):
58 """Start profiling.
59
60@@ -51,8 +68,16 @@
61 """
62 self._g_threadmap = {}
63 self.p = Profiler()
64- self.p.enable(subcalls=True)
65- threading.setprofile(self._thread_profile)
66+ permitted = self.__class__.profiler_lock.acquire(
67+ self.__class__.profiler_block)
68+ if not permitted:
69+ raise errors.InternalBzrError(msg="Already profiling something")
70+ try:
71+ self.p.enable(subcalls=True)
72+ threading.setprofile(self._thread_profile)
73+ except:
74+ self.__class__.profiler_lock.release()
75+ raise
76
77 def stop(self):
78 """Stop profiling.
79@@ -62,17 +87,20 @@
80
81 :return: A bzrlib.lsprof.Stats object.
82 """
83- self.p.disable()
84- for pp in self._g_threadmap.values():
85- pp.disable()
86- threading.setprofile(None)
87- p = self.p
88- self.p = None
89- threads = {}
90- for tid, pp in self._g_threadmap.items():
91- threads[tid] = Stats(pp.getstats(), {})
92- self._g_threadmap = None
93- return Stats(p.getstats(), threads)
94+ try:
95+ self.p.disable()
96+ for pp in self._g_threadmap.values():
97+ pp.disable()
98+ threading.setprofile(None)
99+ p = self.p
100+ self.p = None
101+ threads = {}
102+ for tid, pp in self._g_threadmap.items():
103+ threads[tid] = Stats(pp.getstats(), {})
104+ self._g_threadmap = None
105+ return Stats(p.getstats(), threads)
106+ finally:
107+ self.__class__.profiler_lock.release()
108
109 def _thread_profile(self, f, *args, **kwds):
110 # we lose the first profile point for a new thread in order to
111
112=== modified file 'bzrlib/tests/__init__.py'
113--- bzrlib/tests/__init__.py 2010-06-29 16:21:13 +0000
114+++ bzrlib/tests/__init__.py 2010-07-04 06:36:28 +0000
115@@ -3377,6 +3377,9 @@
116
117 def startTest(self, test):
118 self.profiler = bzrlib.lsprof.BzrProfiler()
119+ # Prevent deadlocks in tests that use lsprof: those tests will
120+ # unavoidably fail.
121+ bzrlib.lsprof.BzrProfiler.profiler_block = 0
122 self.profiler.start()
123 ForwardingResult.startTest(self, test)
124
125
126=== modified file 'bzrlib/tests/test_lsprof.py'
127--- bzrlib/tests/test_lsprof.py 2009-08-24 21:05:09 +0000
128+++ bzrlib/tests/test_lsprof.py 2010-07-04 06:36:28 +0000
129@@ -19,9 +19,10 @@
130
131 import cPickle
132 import os
133+import threading
134
135 import bzrlib
136-from bzrlib import tests
137+from bzrlib import errors, tests
138
139
140 class _LSProfFeature(tests.Feature):
141@@ -111,3 +112,40 @@
142 lines = [str(data) for data in stats.data]
143 lines = [line for line in lines if 'a_function' in line]
144 self.assertLength(1, lines)
145+
146+ def test_block_0(self):
147+ # When profiler_block is 0, reentrant profile requests fail.
148+ self.overrideAttr(bzrlib.lsprof.BzrProfiler, 'profiler_block', 0)
149+ inner_calls = []
150+ def inner():
151+ profiler = bzrlib.lsprof.BzrProfiler()
152+ self.assertRaises(errors.BzrError, profiler.start)
153+ inner_calls.append(True)
154+ bzrlib.lsprof.profile(inner)
155+ self.assertLength(1, inner_calls)
156+
157+ def test_block_1(self):
158+ # When profiler_block is 1, concurrent profiles serialise.
159+ # This is tested by manually acquiring the profiler lock, then
160+ # starting a thread that tries to profile, and releasing the lock.
161+ # We know due to test_block_0 that two profiles at once hit the lock,
162+ # so while this isn't perfect (we'd want a callback on the lock being
163+ # entered to allow lockstep evaluation of the actions), its good enough
164+ # to be confident regressions would be caught. Alternatively, if this
165+ # is flakey, a fake Lock object can be used to trace the calls made.
166+ calls = []
167+ def profiled():
168+ calls.append('profiled')
169+ def do_profile():
170+ bzrlib.lsprof.profile(profiled)
171+ calls.append('after_profiled')
172+ thread = threading.Thread(target=do_profile)
173+ bzrlib.lsprof.BzrProfiler.profiler_lock.acquire()
174+ try:
175+ try:
176+ thread.start()
177+ finally:
178+ bzrlib.lsprof.BzrProfiler.profiler_lock.release()
179+ finally:
180+ thread.join()
181+ self.assertLength(2, calls)