RE: Patch to DorothyLocker

This is a multi-part message in MIME format.

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

Okay, this should be MUCH better. It might still have problems when it does
report on a long-held lock, but I can run PyDS without hanging or crashing
now. I'll write a suite of unit tests to raise everyone's confidence levels
(mine included) that it's stable. 

If you don't want to be blinded with detail, change the setting of
``verbose`` in Tool.py to:

			self.lock = DorothyRLock(verbose=None,
toolName=name) 

-----Original Message-----
From: Garth T Kidd [mailto:garth-OnzZ1s1DREKDegMON/[email protected]] 
Sent: Wednesday, 22 September 2004 5:22 PM
To: 'Garth T Kidd'; 'Thomas Klaeger'; 'pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]'
Subject: RE: [Pyds-dev] Patch to DorothyLocker

Aah, bugger. I've replaced one deadlock with another; it's just happening on
Events because every other tool talks to it. I'll have to re-do large
chunks. 

-----Original Message-----
From: Garth T Kidd [mailto:garth-OnzZ1s1DREKDegMON/[email protected]]
Sent: Wednesday, 22 September 2004 2:31 PM
To: 'Garth T Kidd'; 'Thomas Klaeger'; 'pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]'
Subject: RE: [Pyds-dev] Patch to DorothyLocker

Okay; my first and most major blunder was that DorothyRLock wasn't
thread-safe. What's left, after fixing that and a couple more bugs, is that
the code to print details about foreign owners just isn't right. I'll fix
it. What'll be left after *that* is a blockade on the Events tool. 

-----Original Message-----
From: pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]
[mailto:pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]] On Behalf Of Garth T Kidd
Sent: Wednesday, 22 September 2004 11:18 AM
To: 'Thomas Klaeger'; pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]
Subject: RE: [Pyds-dev] Patch to DorothyLocker

I'll have to re-test. I can't incorporate the patches as-is because they're
broken: Rlocks can be locked multiple times by the same thread, and your
added lockContext attributes bypass my stack of lock details. 

-----Original Message-----
From: pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]
[mailto:pyds-dev-admin-iYtK5bfT9M//Ad8WF/[email protected]] On Behalf Of Thomas Klaeger
Sent: Monday, 20 September 2004 8:41 PM
To: pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]
Subject: [Pyds-dev] Patch to DorothyLocker

DorothyLocker raised exceptions if a lock was held by another task. In this
case the lockContext and lockTime was not defined although it should have
been.

Additionally it whined about unable to lock long after the lock had been
acquired due to the LockWhiner not checking if it has been stopped before
whining.


_______________________________________________
Pyds-dev mailing list
Pyds-dev-iYtK5bfT9M//Ad8WF/[email protected]
http://www.westfalen.de/cgi-bin/mailman/listinfo/pyds-dev

------=_NextPart_000_0000_01C4A13B.CB1FFC70
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 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

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
				print "-"*70
				print "Just in case this is a deadlock, here's some additional "
				print "information 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)
				print "Lock most recently obtained at %s by thread id %d, name %s" % =
(timeRep, id(owner), owner.getName())
				if not owner.isAlive():=20
					print "**THREAD IS DEAD**"
				print "\nLock holding stack:"
				if topContext is None:=20
					print "(unknown)"
				else:
					print_minitrace(topContext[-1])
				if waits=3D=3D1:=20
					print "\nWaiting thread: id %d, name %s" % (id(self.whineThread), =
self.whineThread.getName())
					print "\nWaiting stack:"=20
					print_minitrace(self.whineContext[-1])
				print "-"*70

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_0000_01C4A13B.CB1FFC70--