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