RE: Patch to DorothyLocker

This is a multi-part message in MIME format.

------=_NextPart_000_0004_01C4A13E.79676500
Content-Type: text/plain;
	charset="us-ascii"
Content-Transfer-Encoding: 7bit

Excellent idea, that. Whining and whining loudly is fine; all I had to do
was consolidate down to only one ``print`` so output didn't interleave. New
version attached. 

-----Original Message-----
From: Garth T Kidd [mailto:garth-OnzZ1s1DREKDegMON/[email protected]] 
Sent: Thursday, 23 September 2004 7:18 AM
To: 'Thomas Klaeger'
Cc: 'pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]'
Subject: RE: [Pyds-dev] Patch to DorothyLocker

No need, but thanks for the offer! I stripped back and simplified the code,
kept in mind that if the calling thread was the lock owner I knew I wasn't
re-entrant, and it all behaved pretty quickly. My main cause for concern now
is not knowing how well the LockWhiner reporting will go. I guess I should
set the whine period to a tenth of a second to try it out. :) 

-----Original Message-----
From: pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]
[mailto:pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]] On Behalf Of Thomas Klaeger
Sent: Wednesday, 22 September 2004 7:55 PM
To: Garth T Kidd
Cc: pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]
Subject: Re: [Pyds-dev] Patch to DorothyLocker

Is there any possibility I can help out?

------=_NextPart_000_0004_01C4A13E.79676500
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 subclass of threading.RLock that=20
insists upon release() being called from the same execution frame that=20
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=20
lock you think is free, and blocks.=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 =

