RE: AW: Patch to DorothyLocker
"Garth T Kidd" <garth-OnzZ1s1DREKDegMON/[email protected]> Sat, 25 Sep 2004 23:01:50 +1000
| Newsgroups | gmane.comp.pythin.pyds.devel |
|---|---|
| Organization | Deadly Bloody Serious |
| Message-ID | <[email protected]> |
This is a multi-part message in MIME format. ------=_NextPart_000_0019_01C4A353.A720BC50 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit Please find attached, a version with a lot more testing and adherence to pylint requirements; I'm thinking it's useful enough to be distributed in its own right. 40% of the code is now unit tests. :) I've also fixed a few bugs (yaay, tests!) and simplified some of the code. There's now just one list of things to ignore, for example, not two. Regards, Garth. -----Original Message----- From: pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected] [mailto:pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]] On Behalf Of Georg Bauer Sent: Friday, 24 September 2004 3:28 AM To: Thomas Klaeger Cc: Garth T Kidd; pyds-dev-iYtK5bfT9M//Ad8WF/[email protected] Subject: Re: AW: [Pyds-dev] Patch to DorothyLocker Hi! > The patch was wrong since thread.lock#acquire takes no keyword > arguments. It just needs to read acquire(1). Looks like that fixed it. At least it now starts fine, doesn't barf and stops fine on ctrl-c or sigkill. I commited it to CVS. Thanks. bye, Georg _______________________________________________ Pyds-dev mailing list Pyds-dev-iYtK5bfT9M//Ad8WF/[email protected] http://www.westfalen.de/cgi-bin/mailman/listinfo/pyds-dev ------=_NextPart_000_0019_01C4A353.A720BC50 Content-Type: application/octet-stream; name="20040925-1049-dorothyupdate.diff" Content-Transfer-Encoding: quoted-printable Content-Disposition: attachment; filename="20040925-1049-dorothyupdate.diff" Index: PyDS/Tool.py =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D RCS file: /pyds/PyDS/PyDS/Tool.py,v retrieving revision 1.196 diff -c -c -r1.196 Tool.py *** PyDS/Tool.py 23 Sep 2004 12:35:14 -0000 1.196 --- PyDS/Tool.py 25 Sep 2004 12:48:13 -0000 *************** *** 49,55 **** =20 import PyDS.StructuredText import PyDS.CommandQueue ! from PyDS.DorothyLocker import DorothyRLock, LockAssertionError, = print_minitrace import PyDS =20 version =3D 'Python Desktop Server %s (http://pyds.muensterland.org/)' = % PyDS.__version__ --- 49,55 ---- =20 import PyDS.StructuredText import PyDS.CommandQueue ! from PyDS.DorothyLocker import DorothyRLock, LockAssertionError import PyDS =20 version =3D 'Python Desktop Server %s (http://pyds.muensterland.org/)' = % PyDS.__version__ *************** *** 1144,1150 **** self.rss =3D 0 self.hasAPI =3D 1 if _PyDS.verbose: ! self.lock =3D DorothyRLock(verbose=3DNone, name=3D'%s.lock' % name) = else: self.lock =3D threading.RLock() self.lockedFrom =3D None --- 1144,1153 ---- self.rss =3D 0 self.hasAPI =3D 1 if _PyDS.verbose: ! self.lock =3D DorothyRLock(verbose=3DNone,=20 ! name=3D'%s.lock' % name, ! ignores=3D[self._acquire.func_code,=20 ! self._release.func_code])=20 else: self.lock =3D threading.RLock() self.lockedFrom =3D None *************** *** 1377,1389 **** def _acquire(self, blocking=3D1): try:=20 return self.lock.acquire(blocking) ! except LockAssertionError, e:=20 ! msg, frame, t =3D e ! print "%s caught; lock was acquired in frame id %d at time %s" % ( ! msg, id(frame), time.ctime(t)) ! print "Trace of the initial lock acquisition:" =09 ! print_minitrace(frame) ! print raise # let the caller know we had a problem except:=20 print "_acquire: " --- 1380,1387 ---- def _acquire(self, blocking=3D1): try:=20 return self.lock.acquire(blocking) ! except LockAssertionError, ex:=20 ! ex.print_diagnosis() raise # let the caller know we had a problem except:=20 print "_acquire: " *************** *** 1397,1408 **** try:=20 return self.lock.release() except LockAssertionError, e:=20 ! msg, frame, t =3D e ! print "%s caught; lock was acquired in frame id %d at time %s" % ( ! msg, id(frame), time.ctime(t)) ! print "Trace of the initial lock acquisition:" ! print_minitrace(frame) ! raise # let the caller know we had a problem except:=20 print "_release: " (e, d, tb) =3D sys.exc_info() --- 1395,1402 ---- try:=20 return self.lock.release() except LockAssertionError, e:=20 ! ex.print_diagnosis() ! raise except:=20 print "_release: " (e, d, tb) =3D sys.exc_info() Index: PyDS/DorothyLocker.py =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D= =3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D=3D RCS file: /pyds/PyDS/PyDS/DorothyLocker.py,v retrieving revision 1.2 diff -c -c -r1.2 DorothyLocker.py *** PyDS/DorothyLocker.py 14 Sep 2004 08:51:06 -0000 1.2 --- PyDS/DorothyLocker.py 25 Sep 2004 12:46:11 -0000 *************** *** 1,272 **** """ "There's no place like home." -- Dorothy =20 ! The DorothyLocker module provides a subclass of threading.RLock that=20 ! insists upon release() being called from the same execution frame that = ! acquire()d it in the first place. RLock itself is vulnerable to = missing=20 ! a release() or tossing in an acquire() too many times within a single=20 ! thread, and it won't show until some *other* thread tries to acquire a = ! lock you think is free, and blocks.=20 !=20 ! As a PyDS-specific feature, DorothyRLock skips functions named in = IGNORE.=20 ! This is because each tool routes calls to it's lock's acquire method=20 ! via PyDS.Tool._acquire, and similarly treats release. By ignoring = frames=20 ! from _acquire and _release, DorothyRLock can concentrate on the frames = ! actually causing the locks and releases.=20 """ =20 ! from threading import _RLock, currentThread, Thread import time import inspect import sys ! import traceback =20 ! IGNORE =3D ['_acquire', '_release'] =20 def ltrim_common(oblist1, oblist2):=20 ! "Return the arguments with all common first elements removed." ! for pos in range(min(len(oblist1), len(oblist2))):=20 ! if oblist1[pos] is not oblist2[pos]:=20 ! break ! else:=20 ! pos =3D pos + 1 ! return oblist1[pos:], oblist2[pos:] !=20 ! def extract_minitrace(frame): ! "Extract a mini-trace from a locking context." ! mycontext =3D context() ! items =3D [] ! while frame:=20 ! if frame in mycontext:=20 ! break ! items.append(( ! frame.f_code.co_filename,=20 ! frame.f_lineno,=20 ! frame.f_code.co_name)) ! frame =3D frame.f_back ! return items !=20 ! def print_minitrace(frame):=20 ! "Print a mini-trace from a locking context." ! for filename, line, name in extract_minitrace(frame):=20 ! print 'File "%s", line %d, in %s' % ( ! filename, line, name) ! =09 ! def context(ignorecodes=3D[], ignorenames=3D[]):=20 ! """Distil a calling context, ignoring certain code objects and=20 ! function names.""" ! try:=20 ! stack =3D inspect.stack() ! codestack =3D [] ! for frame, filename, lineno, co_name, lines, index in stack:=20 ! if frame.f_code is context.func_code \ ! or frame.f_code in ignorecodes \ ! or co_name in ignorenames:=20 ! continue ! codestack.append(frame) ! codestack.reverse() ! return tuple(codestack) ! finally:=20 ! del frame !=20 ! class ReleaseFailure(Exception):=20 ! "Raised if DorothyRLock detects a failure to release an acquired = lock." ! pass !=20 ! class DorothyRLock(_RLock):=20 ! """DorothyRLock insists upon release() being called from the same=20 ! execution frame that acquire()d it in the first place. Frames named=20 ! in DorothyLocker.IGNORE will be ignored. ! =09 ! If a subframe re-acquires, that's okay, so long as it releases before = ! acquire or release is called via further up the frame stack.""" ! =09 ! def __init__(self, verbose=3DNone):=20 ! "Initialise the RLock." ! _RLock.__init__(self, verbose) ! self.__threads =3D {} ! self.__ignores =3D [ ! self.acquire.func_code,=20 ! self.release.func_code, ! self.callContext.func_code] ! =09 ! def callContext(self):=20 ! "Distil our calling context, with instance-specific ignores." ! return context(self.__ignores, IGNORE) ! =09 ! def acquire(self, blocking=3D1):=20 ! """Acquire the lock, first checking that any previous locks have=20 ! been released.""" ! # First, get our context:=20 ! me =3D currentThread() ! myLocks =3D self.__threads.setdefault(me, []) ! mycontext, myt =3D self.callContext(), time.time() !=20 ! # If there were any locks...=20 ! if myLocks:=20 ! # Try to figure out whether the previous lock should have been=20 ! # released.=20 ! # TODO: shouldn't we check all the locks?=20 ! prevcontext, prevt =3D myLocks[-1] ! prevframe =3D prevcontext[-1] ! # eliminate the common parts of the call stack ! pc, mc =3D ltrim_common(prevcontext, mycontext) ! if pc: ! if mc:=20 ! # different parts of the call stack ! # =3D> failure to release ! raise ReleaseFailure, ("failure to release", prevframe, prevt) ! else:=20 ! # mc matched, but shorter ! # =3D> re-acquire from calling frame ! raise ReleaseFailure, ("failure to release", prevframe, prevt) ! else:=20 ! if mc:=20 ! # re-acquired from further down the call stack ! pass ! else:=20 ! # not pc AND not mc ! # =3D> identical contexts ! raise ReleaseFailure, ("frame re-called acquire", prevframe, = prevt) ! =09 ! # If we got this far, it's safe to lock.=20 ! if blocking:=20 ! result =3D _RLock.acquire(self, blocking=3D0) ! if not result:=20 ! # Whine whilst we wait for the lock to clear.=20 ! whiner =3D LockWhiner(self, mycontext, myt, prevcontext, prevt) ! whiner.start() ! result =3D _RLock.acquire(self, blocking) ! whiner.stop() ! else:=20 ! result =3D _RLock.acquire(self, blocking=3D0) ! =09 ! if result:=20 ! myLocks.append((mycontext, myt)) !=20 ! return result !=20 ! def release(self):=20 ! """Release the lock, first checking that we're releasing from the=20 ! same frame that acquired us.""" ! result =3D _RLock.release(self) # raises AssertionError if not = acquired in this thread ! context =3D self.callContext() ! me =3D currentThread() ! myLocks =3D self.__threads[me] ! prevcontext, prevt =3D myLocks[-1] ! if prevcontext =3D=3D context:=20 ! myLocks.pop() # Permament! myLocks is bound to the=20 ! # original, NOT a copy.=20 ! return # TODO: figure out whether this should return `result` ! raise ReleaseFailure, ("failure to release", prevcontext[-1], prevt) =20 class LockWhiner(Thread):=20 ! def __init__(self, dorothy, waitcontext, waittime, prevcontext, = prevtime, every=3D10):=20 ! Thread.__init__(self) ! self.dorothy =3D dorothy ! self.whineTime =3D waittime ! self.whineContext =3D waitcontext ! self.lockTime =3D prevtime ! self.lockContext =3D prevcontext ! self.whineEvery =3D every ! self.thread =3D currentThread() ! self.active =3D 1 ! self.setDaemon(1) # let PyDS shut down even if we're active ! =09 ! def stop(self):=20 ! self.stopTime =3D time.time() ! self.active =3D 0 ! print "%s: LockWhiner stopped; lock acquired after %.2f seconds" % ( ! time.ctime(self.stopTime),=20 ! self.stopTime - self.whineTime) !=20 ! def run(self):=20 ! try:=20 ! #import pprint ! #pprint.pprint(self.__dict__) ! self._run() ! except:=20 ! print "_LockWhiner.run: Bugger." ! (e, d, tb) =3D sys.exc_info() ! print 'Exception %s: %s' % (e, d) ! for row in traceback.extract_tb(tb): ! print repr(row) !=20 ! def _run(self):=20 ! fun =3D self.whineContext[-1][2] ! print "%s: LockWhiner started by %s thread %d" % (\ ! time.ctime(self.whineTime),=20 ! self.dorothy.name,=20 ! id(self.thread)) ! waits =3D 0 ! while self.active:=20 ! time.sleep(self.whineEvery) ! waits =3D waits + 1 ! now =3D time.time() ! print "%s: LockWhiner has been waiting for %.2fs" % ( ! time.ctime(), ! now - self.whineTime) ! if waits=3D=3D1:=20 ! print "-"*70 ! print "Just in case this is a deadlock, here's some additional " ! print "information for debugging purposes:\n" ! print "Lock obtained: %s" % (time.ctime(self.lockTime)) ! print "\nLock holding stack:" ! print_minitrace(self.lockContext[-1]) ! print "\nWaiting stack:"=20 ! print_minitrace(self.whineContext[-1]) ! print "\nLock held by:", ! lockOwner =3D self.dorothy._RLock__owner ! if lockOwner is None:=20 ! print "(None.)" ! else:=20 ! print id(lockOwner) ! print "-"*70 =20 if __name__ =3D=3D '__main__':=20 ! import pprint =20 ! nrl =3D DorothyRLock() ! def spit():=20 ! pprint.pprint(nrl.callContext()) ! def a():=20 ! spit() ! def b():=20 ! a() ! a() ! print ! b() ! def _release(): ! assert nrl.callContext()[-1].f_code.co_name !=3D '_release' ! _release() ! =09 ! nrl.acquire() ! nrl.release() !=20 ! def fail1_top():=20 ! fail1_mid1() ! fail1_mid2() ! def fail1_mid1():=20 ! nrl.acquire() ! def fail1_mid2():=20 ! nrl.release() !=20 ! def fail2_top():=20 ! fail2_mid1() ! fail2_mid2() ! def fail2_mid1():=20 ! nrl.acquire() ! def fail2_mid2():=20 ! nrl.acquire() ! nrl.release() !=20 ! for test in [fail1_top, fail2_top]:=20 ! try:=20 ! print "\nTest: %s" % test.func_name ! test() ! except ReleaseFailure, e:=20 ! msg, frame, t =3D e ! print "%s caught; lock was acquired in frame id %d at time %s" % ( ! msg, id(frame), time.ctime(t)) ! print_minitrace(frame) =20 --- 1,868 ---- """ "There's no place like home." -- Dorothy =20 ! The DorothyLocker module provides a reimplementation of = threading.RLock=20 ! that assists debugging lock contention problems by=20 !=20 ! a) checking whether any previous locks have been correctly released=20 ! before performing subsequent acquire() and release() calls, or=20 ! whenever sanity_check() is called; and !=20 ! b) giving stack trace information of the locking call context when=20 ! another thread has to wait too long for the lock to be released.=20 !=20 ! `DorothyRLock` will raise `LockAssertionError` exceptions for any lock = ! usage other than::=20 !=20 ! try:=20 ! lock.acquire() ! # do stuff ! finally:=20 ! lock.release() !=20 ! DorothyRLock does permit `RLock`'s nesting behaviour, without which = it'd=20 ! just be a normal `Lock`. Each method must, however, release the lock = if=20 ! it acquired it.=20 !=20 ! To support environments like PyDS in which an instance's lock is = managed=20 ! via bound acquire and release methods, DorothyRLock instances can be=20 ! configured with an ignore list. By ignoring frames from these methods, = ! DorothyRLock can concentrate on the frames actually causing the locks = and=20 ! releases. For more details, see the implementation of `IgnoreTests`. """ =20 ! import threading ! from threading import _Verbose, currentThread, Thread ! from thread import allocate_lock import time import inspect import sys ! import re ! import types !=20 ! __all__ =3D ['DorothyRLock', 'LockAssertionError', 'CallingContext'] =20 ! __revision__ =3D '$Id$' =20 def ltrim_common(oblist1, oblist2):=20 ! "Return the arguments with all common first elements removed." ! for pos in range(min(len(oblist1), len(oblist2))):=20 ! if not oblist1[pos] =3D=3D oblist2[pos]:=20 ! break ! else:=20 ! pos =3D pos + 1 ! return oblist1[pos:], oblist2[pos:] !=20 ! class FrameInfo(object):=20 ! "Frozen frame information." !=20 ! def __init__(self, frame):=20 ! "Initialise ourself from a frame." ! object.__init__(self) ! self.frame_id =3D id(frame) ! self.f_code =3D frame.f_code ! self.f_lineno =3D frame.f_lineno !=20 ! def __eq__(self, other):=20 ! "Does this refer to the same frame ID as the other?" ! return self.frame_id =3D=3D other.frame_id ! =20 ! class CallingContext(object):=20 ! """Object representing the calling context as a tuple of FrameInfo = ! objects, one per calling frame. The context is reversed so that=20 ! earlier frames are first, not last.""" !=20 ! def __init__(self, ignores=3DNone):=20 ! """Distil the calling context, ignoring nominated code objects = and=20 ! function names. ! =20 ! ignores -- a list of function names or code objects to ignore ! """ ! object.__init__(self) # good form ! self.when =3D time.time() ! self.thread =3D currentThread() ! frame =3D None ! if ignores is None:=20 ! ignores =3D [] ! try:=20 ! stack =3D inspect.stack() ! framestack =3D [] ! for frame, filename, lineno, co_name, lines, index in = stack:=20 ! if frame.f_code is self.__init__.im_func.func_code \ ! or frame.f_code in ignores or co_name in ignores:=20 ! continue ! assert type(frame) =3D=3D types.FrameType ! framestack.append(FrameInfo(frame)) ! framestack.reverse() ! self.framestack =3D tuple(framestack) ! finally:=20 ! del frame # apparently helpful with frame objects ! =20 ! def __getitem__(self, index):=20 ! "Get a frame from the context by number (-1 is most recent)." ! return self.framestack[index] !=20 ! def __len__(self):=20 ! "How many frames are in the context?" ! return len(self.framestack) !=20 ! def minitrace(self):=20 ! "Extract a mini-trace from the context." ! tups =3D [] ! for frame in self:=20 ! tups.append((frame.f_code.co_filename,=20 ! frame.f_lineno,=20 ! frame.f_code.co_name)) ! tups.reverse() ! return tups !=20 ! def formatted_minitrace(self):=20 ! "Return a formatted mini-trace of the context." ! lines =3D [] ! for filename, line, name in self.minitrace():=20 ! lines.append('File "%s", line %d, in %s' % ( ! filename, line, name)) ! return lines !=20 ! def print_minitrace(self, out=3DNone):=20 ! "Print a mini-trace of the context." ! if out is None:=20 ! out =3D sys.stdout ! print >> out, '\n'.join(self.formatted_minitrace()) ! =20 ! def consolidate_string(string):=20 ! """Consolidate a string, eliminating redundant whitespace. ! Intended to turn docstrings into single-line strings.""" ! return re.sub('\s+', ' ', string).strip() ! =20 ! class LockAssertionError(AssertionError):=20 ! "Raised if DorothyRLock detects a failure to release an acquired = lock." ! def __init__(self, lock_context, detection_context, message=3D""): = ! self.lock_context =3D lock_context ! self.detection_context =3D detection_context !=20 ! # If the user didn't specify a message, use our doc string. ! if not message:=20 ! message =3D consolidate_string(self.__doc__) ! self.message =3D message !=20 ! # Super call; good form, and helps anyone who looks at .args ! AssertionError.__init__(self, lock_context, detection_context, = ! message) !=20 ! def formatted_diagnosis(self):=20 ! "Return lines of a formatted diagnosis of the = LockAssertionError." ! name =3D self.__class__.__name__ ! dash =3D '-' * len(name) ! msg =3D [dash, name, dash, self.message] ! if self.detection_context:=20 ! msg.append("Detection context:") ! msg.extend([' '+line for line in=20 ! self.detection_context.formatted_minitrace()]) ! if self.lock_context:=20 ! msg.append("Lock context:") ! msg.extend([' '+line for line in=20 ! self.lock_context.formatted_minitrace()]) ! return msg !=20 ! def print_diagnosis(self, out=3DNone):=20 ! "Print a diagnosis of the LockAssertionError." ! if out is None:=20 ! out =3D sys.stdout ! print >> out, '\n'.join(self.formatted_diagnosis()) !=20 ! class LeftAcquiringFrame(LockAssertionError):=20 ! """The lock owner's call stack no longer contains the frame=20 ! from which the owner acquired the lock. This is almost certainly=20 ! a failure to release the lock.""" !=20 ! class ReleaseFromSubFrame(LockAssertionError):=20 ! """A sub-frame of the locking frame tried to release. Either the=20 ! locking frame failed to release, or the sub-frame failed to=20 ! acquire.""" !=20 ! class ReAcquireFromSameFrame(LockAssertionError):=20 ! """A frame tried to acquire again, indicating a probable release=20 ! in a method which has more than one acquire/release pair or which=20 ! acquires and releases inside a loop.""" !=20 ! class ReleaseFromForeignThread(LockAssertionError):=20 ! """An attempt to release the lock from a thread that didn't own = it.=20 ! Strictly speaking, this is probably a failure to acquire.""" !=20 ! class ReleaseOfUnAcquiredLock(LockAssertionError):=20 ! """An attempt to release an un-acquired lock. Probably caused by=20 ! failure to acquire.""" !=20 ! class DorothyRLock(_Verbose):=20 ! """DorothyRLock insists upon release() being called from the same=20 ! execution frame that acquire()d it in the first place. Frames = named=20 ! in DorothyLocker.IGNORE will be ignored. ! =20 ! If a subframe re-acquires, that's okay, so long as it releases = before=20 ! acquire or release is called via further up the frame stack.""" !=20 ! def squawk(cls):=20 ! "Let users know if we're in use." ! att =3D 'squawked' ! if not hasattr(cls, att):=20 ! msg =3D "Enabled verbose lock debugging via = DorothyLocker." ! dash =3D '-' * len(msg) ! print "\n%s\n%s\n%s\n" % (dash, msg, dash) ! setattr(cls, att, True) ! squawk =3D classmethod(squawk) ! =20 ! def __init__(self, verbose=3DNone, name=3D'(unknown)', = ignores=3DNone):=20 ! "Initialise the DorothyRLock." ! _Verbose.__init__(self, verbose) ! self.name =3D name ! self.__ignores =3D [ ! self.acquire.func_code,=20 ! self.release.func_code, ! self.call_context.func_code, ! self.sanity_check.func_code] ! if ignores is not None:=20 ! self.__ignores.extend(ignores) ! self.__owner =3D None ! self.__lockstack =3D [] ! self.__block =3D allocate_lock() ! self.__class__.squawk() ! =20 ! def call_context(self):=20 ! "Distil our calling context, with instance-specific ignores." ! return CallingContext(ignores=3Dself.__ignores) ! =20 ! def sanity_check(self):=20 ! """Perform a sanity check: if we're locked by this thread, and = ! the calling frame doesn't share the locking frame, we know the = ! locking frame didn't release. ! =20 ! Be careful calling this if you're about to release.""" !=20 ! self.__sanity_check('anytime', self.call_context()) !=20 ! def __sanity_check(self, mode, my_context):=20 ! """Perform sanity checks when asked by acquire, release, or = the=20 ! public sanity_check method. !=20 ! mode -- 'anytime', 'acquire', or 'release'. ! my_thread -- my thread object. ! my_context -- a CallingContext obtained via call_context. ! """ ! =20 ! assert mode in ['anytime', 'acquire', 'release'] !=20 ! owner =3D self.__owner !=20 ! if owner is my_context.thread:=20 ! lock_context =3D self.__lockstack[-1] ! # eliminate the common parts of the call stack ! lock_uniques, my_uniques =3D ltrim_common(lock_context, = my_context) ! if lock_uniques: ! # if my_uniques, it's different part of the call stack ! # if not my_uniques, we're in one of our calling = frames ! # this is bad nomatter what the sanity check mode ! raise LeftAcquiringFrame, (lock_context, my_context) ! else:=20 ! if my_uniques:=20 ! # we're further down the call stack from the = acquire,=20 ! # which is:=20 ! # * wrong for release,=20 ! # * fine for sanity check, and ! # * fine for acquire ! if mode =3D=3D 'release':=20 ! raise ReleaseFromSubFrame, (lock_context, = my_context) ! else:=20 ! # the contexts are identical, which is:=20 ! # * perfect for release, ! # * unusual for sanity_check, and ! # * highly unusual for acquire ! if mode =3D=3D 'acquire': ! raise ReAcquireFromSameFrame, (lock_context, = my_context) ! =20 ! elif owner is None:=20 ! # fine for sanity and acquire, bad for release ! if mode =3D=3D 'release':=20 ! raise ReleaseOfUnAcquiredLock, (None, my_context) !=20 ! else: # foreign owner ! # fine for sanity, acquire will happily block, bad for = release ! lock_context =3D self.__lockstack[-1] ! if mode =3D=3D 'release':=20 ! raise ReleaseFromForeignThread, (lock_context, = my_context) !=20 ! def acquire(self, blocking=3D1):=20 ! """Acquire the lock, first checking that any prior locks by = this=20 ! thread have been released if they're not still on our call = chain. ! """ ! =20 ! # First, get our context.=20 ! my_context =3D self.call_context() !=20 ! # Are we the owner?=20 ! # This check is safe because owner is me only if we've called=20 ! # acquire() from the same thread.=20 ! if self.__owner is my_context.thread:=20 ! # Try to figure out whether the previous lock should have = been=20 ! # released.=20 ! self.__sanity_check('acquire', my_context) !=20 ! # If we got this far, we're OK.=20 ! # Add our details to the lock stack and return success.=20 ! self.__lockstack.append(my_context) ! if __debug__:=20 ! self._note("%s.acquire(%s): recursive success", self, = blocking) ! return 1 ! =20 ! # The lock isn't owned by this thread. The only way to know = for ! # sure it isn't owned by anyone else is to acquire it. Let's = try=20 ! # doing it without blocking, first.=20 ! result =3D self.__block.acquire(0) ! =20 ! if not result: # Our attempt to lock failed.=20 ! if not blocking:=20 ! # If we didn't want a blocking call, we can fail = outright here.=20 ! if __debug__:=20 ! self._note("%s.acquire(%s): failure", self, = blocking) ! return 0 !=20 ! # We know for sure someone else had self.__block at the = time=20 ! # we tried to get it, but by now the ownership might have=20 ! # changed or it might have been released. So, we'll start = a=20 ! # LockWhiner and then perform a blocking wait.=20 ! whiner =3D LockWhiner(self, my_context) ! whiner.start() ! result =3D self.__block.acquire() ! =20 ! # We can ONLY get here if we succeeded... ! assert result # ... but you can never be too careful.=20 ! =20 ! # Stop the whiner.=20 ! whiner.stop() ! =20 ! # Success! Let's grab the goodies and run.=20 ! self.__owner =3D my_context.thread ! self.__lockstack =3D [my_context] ! if __debug__:=20 ! self._note("%s.acquire(%s): initial success", self, = blocking) ! return 1 !=20 ! def release(self):=20 ! """Release the lock, first checking that we're releasing from = the=20 ! same frame that acquired us.""" ! =20 ! # First, get our context.=20 ! my_context =3D self.call_context() !=20 ! # Raise an appropriate exception if we detect a problem or=20 ! # shouldn't release (say, because we don't own the lock).=20 ! self.__sanity_check('release', my_context) ! =20 ! # If we got here, all is well.=20 ! lock_context =3D self.__lockstack.pop() ! delay =3D my_context.when - lock_context.when ! if self.__lockstack:=20 ! if __debug__:=20 ! self._note("%s.release(): non-final release after = %.2fs",=20 ! self, delay) ! else:=20 ! if __debug__:=20 ! self._note("%s.release(): final release after %.2fs",=20 ! self, delay) ! self.__owner =3D None ! self.__block.release() ! # That better be the last statement that affects state, = because ! # a thread waiting in the middle of acquire() will soon be = ! # adjusting the state itself.=20 !=20 ! def __repr__(self):=20 ! "Return a representation of this object." ! return "<%s owned by %s with count %d>" % ( ! self.name,=20 ! self.__owner and self.__owner.getName(),=20 ! len(self.__lockstack)) !=20 ! def lock_details(self):=20 ! """Return top lock details: owner, lock count, top context, = time. ! Because of race conditions, details might not be = consistent.""" ! try:=20 ! lock_context =3D self.__lockstack[-1] ! except IndexError:=20 ! lock_context =3D None ! return self.__owner, len(self.__lockstack), lock_context =20 class LockWhiner(Thread):=20 ! """Thread that whines until a DorothyRLock.acquire() succeeds,=20 ! occasionally whining loudly with [hopefully] helpful debugging=20 ! information about the current owner of the lock.""" ! =20 ! def __init__(self, dorothy, whine_context, out=3DNone, every=3D6,=20 ! loudly_every=3DNone):=20 ! """Initialise the LockWhiner. ! =20 ! dorothy -- the lock for which we're waiting ! whine_context -- the call context that's waiting ! out -- file-like-object to whine to ! every -- how many seconds to wait between whines ! loudly_every -- how many seconds to wait between loud whines ! """ ! self.dorothy =3D dorothy ! self.whine_context =3D whine_context ! self.every =3D every ! if out is None:=20 ! out =3D sys.stdout ! self.out =3D out ! if loudly_every:=20 ! self.loudly_every =3D loudly_every ! else:=20 ! self.loudly_every =3D every * 10 ! self.active =3D 1 ! self.stop_time =3D 0 # filled in by stop() ! self.exc_info =3D None # filled in if necessary by run() !=20 ! # Super call -- enforced by Thread.start and other methods ! Thread.__init__(self) ! self.setDaemon(1) # let Python shut down even if we're still = active !=20 ! def stop(self):=20 ! """Ask the LockWhiner to stop.""" ! self.stop_time =3D time.time() ! self.active =3D 0 ! delay =3D self.stop_time - self.whine_context.when ! print >> self.out, "%s: LockWhiner %d stopped for %s; "\ ! "acquired by thread %d (%s) after %.2f seconds" % ( ! time.ctime(self.stop_time),=20 ! id(self),=20 ! self.dorothy.name,=20 ! id(self.whine_context.thread),=20 ! self.whine_context.thread.getName(), ! delay) !=20 ! def run(self):=20 ! """Whine until stopped.""" ! try:=20 ! self._run() ! except Exception:=20 ! # Stash the exception for later if we're supposed to still = ! # be waiting. If not, we probably crashed creating a = report=20 ! # because the lock changed status.=20 ! if self.active:=20 ! self.exc_info =3D sys.exc_info() !=20 ! def check(self):=20 ! """Check for exceptions caught by `run`.""" ! if self.exc_info is not None:=20 ! extype, exvalue, extraceback =3D self.exc_info ! raise extype, exvalue, extraceback !=20 ! def _run(self):=20 ! """Whine until stopped.""" ! out =3D self.out ! whine_time =3D self.whine_context.when ! print >> out, "%s: LockWhiner %d started for %s; "\ ! "thread %d (%s) waiting" % (\ ! time.ctime(whine_time),=20 ! id(self),=20 ! self.dorothy.name,=20 ! id(self.whine_context.thread), ! self.whine_context.thread.getName()) ! waits =3D 0 ! louds =3D int(self.loudly_every/self.every) ! while self.active:=20 ! time.sleep(self.every) ! if not self.active:=20 ! break ! waits =3D waits + 1 ! now =3D time.time() ! print >> out, "%s: LockWhiner %d has been waiting for = %.2fs" % ( ! time.ctime(now), ! id(self),=20 ! now - whine_time) ! if not (waits-1) % louds:=20 ! # Prepare a detailed complaint. This will fail if the=20 ! # lock is suddenly released and its state changes,=20 ! # but that won't stop any thread but the whiner.=20 ! msg =3D [] ! add =3D msg.append ! add("-"*70) ! add("Just in case this is a deadlock, here's some "\ ! "additional information") ! add("for debugging purposes:\n") ! owner, lock_count, lock_context =3D \ ! self.dorothy.lock_details() ! if lock_context is None:=20 ! time_rep =3D "(unknown)" ! else:=20 ! time_rep =3D time.ctime(lock_context.when) ! add("Lock most recently obtained at %s "\ ! "by thread id %d, name %s" % ( ! time_rep, id(owner), owner.getName())) ! add("Lock count by this thread: %d" % lock_count) ! if not owner.isAlive():=20 ! add("**THREAD IS DEAD**") ! add("\nLock holding stack:") ! if lock_context is None:=20 ! add("(unknown)") ! else: ! msg.extend(lock_context.formatted_minitrace()) ! if waits =3D=3D 1:=20 ! add("\nWaiting thread: id %d, name %s" % ( ! id(self.whine_context.thread),=20 ! self.whine_context.thread.getName())) ! add("\nWaiting stack:") ! = msg.extend(self.whine_context.formatted_minitrace()) ! add("-"*70) ! print >> out, '\n'.join(msg) =20 if __name__ =3D=3D '__main__':=20 ! import unittest ! import StringIO !=20 ! class CallingContextTests(unittest.TestCase):=20 ! "Tests of multi-threaded locking behaviour." !=20 ! # First, define some methods used by the tests.=20 ! # Argument funkiness used to pass arguments to CallingContext. = =20 ! def one(self, ignores=3DNone):=20 ! "Return whatever `two` returns." ! return self.two(ignores) ! =20 ! def two(self, ignores=3DNone):=20 ! "Return whatever 'three' returns." ! return self.three(ignores) ! =20 ! def three(self, ignores=3DNone): ! "Return `three`'s call context." ! return CallingContext(ignores) !=20 ! # Now, the tests:=20 !=20 ! def test_creation(self):=20 ! "Test call context creation" ! CallingContext() !=20 ! def test_basic(self):=20 ! "Basic context check" ! context =3D self.one() ! assert context[-1].f_code is self.three.func_code ! assert context[-2].f_code is self.two.func_code ! assert context[-3].f_code is self.one.func_code !=20 ! def test_ignorecodes(self):=20 ! "Make sure ignoring codes works" ! context =3D self.one(ignores=3D[self.three.func_code]) ! assert context[-1].f_code is self.two.func_code !=20 ! def test_ignorenames(self):=20 ! "Make sure ignoring names works" ! context =3D self.one(ignores=3D['three']) ! assert context[-1].f_code is self.two.func_code !=20 ! def test_getitem(self):=20 ! "Get last frame as context[-1]" ! context =3D self.one() ! context[-1] ! =20 ! def test_len(self):=20 ! "Return number of frames in context as len(context)" ! context =3D self.one() ! assert len(context) > 3 ! =20 ! def test_minitrace(self):=20 ! "Context mini-trace" ! context =3D self.one() ! minitrace =3D context.minitrace() ! assert isinstance(minitrace, list) ! for filename, lineno, name in minitrace:=20 ! assert isinstance(filename, basestring) ! assert isinstance(lineno, int) ! assert isinstance(name, basestring) ! assert minitrace[0][2] =3D=3D 'three' ! assert minitrace[0][0] =3D=3D __file__ ! =20 ! def test_formatted_minitrace(self):=20 ! "Formatted context mini-trace" ! context =3D self.one() ! formatted_minitrace =3D context.formatted_minitrace() ! assert isinstance(formatted_minitrace, list) !=20 ! def test_print_minitrace(self):=20 ! "Printed context mini-trace" ! out =3D StringIO.StringIO() ! context =3D self.one() ! context.print_minitrace(out) ! assert len(out.getvalue()) ! out.close() !=20 ! class BasicTests(unittest.TestCase):=20 ! "Basic tests." !=20 ! def test_creation(self):=20 ! "Creation" ! DorothyRLock() ! =20 ! def test_verbose_creation(self):=20 ! "Verbose creation" ! DorothyRLock(verbose=3DTrue) ! =20 ! def test_named_creation(self):=20 ! "Named creation" ! DorothyRLock(name=3D'lockName') ! =20 ! def test_verbose_named_creation(self):=20 ! "Verbose, named creation" ! DorothyRLock(verbose=3DTrue, name=3D'lockName') ! =20 ! def test_acquire_release(self):=20 ! "Basic acquisition and release" ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! dorothy.release() !=20 ! def test_mistaken_release_of_unacquired_lock(self):=20 ! "React properly to someone releasing an un-acquired lock" !=20 ! def mistaken_release_of_unacquired_lock():=20 ! "Release a lock without acquiring it." ! dorothy =3D DorothyRLock() ! dorothy.release() !=20 ! self.assertRaises(ReleaseOfUnAcquiredLock,=20 ! mistaken_release_of_unacquired_lock) !=20 ! def test_formatted_diagnosis(self):=20 ! "LockAssertionError formatted diagnostics" ! dorothy =3D DorothyRLock() ! try:=20 ! dorothy.acquire() ! dorothy.acquire() ! except LockAssertionError, ex:=20 ! formatted_diagnosis =3D ex.formatted_diagnosis() ! assert len(formatted_diagnosis) !=20 ! def test_printed_diagnosis(self):=20 ! "LockAssertionError printed diagnostics" ! dorothy =3D DorothyRLock() ! try:=20 ! dorothy.acquire() ! dorothy.acquire() ! except LockAssertionError, ex:=20 ! out =3D StringIO.StringIO() ! ex.print_diagnosis(out) ! assert len(out.getvalue()) ! out.close() ! =20 ! class ReleaseFailureTests(unittest.TestCase): ! "Tests of the release failure detection mechanism." !=20 ! def acquire_and_release(self, dorothy):=20 ! "Acquire and release `dorothy`. Used by tests." ! dorothy.acquire() ! dorothy.release() !=20 ! def acquire_with_no_release(self, dorothy):=20 ! "Acquire, but don't release, `dorothy`. Used by tests." ! dorothy.acquire() ! # didn't call dorothy.release() -- oops! ! =20 ! def release_with_no_acquire(self, dorothy):=20 ! "Release, but don't acquire, `dorothy`. Used by tests." ! # didn't call dorothy.acquire() -- oops! ! dorothy.release() ! =20 ! def test_boxed_pairs(self):=20 ! "Permit subframes to re-acquire" ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! self.acquire_and_release(dorothy) ! dorothy.release() !=20 ! def test_release_from_calling_frame(self):=20 ! "Detect release failure when a calling frame releases" !=20 ! def release_from_calling_frame():=20 ! "Force `LeftAcquiringFrame`." ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! self.acquire_with_no_release(dorothy) ! dorothy.release() ! =20 ! self.assertRaises(LeftAcquiringFrame, = release_from_calling_frame) !=20 ! def test_release_from_sub_frame(self):=20 ! "Detect acquire failure when a sub-frame releases" !=20 ! def release_from_sub_frame():=20 ! "Force `ReleaseFromSubFrame`." ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! self.release_with_no_acquire(dorothy) ! dorothy.release() ! =20 ! self.assertRaises(ReleaseFromSubFrame, = release_from_sub_frame) !=20 ! def test_reacquire_from_calling_frame(self):=20 ! "Detect release failure when a calling frame re-acquires" !=20 ! def reacquire_from_calling_frame():=20 ! "Force `LeftAcquiringFrame`." ! dorothy =3D DorothyRLock() ! self.acquire_with_no_release(dorothy) ! dorothy.acquire() ! =20 ! self.assertRaises(LeftAcquiringFrame, = reacquire_from_calling_frame) ! =20 ! def test_reacquire_from_foreign_frame(self):=20 ! "Detect release failure when the lock is re-acquired from = elsewhere" !=20 ! def reacquire_from_foreign_frame(): ! "Force `LeftAcquiringFrame`." ! dorothy =3D DorothyRLock() ! self.acquire_with_no_release(dorothy) ! # the second time around, this is a different *frame*=20 ! # despite it being the same callable object ! self.acquire_with_no_release(dorothy) !=20 ! self.assertRaises(LeftAcquiringFrame, = reacquire_from_foreign_frame) ! =20 ! def test_reacquire_from_same_frame(self):=20 ! "Detect release failure when lock re-acquired from the = same frame" !=20 ! def reacquire_from_same_frame(): ! "Force `ReAcquireFromSameFrame`." ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! dorothy.acquire() !=20 ! self.assertRaises(ReAcquireFromSameFrame, = reacquire_from_same_frame) ! =20 ! class LockSittingThread(threading.Thread):=20 ! "Thread that sits on a lock. Automatically starts itself" !=20 ! def __init__(self, lock):=20 ! "Initialise and start the `LockSittingThread`." ! self.lock =3D lock ! self.acquired =3D 0 ! self.keepGoing =3D 1 ! threading.Thread.__init__(self) ! self.setDaemon(1) # lets test suite exit if thread still = going !=20 ! # start, and wait for acquisition ! self.start() ! while not self.acquired:=20 ! time.sleep(0.1) ! =20 ! def run(self):=20 ! "In the thread: acquire the lock, wait, and release when = told." ! self.lock.acquire() ! self.acquired =3D 1 ! while self.keepGoing:=20 ! time.sleep(0.1) ! self.lock.release() !=20 ! def stop(self):=20 ! "Ask the thread to stop and release, and wait for it to = obey." ! self.keepGoing =3D 0 ! self.join() ! =20 ! class MultiThreadedTests(unittest.TestCase):=20 ! "Tests of multi-threaded locking behaviour." !=20 ! def test_nonblocking_acquire_of_acquired_lock(self):=20 ! "Fail non-blocking acquires of a lock acquired by another = thread" ! dorothy =3D DorothyRLock() ! sitter =3D LockSittingThread(dorothy) ! self.assert_(not dorothy.acquire(0)) ! sitter.stop() !=20 ! def test_foreign_release(self):=20 ! "Catch one thread releasing a lock acquired by another = thread" ! dorothy =3D DorothyRLock() ! sitter =3D LockSittingThread(dorothy) ! self.assertRaises(ReleaseFromForeignThread, = dorothy.release) ! sitter.stop() !=20 ! class IgnoreTests(unittest.TestCase):=20 ! """Tests of CallContext's ignore behaviour as used by = DorothyRLock. ! Also demonstrates the use case for ignores: an instance with a = ! private lock to which it needs to grant controlled access from = ! other objects.""" !=20 ! def setUp(self):=20 ! "Set up the private lock." ! self.__dorothy =3D DorothyRLock(ignores=3D[ ! self.acquire.func_code, self.release.func_code]) !=20 ! def acquire(self): ! "Acquire the private lock." ! self.__dorothy.acquire() !=20 ! def release(self):=20 ! "Release the private lock." ! self.__dorothy.release() !=20 ! def test_ignores(self):=20 ! """Verify instance's acquire and release methods are = ignored=20 ! for the purpose of DorothyRLock's context comparisons.""" ! self.acquire() ! self.release() !=20 ! class LockWhinerTests(unittest.TestCase):=20 ! "Tests of the `LockWhiner`." !=20 ! def test_creation(self):=20 ! "LockWhiner creation" ! dorothy =3D DorothyRLock() ! LockWhiner(dorothy, CallingContext()) !=20 ! def test_fast_creation(self):=20 ! "Fast LockWhiner creation" ! dorothy =3D DorothyRLock() ! LockWhiner(dorothy, CallingContext(), every=3D0.1) !=20 ! def test_startstop(self):=20 ! "LockWhiner start and stop" ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! # whine on behalf of this context into a StringIO object. ! out =3D StringIO.StringIO() ! context =3D CallingContext() ! whiner =3D LockWhiner(dorothy, context, every=3D0.1, = out=3Dout) ! whiner.start() # start it ! whiner.stop() # ask it to stop ! whiner.join(whiner.every + 1) # wait for it to stop = running ! assert not whiner.isAlive() # fail test if we timed out = waiting ! whiner.check() # raise any exceptions caught by = LockWhiner.run !=20 ! def test_whinereports(self):=20 ! "LockWhiner whining" ! dorothy =3D DorothyRLock() ! dorothy.acquire() ! out =3D StringIO.StringIO() ! context =3D CallingContext() ! whiner =3D LockWhiner(dorothy, context, every=3D0.1, = out=3Dout) ! whiner.start() # start it !=20 ! # Now, make sure there's some output.=20 ! time.sleep(0.2) # wait a while ! output1 =3D out.getvalue() ! assert len(output1), "no whining detected" !=20 ! time.sleep(0.2) # wait some more ! output2 =3D out.getvalue() ! assert len(output2)>len(output1), "no additional whining = detected" !=20 ! # See if we can get a full report ! time.sleep(1) ! output3 =3D out.getvalue() ! assert output3.find("additional information") >=3D 0, \ ! "no report detected" !=20 ! whiner.stop() # ask it to stop ! whiner.join(whiner.every + 1) # wait for it to stop = running ! assert not whiner.isAlive() # fail test if we timed out = waiting ! whiner.check() # raise any exceptions caught by = LockWhiner.run =20 + # Run the tests. + unittest.main() ------=_NextPart_000_0019_01C4A353.A720BC50 Content-Type: text/plain; name="DorothyLocker.py" Content-Transfer-Encoding: quoted-printable Content-Disposition: attachment; filename="DorothyLocker.py" """ "There's no place like home." -- Dorothy The DorothyLocker module provides a reimplementation of threading.RLock=20 that assists debugging lock contention problems by=20 a) checking whether any previous locks have been correctly released=20 before performing subsequent acquire() and release() calls, or=20 whenever sanity_check() is called; and b) giving stack trace information of the locking call context when=20 another thread has to wait too long for the lock to be released.=20 `DorothyRLock` will raise `LockAssertionError` exceptions for any lock=20 usage other than::=20 try:=20 lock.acquire() # do stuff finally:=20 lock.release() DorothyRLock does permit `RLock`'s nesting behaviour, without which it'd = just be a normal `Lock`. Each method must, however, release the lock if=20 it acquired it.=20 To support environments like PyDS in which an instance's lock is managed = via bound acquire and release methods, DorothyRLock instances can be=20 configured with an ignore list. By ignoring frames from these methods,=20 DorothyRLock can concentrate on the frames actually causing the locks = and=20 releases. For more details, see the implementation of `IgnoreTests`. """ import threading from threading import _Verbose, currentThread, Thread from thread import allocate_lock import time import inspect import sys import re import types __all__ =3D ['DorothyRLock', 'LockAssertionError', 'CallingContext'] __revision__ =3D '$Id$' def ltrim_common(oblist1, oblist2):=20 "Return the arguments with all common first elements removed." for pos in range(min(len(oblist1), len(oblist2))):=20 if not oblist1[pos] =3D=3D oblist2[pos]:=20 break else:=20 pos =3D pos + 1 return oblist1[pos:], oblist2[pos:] class FrameInfo(object):=20 "Frozen frame information." def __init__(self, frame):=20 "Initialise ourself from a frame." object.__init__(self) self.frame_id =3D id(frame) self.f_code =3D frame.f_code self.f_lineno =3D frame.f_lineno def __eq__(self, other):=20 "Does this refer to the same frame ID as the other?" return self.frame_id =3D=3D other.frame_id =20 class CallingContext(object):=20 """Object representing the calling context as a tuple of FrameInfo=20 objects, one per calling frame. The context is reversed so that=20 earlier frames are first, not last.""" def __init__(self, ignores=3DNone):=20 """Distil the calling context, ignoring nominated code objects = and=20 function names. =20 ignores -- a list of function names or code objects to ignore """ object.__init__(self) # good form self.when =3D time.time() self.thread =3D currentThread() frame =3D None if ignores is None:=20 ignores =3D [] try:=20 stack =3D inspect.stack() framestack =3D [] for frame, filename, lineno, co_name, lines, index in stack: = if frame.f_code is self.__init__.im_func.func_code \ or frame.f_code in ignores or co_name in ignores:=20 continue assert type(frame) =3D=3D types.FrameType framestack.append(FrameInfo(frame)) framestack.reverse() self.framestack =3D tuple(framestack) finally:=20 del frame # apparently helpful with frame objects =20 def __getitem__(self, index):=20 "Get a frame from the context by number (-1 is most recent)." return self.framestack[index] def __len__(self):=20 "How many frames are in the context?" return len(self.framestack) def minitrace(self):=20 "Extract a mini-trace from the context." tups =3D [] for frame in self:=20 tups.append((frame.f_code.co_filename,=20 frame.f_lineno,=20 frame.f_code.co_name)) tups.reverse() return tups def formatted_minitrace(self):=20 "Return a formatted mini-trace of the context." lines =3D [] for filename, line, name in self.minitrace():=20 lines.append('File "%s", line %d, in %s' % ( filename, line, name)) return lines def print_minitrace(self, out=3DNone):=20 "Print a mini-trace of the context." if out is None:=20 out =3D sys.stdout print >> out, '\n'.join(self.formatted_minitrace()) =20 def consolidate_string(string):=20 """Consolidate a string, eliminating redundant whitespace. Intended to turn docstrings into single-line strings.""" return re.sub('\s+', ' ', string).strip() =20 class LockAssertionError(AssertionError):=20 "Raised if DorothyRLock detects a failure to release an acquired = lock." def __init__(self, lock_context, detection_context, message=3D""):=20 self.lock_context =3D lock_context self.detection_context =3D detection_context # If the user didn't specify a message, use our doc string. if not message:=20 message =3D consolidate_string(self.__doc__) self.message =3D message # Super call; good form, and helps anyone who looks at .args AssertionError.__init__(self, lock_context, detection_context,=20 message) def formatted_diagnosis(self):=20 "Return lines of a formatted diagnosis of the = LockAssertionError." name =3D self.__class__.__name__ dash =3D '-' * len(name) msg =3D [dash, name, dash, self.message] if self.detection_context:=20 msg.append("Detection context:") msg.extend([' '+line for line in=20 self.detection_context.formatted_minitrace()]) if self.lock_context:=20 msg.append("Lock context:") msg.extend([' '+line for line in=20 self.lock_context.formatted_minitrace()]) return msg def print_diagnosis(self, out=3DNone):=20 "Print a diagnosis of the LockAssertionError." if out is None:=20 out =3D sys.stdout print >> out, '\n'.join(self.formatted_diagnosis()) class LeftAcquiringFrame(LockAssertionError):=20 """The lock owner's call stack no longer contains the frame=20 from which the owner acquired the lock. This is almost certainly=20 a failure to release the lock.""" class ReleaseFromSubFrame(LockAssertionError):=20 """A sub-frame of the locking frame tried to release. Either the=20 locking frame failed to release, or the sub-frame failed to=20 acquire.""" class ReAcquireFromSameFrame(LockAssertionError):=20 """A frame tried to acquire again, indicating a probable release=20 in a method which has more than one acquire/release pair or which=20 acquires and releases inside a loop.""" class ReleaseFromForeignThread(LockAssertionError):=20 """An attempt to release the lock from a thread that didn't own it.=20 Strictly speaking, this is probably a failure to acquire.""" class ReleaseOfUnAcquiredLock(LockAssertionError):=20 """An attempt to release an un-acquired lock. Probably caused by=20 failure to acquire.""" class DorothyRLock(_Verbose):=20 """DorothyRLock insists upon release() being called from the same=20 execution frame that acquire()d it in the first place. Frames named=20 in DorothyLocker.IGNORE will be ignored. =20 If a subframe re-acquires, that's okay, so long as it releases = before=20 acquire or release is called via further up the frame stack.""" def squawk(cls):=20 "Let users know if we're in use." att =3D 'squawked' if not hasattr(cls, att):=20 msg =3D "Enabled verbose lock debugging via DorothyLocker." dash =3D '-' * len(msg) print "\n%s\n%s\n%s\n" % (dash, msg, dash) setattr(cls, att, True) squawk =3D classmethod(squawk) =20 def __init__(self, verbose=3DNone, name=3D'(unknown)', = ignores=3DNone):=20 "Initialise the DorothyRLock." _Verbose.__init__(self, verbose) self.name =3D name self.__ignores =3D [ self.acquire.func_code,=20 self.release.func_code, self.call_context.func_code, self.sanity_check.func_code] if ignores is not None:=20 self.__ignores.extend(ignores) self.__owner =3D None self.__lockstack =3D [] self.__block =3D allocate_lock() self.__class__.squawk() =20 def call_context(self):=20 "Distil our calling context, with instance-specific ignores." return CallingContext(ignores=3Dself.__ignores) =20 def sanity_check(self):=20 """Perform a sanity check: if we're locked by this thread, and=20 the calling frame doesn't share the locking frame, we know the=20 locking frame didn't release. =20 Be careful calling this if you're about to release.""" self.__sanity_check('anytime', self.call_context()) def __sanity_check(self, mode, my_context):=20 """Perform sanity checks when asked by acquire, release, or the=20 public sanity_check method. mode -- 'anytime', 'acquire', or 'release'. my_thread -- my thread object. my_context -- a CallingContext obtained via call_context. """ =20 assert mode in ['anytime', 'acquire', 'release'] owner =3D self.__owner if owner is my_context.thread:=20 lock_context =3D self.__lockstack[-1] # eliminate the common parts of the call stack lock_uniques, my_uniques =3D ltrim_common(lock_context, = my_context) if lock_uniques: # if my_uniques, it's different part of the call stack # if not my_uniques, we're in one of our calling frames # this is bad nomatter what the sanity check mode raise LeftAcquiringFrame, (lock_context, my_context) else:=20 if my_uniques:=20 # we're further down the call stack from the = acquire,=20 # which is:=20 # * wrong for release,=20 # * fine for sanity check, and # * fine for acquire if mode =3D=3D 'release':=20 raise ReleaseFromSubFrame, (lock_context, = my_context) else:=20 # the contexts are identical, which is:=20 # * perfect for release, # * unusual for sanity_check, and # * highly unusual for acquire if mode =3D=3D 'acquire': raise ReAcquireFromSameFrame, (lock_context, = my_context) =20 elif owner is None:=20 # fine for sanity and acquire, bad for release if mode =3D=3D 'release':=20 raise ReleaseOfUnAcquiredLock, (None, my_context) else: # foreign owner # fine for sanity, acquire will happily block, bad for = release lock_context =3D self.__lockstack[-1] if mode =3D=3D 'release':=20 raise ReleaseFromForeignThread, (lock_context, = my_context) def acquire(self, blocking=3D1):=20 """Acquire the lock, first checking that any prior locks by this = thread have been released if they're not still on our call = chain. """ =20 # First, get our context.=20 my_context =3D self.call_context() # Are we the owner?=20 # This check is safe because owner is me only if we've called=20 # acquire() from the same thread.=20 if self.__owner is my_context.thread:=20 # Try to figure out whether the previous lock should have = been=20 # released.=20 self.__sanity_check('acquire', my_context) # If we got this far, we're OK.=20 # Add our details to the lock stack and return success.=20 self.__lockstack.append(my_context) if __debug__:=20 self._note("%s.acquire(%s): recursive success", self, = blocking) return 1 =20 # The lock isn't owned by this thread. The only way to know for # sure it isn't owned by anyone else is to acquire it. Let's try = # doing it without blocking, first.=20 result =3D self.__block.acquire(0) =20 if not result: # Our attempt to lock failed.=20 if not blocking:=20 # If we didn't want a blocking call, we can fail = outright here.=20 if __debug__:=20 self._note("%s.acquire(%s): failure", self, = blocking) return 0 # We know for sure someone else had self.__block at the time = # we tried to get it, but by now the ownership might have=20 # changed or it might have been released. So, we'll start a=20 # LockWhiner and then perform a blocking wait.=20 whiner =3D LockWhiner(self, my_context) whiner.start() result =3D self.__block.acquire() =20 # We can ONLY get here if we succeeded... assert result # ... but you can never be too careful.=20 =20 # Stop the whiner.=20 whiner.stop() =20 # Success! Let's grab the goodies and run.=20 self.__owner =3D my_context.thread self.__lockstack =3D [my_context] if __debug__:=20 self._note("%s.acquire(%s): initial success", self, = blocking) return 1 def release(self):=20 """Release the lock, first checking that we're releasing from = the=20 same frame that acquired us.""" =20 # First, get our context.=20 my_context =3D self.call_context() # Raise an appropriate exception if we detect a problem or=20 # shouldn't release (say, because we don't own the lock).=20 self.__sanity_check('release', my_context) =20 # If we got here, all is well.=20 lock_context =3D self.__lockstack.pop() delay =3D my_context.when - lock_context.when if self.__lockstack:=20 if __debug__:=20 self._note("%s.release(): non-final release after = %.2fs",=20 self, delay) else:=20 if __debug__:=20 self._note("%s.release(): final release after %.2fs",=20 self, delay) self.__owner =3D None self.__block.release() # That better be the last statement that affects state, = because # a thread waiting in the middle of acquire() will soon be=20 # adjusting the state itself.=20 def __repr__(self):=20 "Return a representation of this object." return "<%s owned by %s with count %d>" % ( self.name,=20 self.__owner and self.__owner.getName(),=20 len(self.__lockstack)) def lock_details(self):=20 """Return top lock details: owner, lock count, top context, = time. Because of race conditions, details might not be consistent.""" try:=20 lock_context =3D self.__lockstack[-1] except IndexError:=20 lock_context =3D None return self.__owner, len(self.__lockstack), lock_context class LockWhiner(Thread):=20 """Thread that whines until a DorothyRLock.acquire() succeeds,=20 occasionally whining loudly with [hopefully] helpful debugging=20 information about the current owner of the lock.""" =20 def __init__(self, dorothy, whine_context, out=3DNone, every=3D6,=20 loudly_every=3DNone):=20 """Initialise the LockWhiner. =20 dorothy -- the lock for which we're waiting whine_context -- the call context that's waiting out -- file-like-object to whine to every -- how many seconds to wait between whines loudly_every -- how many seconds to wait between loud whines """ self.dorothy =3D dorothy self.whine_context =3D whine_context self.every =3D every if out is None:=20 out =3D sys.stdout self.out =3D out if loudly_every:=20 self.loudly_every =3D loudly_every else:=20 self.loudly_every =3D every * 10 self.active =3D 1 self.stop_time =3D 0 # filled in by stop() self.exc_info =3D None # filled in if necessary by run() # Super call -- enforced by Thread.start and other methods Thread.__init__(self) self.setDaemon(1) # let Python shut down even if we're still = active def stop(self):=20 """Ask the LockWhiner to stop.""" self.stop_time =3D time.time() self.active =3D 0 delay =3D self.stop_time - self.whine_context.when print >> self.out, "%s: LockWhiner %d stopped for %s; "\ "acquired by thread %d (%s) after %.2f seconds" % ( time.ctime(self.stop_time),=20 id(self),=20 self.dorothy.name,=20 id(self.whine_context.thread),=20 self.whine_context.thread.getName(), delay) def run(self):=20 """Whine until stopped.""" try:=20 self._run() except Exception:=20 # Stash the exception for later if we're supposed to still=20 # be waiting. If not, we probably crashed creating a report=20 # because the lock changed status.=20 if self.active:=20 self.exc_info =3D sys.exc_info() def check(self):=20 """Check for exceptions caught by `run`.""" if self.exc_info is not None:=20 extype, exvalue, extraceback =3D self.exc_info raise extype, exvalue, extraceback def _run(self):=20 """Whine until stopped.""" out =3D self.out whine_time =3D self.whine_context.when print >> out, "%s: LockWhiner %d started for %s; "\ "thread %d (%s) waiting" % (\ time.ctime(whine_time),=20 id(self),=20 self.dorothy.name,=20 id(self.whine_context.thread), self.whine_context.thread.getName()) waits =3D 0 louds =3D int(self.loudly_every/self.every) while self.active:=20 time.sleep(self.every) if not self.active:=20 break waits =3D waits + 1 now =3D time.time() print >> out, "%s: LockWhiner %d has been waiting for %.2fs" = % ( time.ctime(now), id(self),=20 now - whine_time) if not (waits-1) % louds:=20 # Prepare a detailed complaint. This will fail if the=20 # lock is suddenly released and its state changes,=20 # but that won't stop any thread but the whiner.=20 msg =3D [] add =3D msg.append add("-"*70) add("Just in case this is a deadlock, here's some "\ "additional information") add("for debugging purposes:\n") owner, lock_count, lock_context =3D \ self.dorothy.lock_details() if lock_context is None:=20 time_rep =3D "(unknown)" else:=20 time_rep =3D time.ctime(lock_context.when) add("Lock most recently obtained at %s "\ "by thread id %d, name %s" % ( time_rep, id(owner), owner.getName())) add("Lock count by this thread: %d" % lock_count) if not owner.isAlive():=20 add("**THREAD IS DEAD**") add("\nLock holding stack:") if lock_context is None:=20 add("(unknown)") else: msg.extend(lock_context.formatted_minitrace()) if waits =3D=3D 1:=20 add("\nWaiting thread: id %d, name %s" % ( id(self.whine_context.thread),=20 self.whine_context.thread.getName())) add("\nWaiting stack:") msg.extend(self.whine_context.formatted_minitrace()) add("-"*70) print >> out, '\n'.join(msg) if __name__ =3D=3D '__main__':=20 import unittest import StringIO class CallingContextTests(unittest.TestCase):=20 "Tests of multi-threaded locking behaviour." # First, define some methods used by the tests.=20 # Argument funkiness used to pass arguments to CallingContext.=20 def one(self, ignores=3DNone):=20 "Return whatever `two` returns." return self.two(ignores) =20 def two(self, ignores=3DNone):=20 "Return whatever 'three' returns." return self.three(ignores) =20 def three(self, ignores=3DNone): "Return `three`'s call context." return CallingContext(ignores) # Now, the tests:=20 def test_creation(self):=20 "Test call context creation" CallingContext() def test_basic(self):=20 "Basic context check" context =3D self.one() assert context[-1].f_code is self.three.func_code assert context[-2].f_code is self.two.func_code assert context[-3].f_code is self.one.func_code def test_ignorecodes(self):=20 "Make sure ignoring codes works" context =3D self.one(ignores=3D[self.three.func_code]) assert context[-1].f_code is self.two.func_code def test_ignorenames(self):=20 "Make sure ignoring names works" context =3D self.one(ignores=3D['three']) assert context[-1].f_code is self.two.func_code def test_getitem(self):=20 "Get last frame as context[-1]" context =3D self.one() context[-1] =20 def test_len(self):=20 "Return number of frames in context as len(context)" context =3D self.one() assert len(context) > 3 =20 def test_minitrace(self):=20 "Context mini-trace" context =3D self.one() minitrace =3D context.minitrace() assert isinstance(minitrace, list) for filename, lineno, name in minitrace:=20 assert isinstance(filename, basestring) assert isinstance(lineno, int) assert isinstance(name, basestring) assert minitrace[0][2] =3D=3D 'three' assert minitrace[0][0] =3D=3D __file__ =20 def test_formatted_minitrace(self):=20 "Formatted context mini-trace" context =3D self.one() formatted_minitrace =3D context.formatted_minitrace() assert isinstance(formatted_minitrace, list) def test_print_minitrace(self):=20 "Printed context mini-trace" out =3D StringIO.StringIO() context =3D self.one() context.print_minitrace(out) assert len(out.getvalue()) out.close() class BasicTests(unittest.TestCase):=20 "Basic tests." def test_creation(self):=20 "Creation" DorothyRLock() =20 def test_verbose_creation(self):=20 "Verbose creation" DorothyRLock(verbose=3DTrue) =20 def test_named_creation(self):=20 "Named creation" DorothyRLock(name=3D'lockName') =20 def test_verbose_named_creation(self):=20 "Verbose, named creation" DorothyRLock(verbose=3DTrue, name=3D'lockName') =20 def test_acquire_release(self):=20 "Basic acquisition and release" dorothy =3D DorothyRLock() dorothy.acquire() dorothy.release() def test_mistaken_release_of_unacquired_lock(self):=20 "React properly to someone releasing an un-acquired lock" def mistaken_release_of_unacquired_lock():=20 "Release a lock without acquiring it." dorothy =3D DorothyRLock() dorothy.release() self.assertRaises(ReleaseOfUnAcquiredLock,=20 mistaken_release_of_unacquired_lock) def test_formatted_diagnosis(self):=20 "LockAssertionError formatted diagnostics" dorothy =3D DorothyRLock() try:=20 dorothy.acquire() dorothy.acquire() except LockAssertionError, ex:=20 formatted_diagnosis =3D ex.formatted_diagnosis() assert len(formatted_diagnosis) def test_printed_diagnosis(self):=20 "LockAssertionError printed diagnostics" dorothy =3D DorothyRLock() try:=20 dorothy.acquire() dorothy.acquire() except LockAssertionError, ex:=20 out =3D StringIO.StringIO() ex.print_diagnosis(out) assert len(out.getvalue()) out.close() =20 class ReleaseFailureTests(unittest.TestCase): "Tests of the release failure detection mechanism." def acquire_and_release(self, dorothy):=20 "Acquire and release `dorothy`. Used by tests." dorothy.acquire() dorothy.release() def acquire_with_no_release(self, dorothy):=20 "Acquire, but don't release, `dorothy`. Used by tests." dorothy.acquire() # didn't call dorothy.release() -- oops! =20 def release_with_no_acquire(self, dorothy):=20 "Release, but don't acquire, `dorothy`. Used by tests." # didn't call dorothy.acquire() -- oops! dorothy.release() =20 def test_boxed_pairs(self):=20 "Permit subframes to re-acquire" dorothy =3D DorothyRLock() dorothy.acquire() self.acquire_and_release(dorothy) dorothy.release() def test_release_from_calling_frame(self):=20 "Detect release failure when a calling frame releases" def release_from_calling_frame():=20 "Force `LeftAcquiringFrame`." dorothy =3D DorothyRLock() dorothy.acquire() self.acquire_with_no_release(dorothy) dorothy.release() =20 self.assertRaises(LeftAcquiringFrame, = release_from_calling_frame) def test_release_from_sub_frame(self):=20 "Detect acquire failure when a sub-frame releases" def release_from_sub_frame():=20 "Force `ReleaseFromSubFrame`." dorothy =3D DorothyRLock() dorothy.acquire() self.release_with_no_acquire(dorothy) dorothy.release() =20 self.assertRaises(ReleaseFromSubFrame, = release_from_sub_frame) def test_reacquire_from_calling_frame(self):=20 "Detect release failure when a calling frame re-acquires" def reacquire_from_calling_frame():=20 "Force `LeftAcquiringFrame`." dorothy =3D DorothyRLock() self.acquire_with_no_release(dorothy) dorothy.acquire() =20 self.assertRaises(LeftAcquiringFrame, = reacquire_from_calling_frame) =20 def test_reacquire_from_foreign_frame(self):=20 "Detect release failure when the lock is re-acquired from = elsewhere" def reacquire_from_foreign_frame(): "Force `LeftAcquiringFrame`." dorothy =3D DorothyRLock() self.acquire_with_no_release(dorothy) # the second time around, this is a different *frame*=20 # despite it being the same callable object self.acquire_with_no_release(dorothy) self.assertRaises(LeftAcquiringFrame, = reacquire_from_foreign_frame) =20 def test_reacquire_from_same_frame(self):=20 "Detect release failure when lock re-acquired from the same = frame" def reacquire_from_same_frame(): "Force `ReAcquireFromSameFrame`." dorothy =3D DorothyRLock() dorothy.acquire() dorothy.acquire() self.assertRaises(ReAcquireFromSameFrame, = reacquire_from_same_frame) =20 class LockSittingThread(threading.Thread):=20 "Thread that sits on a lock. Automatically starts itself" def __init__(self, lock):=20 "Initialise and start the `LockSittingThread`." self.lock =3D lock self.acquired =3D 0 self.keepGoing =3D 1 threading.Thread.__init__(self) self.setDaemon(1) # lets test suite exit if thread still = going # start, and wait for acquisition self.start() while not self.acquired:=20 time.sleep(0.1) =20 def run(self):=20 "In the thread: acquire the lock, wait, and release when = told." self.lock.acquire() self.acquired =3D 1 while self.keepGoing:=20 time.sleep(0.1) self.lock.release() def stop(self):=20 "Ask the thread to stop and release, and wait for it to = obey." self.keepGoing =3D 0 self.join() =20 class MultiThreadedTests(unittest.TestCase):=20 "Tests of multi-threaded locking behaviour." def test_nonblocking_acquire_of_acquired_lock(self):=20 "Fail non-blocking acquires of a lock acquired by another = thread" dorothy =3D DorothyRLock() sitter =3D LockSittingThread(dorothy) self.assert_(not dorothy.acquire(0)) sitter.stop() def test_foreign_release(self):=20 "Catch one thread releasing a lock acquired by another = thread" dorothy =3D DorothyRLock() sitter =3D LockSittingThread(dorothy) self.assertRaises(ReleaseFromForeignThread, dorothy.release) sitter.stop() class IgnoreTests(unittest.TestCase):=20 """Tests of CallContext's ignore behaviour as used by = DorothyRLock. Also demonstrates the use case for ignores: an instance with a=20 private lock to which it needs to grant controlled access from=20 other objects.""" def setUp(self):=20 "Set up the private lock." self.__dorothy =3D DorothyRLock(ignores=3D[ self.acquire.func_code, self.release.func_code]) def acquire(self): "Acquire the private lock." self.__dorothy.acquire() def release(self):=20 "Release the private lock." self.__dorothy.release() def test_ignores(self):=20 """Verify instance's acquire and release methods are ignored = for the purpose of DorothyRLock's context comparisons.""" self.acquire() self.release() class LockWhinerTests(unittest.TestCase):=20 "Tests of the `LockWhiner`." def test_creation(self):=20 "LockWhiner creation" dorothy =3D DorothyRLock() LockWhiner(dorothy, CallingContext()) def test_fast_creation(self):=20 "Fast LockWhiner creation" dorothy =3D DorothyRLock() LockWhiner(dorothy, CallingContext(), every=3D0.1) def test_startstop(self):=20 "LockWhiner start and stop" dorothy =3D DorothyRLock() dorothy.acquire() # whine on behalf of this context into a StringIO object. out =3D StringIO.StringIO() context =3D CallingContext() whiner =3D LockWhiner(dorothy, context, every=3D0.1, = out=3Dout) whiner.start() # start it whiner.stop() # ask it to stop whiner.join(whiner.every + 1) # wait for it to stop running assert not whiner.isAlive() # fail test if we timed out = waiting whiner.check() # raise any exceptions caught by = LockWhiner.run def test_whinereports(self):=20 "LockWhiner whining" dorothy =3D DorothyRLock() dorothy.acquire() out =3D StringIO.StringIO() context =3D CallingContext() whiner =3D LockWhiner(dorothy, context, every=3D0.1, = out=3Dout) whiner.start() # start it # Now, make sure there's some output.=20 time.sleep(0.2) # wait a while output1 =3D out.getvalue() assert len(output1), "no whining detected" time.sleep(0.2) # wait some more output2 =3D out.getvalue() assert len(output2)>len(output1), "no additional whining = detected" # See if we can get a full report time.sleep(1) output3 =3D out.getvalue() assert output3.find("additional information") >=3D 0, \ "no report detected" whiner.stop() # ask it to stop whiner.join(whiner.every + 1) # wait for it to stop running assert not whiner.isAlive() # fail test if we timed out = waiting whiner.check() # raise any exceptions caught by = LockWhiner.run # Run the tests. unittest.main() ------=_NextPart_000_0019_01C4A353.A720BC50--