[Checkins] SVN: Products.LongRequestLogger/trunk/ Use os.pipe() and select() instead of threading.Condition
Leonardo Almeida
cvs-admin at zope.org
Mon Jul 30 13:59:55 UTC 2012
Log message for revision 127403:
Use os.pipe() and select() instead of threading.Condition
This should avoid a slowdown on certain VMWare guests.
Also do some readability code refactoring.
Changed:
U Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py
U Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py
U Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py
U Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py
U Products.LongRequestLogger/trunk/buildout.cfg
U Products.LongRequestLogger/trunk/docs/HISTORY.txt
-=-
Modified: Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py 2012-07-30 08:49:42 UTC (rev 127402)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/dumper.py 2012-07-30 13:59:51 UTC (rev 127403)
@@ -15,6 +15,7 @@
import os.path
import time
import traceback
+import sys
try:
from signal import SIGUSR2
@@ -24,10 +25,11 @@
SIGUSR2 = 12
try:
- from sys import _current_frames
-except ImportError:
+ sys._current_frames
+except AttributeError:
# Python 2.4 and older
- from threadframe import dict as _current_frames
+ import threadframe
+ sys._current_frames = threadframe.dict
class NullHandler(logging.Handler):
@@ -152,9 +154,6 @@
request = self.extract_request(frame)
return self.format_request(request)
- def get_top_thread_frame(self):
- return _current_frames()[self.thread_id]
-
def get_thread_info(self, frame):
request_info = self.extract_request_info(frame)
now = time.time()
@@ -166,7 +165,7 @@
return info
def format_thread(self):
- frame = self.get_top_thread_frame()
+ frame = sys._current_frames()[self.thread_id]
output = StringIO()
thread_info = self.get_thread_info(frame)
print >> output, thread_info
Modified: Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py 2012-07-30 08:49:42 UTC (rev 127402)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/monitor.py 2012-07-30 13:59:51 UTC (rev 127403)
@@ -4,59 +4,56 @@
#
##############################################################################
+import os
+from select import select
from threading import Thread
-from threading import Condition
-from Products.LongRequestLogger import dumper
+from Products.LongRequestLogger.dumper import Dumper
class Monitor(Thread):
"""Logs the stack-trace of a thread until it's stopped
- m = Monitor(thread.get_ident(), timeout=5, interval=2)
+ m = Monitor(dumper)
- Wait 5 seconds before dumping the stack-trace of the identified thread
- every 2 seconds.
+ Wait dumper.timeout seconds before calling dumper() every
+ dumper.interval seconds.
m.stop()
-
+
Stop the monitoring, whether timed-out or not
"""
- running = False
+ dumper = None
- def __init__(self,
- thread_id=None,
- timeout=None,
- interval=None):
+ def __init__(self, dumper=None):
Thread.__init__(self)
- self.dumper = dumper.Dumper(thread_id=thread_id)
- self.timeout = timeout or self.dumper.timeout
- self.interval = interval or self.dumper.interval
- self.running_condition = Condition()
- if self.dumper.is_enabled():
- self.running = True
+ if dumper is None:
+ dumper = Dumper()
+ if dumper.is_enabled():
+ self._event_pipe = os.pipe()
+ self.dumper = dumper
self.start()
+ def waiting(self, timeout):
+ r, _ = self._event_pipe
+ read_ready_list, _, _ = select([r], [], [], timeout)
+ if read_ready_list:
+ os.read(r, 1)
+ # stop() called by monitored thread.
+ # Stop waiting:
+ return False
+ # Still waiting for the other thread to finish
+ return True
+
def stop(self):
"""Stop monitoring the other thread"""
- # this function is called by the other thread, when it wants to stop
- # being monitored
- self.running_condition.acquire()
- try:
- if not self.running:
- return # yes, the finally clause will be run, don't worry
- self.running = False
- self.running_condition.notify()
- finally:
- self.running_condition.release()
- self.join()
+ if self.dumper is not None:
+ r, w = self._event_pipe
+ os.write(w, '\0')
+ self.join()
+ map(os.close, self._event_pipe)
def run(self):
- self.running_condition.acquire()
- self.running_condition.wait(self.timeout)
- # If the other thread is still running by now, it's time to monitor it
- try:
- while self.running:
- self.dumper()
- self.running_condition.wait(self.interval)
- finally:
- self.running_condition.release()
+ timeout = self.dumper.timeout
+ while self.waiting(timeout):
+ self.dumper()
+ timeout = self.dumper.interval
Modified: Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py 2012-07-30 08:49:42 UTC (rev 127402)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/patch.py 2012-07-30 13:59:51 UTC (rev 127403)
@@ -11,12 +11,12 @@
log = getLogger(__name__)
def wrapper(*args, **kw):
- m = Monitor()
+ monitor = Monitor()
try:
result = wrapper.original(*args, **kw)
return result
finally:
- m.stop()
+ monitor.stop()
def do_patch():
from ZPublisher.Publish import publish_module_standard as original
Modified: Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py
===================================================================
--- Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py 2012-07-30 08:49:42 UTC (rev 127402)
+++ Products.LongRequestLogger/trunk/Products/LongRequestLogger/tests/testLongRequestLogger.py 2012-07-30 13:59:51 UTC (rev 127403)
@@ -4,6 +4,7 @@
#
##############################################################################
+import sys
import unittest
from cStringIO import StringIO
from doctest import OutputChecker
@@ -36,8 +37,6 @@
...
File ".../LongRequestLogger/dumper.py", line ..., in format_thread
traceback.print_stack(frame, file=output)
- File ".../LongRequestLogger/dumper.py", line ..., in get_top_thread_frame
- return _current_frames()[self.thread_id]
''')
check_log = SimpleOutputChecker('''
@@ -49,8 +48,6 @@
self.log.warning(self.format_thread())
File ".../LongRequestLogger/dumper.py", line ..., in format_thread
traceback.print_stack(frame, file=output)
- File ".../LongRequestLogger/dumper.py", line ..., in get_top_thread_frame
- return _current_frames()[self.thread_id]
''')
check_monitor_log = SimpleOutputChecker('''
@@ -259,7 +256,8 @@
from Products.LongRequestLogger.dumper import Dumper
def callable():
dumper = Dumper()
- return dumper.extract_request(dumper.get_top_thread_frame())
+ frame = sys._current_frames()[dumper.thread_id]
+ return dumper.extract_request(frame)
request = self.makeRequest('/foo')
retrieved_request = call_object(callable, (), request)
@@ -285,9 +283,7 @@
s = Sleeper(0.01)
s.sleep()
self.assertTrue(m.isAlive())
- self.assertTrue(m.running)
m.stop()
- self.assertFalse(m.running)
self.assertFalse(m.isAlive())
# unless this test is so slow that there were 2 seconds interval
# between starting the monitor and stopping it, there should be no
@@ -297,7 +293,7 @@
def testMonitorStopAfterTimeout(self):
from Products.LongRequestLogger.monitor import Monitor
m = Monitor()
- s = Sleeper(m.timeout + 0.5)
+ s = Sleeper(m.dumper.timeout + 0.5)
# sleep a little more than the timeout to be on the safe side
s.sleep()
m.stop()
@@ -306,7 +302,7 @@
def testMonitorStopAfterTimeoutAndTwoIntervals(self):
from Products.LongRequestLogger.monitor import Monitor
m = Monitor()
- s = Sleeper(m.timeout + 2 * m.interval + 0.5)
+ s = Sleeper(m.dumper.timeout + 2 * m.dumper.interval + 0.5)
# sleep a little more than timeout + intervals to be on the safe
# side
s.sleep()
@@ -315,17 +311,17 @@
def testMonitorConfigurationDisabled(self):
from Products.LongRequestLogger.monitor import Monitor
+ from Products.LongRequestLogger.dumper import DEFAULT_TIMEOUT
+ from Products.LongRequestLogger.dumper import DEFAULT_INTERVAL
os.environ['longrequestlogger_file'] = ''
m = Monitor()
- s = Sleeper(m.timeout + 2 * m.interval + 0.5)
+ s = Sleeper(DEFAULT_TIMEOUT + 2 * DEFAULT_INTERVAL + 0.5)
# sleep a little more than timeout + intervals
s.sleep()
# the thread shouldn't run disabled
self.assertFalse(m.isAlive())
- self.assertFalse(m.running)
# stopping shouldn't break nonetheless
m.stop()
- self.assertFalse(m.running)
self.assertFalse(m.isAlive())
# and there should be no records
self.assertFalse(self.loghandler.records)
@@ -335,7 +331,7 @@
os.environ['longrequestlogger_timeout'] = '3.5'
os.environ['longrequestlogger_interval'] = '2'
m = Monitor()
- s = Sleeper(m.timeout + m.interval + 0.5)
+ s = Sleeper(m.dumper.timeout + m.dumper.interval + 0.5)
# sleep a little more than the timeout to be on the safe side
s.sleep()
m.stop()
Modified: Products.LongRequestLogger/trunk/buildout.cfg
===================================================================
--- Products.LongRequestLogger/trunk/buildout.cfg 2012-07-30 08:49:42 UTC (rev 127402)
+++ Products.LongRequestLogger/trunk/buildout.cfg 2012-07-30 13:59:51 UTC (rev 127403)
@@ -3,7 +3,7 @@
parts =
test
releaser
-extends = http://download.zope.org/Zope2/index/2.12.19/versions.cfg
+extends = http://download.zope.org/Zope2/index/2.12.23/versions.cfg
versions = versions
[releaser]
Modified: Products.LongRequestLogger/trunk/docs/HISTORY.txt
===================================================================
--- Products.LongRequestLogger/trunk/docs/HISTORY.txt 2012-07-30 08:49:42 UTC (rev 127402)
+++ Products.LongRequestLogger/trunk/docs/HISTORY.txt 2012-07-30 13:59:51 UTC (rev 127403)
@@ -4,11 +4,19 @@
1.1dev (unreleased)
-------------------
+- Some refactoring for code readability.
+
+- Use a `os.pipe()` pair and `select.select()` instead of
+ `threading.Condition` to signal when the monitor should stop tracing
+ the original thread. This avoids a performance bottleneck in some
+ VMWare installations, which seem not to have good performance for locks
+ in certain conditions.
+
- Integrate the logging mechanism with Zope's signal handling and ZConfig's
rotating file handler so that USR2 signals will cause the long request log
to get reopened analogous to the access and event log.
-1.0
----
+1.0 (2010-10-28)
+----------------
- Initial release
More information about the checkins
mailing list