from _acquire and _release, DorothyRLock can concentrate on the frames=20
actually causing the locks and releases.=20
"""

import threading
from threading import _Verbose, currentThread, Thread
from thread import allocate_lock
import time
import inspect
import sys
import traceback
import os.path

IGNORE =3D ['_acquire', '_release', '__acquire', '__release', =
'__DorothyRLock_acquire', '__DorothyRLock_release']

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:]

def ping(*args):=20
	myContext =3D context(ignorecodes=3D[ping.func_code])
	frame =3D myContext[-1]
	filename, line, name =3D frame.f_code.co_filename, frame.f_lineno, =
frame.f_code.co_name
	filename =3D os.path.basename(filename)
	me =3D currentThread()
	args =3D ", ".join([repr(a) for a in args])
	print "ping! thread %d/%s %s line %d %s" % (
		id(me), me.getName(), filename, line, args
		)
=09
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

def format_minitrace(frame):=20
	"Format a mini-trace from a locking context."
	msg =3D []
	for filename, line, name in extract_minitrace(frame):=20
		msg.append('File "%s", line %d, in %s' % (
		      filename, line, name))
	return msg

def print_minitrace(frame):=20
	"Print a mini-trace from a locking context."
	print '\n'.join(format_minitrace(frame))

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

class ReleaseFailure(Exception):=20
	"Raised if DorothyRLock detects a failure to release an acquired lock."
	pass

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.
=09
	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 "%s\n%s\n%s\n" % (dash, msg, dash)
			setattr(cls, att, True)
	squawk =3D classmethod(squawk)
	=09
	def __init__(self, verbose=3DNone, toolName=3D'(unknown)'):=20
		"Initialise the DorothyRLock."
		_Verbose.__init__(self, verbose)
		self.toolName =3D toolName
		self.__ignores =3D [
			self.acquire.func_code,=20
			self.release.func_code,
			self.callContext.func_code]
		self.__owner =3D None
		self.__lockStack =3D []
		self.__block =3D allocate_lock()
		self.__class__.squawk()
	=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 prior locks by this=20
		thread have been released if they're not still on our call chain.
		"""
	=09
		# First, get our context.=20
		me =3D currentThread()
		mycontext, myt =3D self.callContext(), time.time()

		# 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 me:=20
			# Try to figure out whether the previous lock should have been=20
			# released.=20
			prevcontext, prevt =3D self.__lockStack[-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)

			# If we got this far, we're OK.=20
			# Add our details to the lock stack and return success.=20
			self.__lockStack.append((mycontext, myt))
			if __debug__:=20
				self._note("%s.acquire(%s): recursive success", self, blocking)
			return 1
	=09
		# 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)
	=09
		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=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, mycontext, myt)
			whiner.start()
			result =3D self.__block.acquire()
	=09
			# We can ONLY get here if we succeeded...
			assert result # ... but you can never be too careful.=20
		=09
			# Stop the whiner.=20
			whiner.stop()
	=09
		# Success! Let's grab the goodies and run.=20
		self.__owner =3D me
		self.__lockStack =3D [(mycontext, myt)]
		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."""
	=09
		# First, get our context.=20
		me =3D currentThread()
		mycontext, myt =3D self.callContext(), time.time()

		if self.__owner is me:=20
			prevcontext, prevt =3D self.__lockStack[-1]
			if not prevcontext =3D=3D mycontext:=20
				# TODO: unwind to some adequate level
				raise ReleaseFailure, ("failure to release", prevcontext[-1], prevt)
		else:=20
			raise ReleaseFailure, ("releasing thread doesn't own the lock", =
mycontext[-1], myt)
	=09
		# If we got here, all is well.=20
		topContext, topTime =3D self.__lockStack.pop()
		delay =3D myt - topTime
		if self.__lockStack:=20
			if __debug__:=20
				self._note("%s.release(): non-final release after %.2fs", self, =
delay)
		else:=20
			if __debug__:=20
				self._note("%s.release(): final release after %.2fs", self, delay)
			self.__owner =3D None
			self.__block.release()

	def __repr__(self):=20
		"Return a representation of this object."
		return "<%s.lock owned by %s with count %d>" % (
			self.toolName,=20
			self.__owner and self.__owner.getName(),=20
			len(self.__lockStack))

	def lockDetails(self):=20
		"""Return top lock details: owner, lock count, top context, time.
		Because of race conditions, details might not be consistent."""
		try:=20
			top =3D self.__lockStack[-1]
			mycontext, myt =3D top
		except IndexError:=20
			mycontext =3D myt =3D None
		return self.__owner, len(self.__lockStack), mycontext, myt

class LockWhiner(Thread):=20
	def __init__(self, dorothy, whineContext, whineTime, every=3D10, =
loudEvery=3D60):=20
		Thread.__init__(self)
		self.dorothy =3D dorothy
		self.whineTime =3D whineTime
		self.whineContext =3D whineContext
		self.whineEvery =3D every
		self.whineLoudlyEvery =3D loudEvery
		self.whineThread =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 %d stopped for %s.lock; acquired by thread %d =
(%s) after %.2f seconds" % (
		      time.ctime(self.stopTime),=20
			  id(self),=20
			  self.dorothy.toolName,=20
			  id(self.whineThread),=20
			  self.whineThread.getName(),
		      self.stopTime - self.whineTime)

	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)
			print 'Dict:'=20
			for key in self.__dict__.keys():=20
				print '  %s =3D %s' % (key, repr(self.__dict__[key]))

	def _run(self):=20
		print "%s: LockWhiner %d started for %s.lock; thread %d (%s) waiting" =
% (\
		      time.ctime(self.whineTime),=20
			  id(self),=20
			  self.dorothy.toolName,=20
		      id(self.whineThread),
			  self.whineThread.getName())
		waits =3D 0
		louds =3D int(self.whineLoudlyEvery/self.whineEvery)
		while self.active:=20
			time.sleep(self.whineEvery)
			if not self.active:=20
				break
			waits =3D waits + 1
			now =3D time.time()
			print "%s: LockWhiner %d has been waiting for %.2fs" % (
			      time.ctime(),
				  id(self),=20
			      now - self.whineTime)
			if not (waits-1) % louds:=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, lockCount, topContext, topTime =3D self.dorothy.lockDetails()
				if topTime is None:=20
					timeRep =3D "(unknown)"
				else:=20
					timeRep =3D time.ctime(topTime)
				add("Lock most recently obtained at %s by thread id %d, name %s" % =
(timeRep, id(owner), owner.getName()))
				if not owner.isAlive():=20
					add("**THREAD IS DEAD**")
				add("\nLock holding stack:")
				if topContext is None:=20
					add("(unknown)")
				else:
					msg.extend(format_minitrace(topContext[-1]))
				if waits=3D=3D1:=20
					add("\nWaiting thread: id %d, name %s" % (id(self.whineThread), =
self.whineThread.getName()))
					add("\nWaiting stack:")
					msg.extend(format_minitrace(self.whineContext[-1]))
				add("-"*70)
				print '\n'.join(msg)

if __name__ =3D=3D '__main__':=20
	import pprint

	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
	def fail1_top():=20
		fail1_mid1()
		fail1_mid2()
	def fail1_mid1():=20
		nrl.acquire()
	def fail1_mid2():=20
		nrl.release()

	def fail2_top():=20
		fail2_mid1()
		fail2_mid2()
	def fail2_mid1():=20
		nrl.acquire()
	def fail2_mid2():=20
		nrl.acquire()
		nrl.release()

	for test in [fail1_top, fail2_top]:=20
		nrl =3D DorothyRLock()
		nrl.acquire()
		nrl.release()
		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)


------=_NextPart_000_0004_01C4A13E.79676500--