[Erp5-report] r39624 leonardo - in /erp5/trunk/utils/Products.LongRequestLogger: ./ Product...
nobody at svn.erp5.org
nobody at svn.erp5.org
Thu Oct 28 17:47:13 CEST 2010
Author: leonardo
Date: Thu Oct 28 17:47:12 2010
New Revision: 39624
URL: http://svn.erp5.org?rev=39624&view=rev
Log:
Add the start-time of the request to log output to make it easier to grep and separate the requests of a thread. Improve documentation.
Modified:
erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/dumper.py
erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/monitor.py
erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/tests/testLongRequestLogger.py
erp5/trunk/utils/Products.LongRequestLogger/README.txt
erp5/trunk/utils/Products.LongRequestLogger/setup.py
Modified: erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/dumper.py
URL: http://svn.erp5.org/erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/dumper.py?rev=39624&r1=39623&r2=39624&view=diff
==============================================================================
--- erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/dumper.py [utf8] (original)
+++ erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/dumper.py [utf8] Thu Oct 28 17:47:12 2010
@@ -92,9 +92,9 @@ def get_configuration():
DEFAULT_INTERVAL)),
)
+THREAD_FORMAT = "Thread %s: Started on %.1f; Running for %.1f secs; %s"
REQUEST_FORMAT = """
-request:
-URL: %(method)s %(url)s
+request: %(method)s %(url)s
retry count: %(retries)s
form: %(form)s
other: %(other)s
@@ -131,7 +131,10 @@ class Dumper(object):
return REQUEST_FORMAT % locals()
def extract_request(self, frame):
- # import locally to get even monkey-patched results
+ # We try to fetch the request from the 'call_object' function because
+ # it's the one that gets called with retried requests.
+ # And we import it locally to get even monkey-patched versions of the
+ # function.
from ZPublisher.Publish import call_object
func_code = call_object.func_code #@UndefinedVariable
while frame is not None:
@@ -152,8 +155,10 @@ class Dumper(object):
request_info = self.extract_request_info(frame)
now = time.time()
runtime = now - self.start
- info = ("Thread %s: Running for %.1f secs; %s" %
- (self.thread_id, runtime, request_info))
+ info = THREAD_FORMAT % (self.thread_id,
+ self.start,
+ runtime,
+ request_info)
return info
def format_thread(self):
Modified: erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/monitor.py
URL: http://svn.erp5.org/erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/monitor.py?rev=39624&r1=39623&r2=39624&view=diff
==============================================================================
--- erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/monitor.py [utf8] (original)
+++ erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/monitor.py [utf8] Thu Oct 28 17:47:12 2010
@@ -50,7 +50,7 @@ class Monitor(Thread):
timeout=None,
interval=None):
Thread.__init__(self)
- self.dumper = dumper.Dumper(thread_id)
+ 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()
Modified: erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/tests/testLongRequestLogger.py
URL: http://svn.erp5.org/erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/tests/testLongRequestLogger.py?rev=39624&r1=39623&r2=39624&view=diff
==============================================================================
--- erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/tests/testLongRequestLogger.py [utf8] (original)
+++ erp5/trunk/utils/Products.LongRequestLogger/Products/LongRequestLogger/tests/testLongRequestLogger.py [utf8] Thu Oct 28 17:47:12 2010
@@ -36,7 +36,8 @@ import os
class SimpleOutputChecker(OutputChecker):
# for certain inputs the doctest output checker is much more convenient
- # than manually munging assertions
+ # than manually munging assertions, but we don't want to go through all
+ # the trouble of actually writing doctests.
optionflags = REPORT_UDIFF | NORMALIZE_WHITESPACE | ELLIPSIS
@@ -51,7 +52,7 @@ class SimpleOutputChecker(OutputChecker)
got, self.optionflags)
check_dump = SimpleOutputChecker('''
-Thread ...: Running for 0.0 secs; [No request]
+Thread ...: Started on ...; Running for 0.0 secs; [No request]
<BLANKLINE>
Traceback:
...
@@ -63,7 +64,7 @@ Traceback:
check_log = SimpleOutputChecker('''
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 0.0 secs; [No request]
+ Thread ...: Started on ...; Running for 0.0 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/dumper.py", line ..., in __call__
@@ -76,7 +77,7 @@ Traceback:
check_monitor_log = SimpleOutputChecker('''
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 2.0 secs; [No request]
+ Thread ...: Started on ...; Running for 2.0 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/tests/common.py", line 41, in sleep
@@ -89,7 +90,7 @@ Traceback:
check_monitor_2_intervals_log = SimpleOutputChecker('''
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 2.0 secs; [No request]
+ Thread ...: Started on ...; Running for 2.0 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/tests/common.py", line 41, in sleep
@@ -99,7 +100,7 @@ Traceback:
File ".../LongRequestLogger/tests/common.py", line 47, in _sleep2
time.sleep(self.interval)
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 3.0 secs; [No request]
+ Thread ...: Started on ...; Running for 3.0 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/tests/common.py", line 41, in sleep
@@ -109,7 +110,7 @@ Traceback:
File ".../LongRequestLogger/tests/common.py", line 47, in _sleep2
time.sleep(self.interval)
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 4.0 secs; [No request]
+ Thread ...: Started on ...; Running for 4.0 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/tests/common.py", line 41, in sleep
@@ -122,8 +123,7 @@ Traceback:
check_publishing_1_interval_log = SimpleOutputChecker('''
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 2.0 secs; request:
-URL: GET http://localhost
+ Thread ...: Started on ...; Running for 2.0 secs; request: GET http://localhost
retry count: 0
form: {}
other: {'ACTUAL_URL': 'http://localhost',
@@ -151,8 +151,7 @@ Traceback:
File ".../LongRequestLogger/tests/common.py", line 47, in _sleep2
time.sleep(self.interval)
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 3.0 secs; request:
-URL: GET http://localhost
+ Thread ...: Started on ...; Running for 3.0 secs; request: GET http://localhost
retry count: 0
form: {}
other: {'ACTUAL_URL': 'http://localhost',
@@ -182,8 +181,7 @@ Traceback:
''')
check_request_formating = SimpleOutputChecker('''
-request:
-URL: GET http://localhost/foo/bar
+request: GET http://localhost/foo/bar
retry count: 0
form: {}
other: {'RESPONSE': HTTPResponse(''),
@@ -194,7 +192,7 @@ other: {'RESPONSE': HTTPResponse(''),
check_monitor_environment_log = SimpleOutputChecker('''
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 3.5 secs; [No request]
+ Thread ...: Started on ...; Running for 3.5 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/tests/common.py", line 41, in sleep
@@ -204,7 +202,7 @@ Traceback:
File ".../LongRequestLogger/tests/common.py", line 47, in _sleep2
time.sleep(self.interval)
Products.LongRequestLogger.dumper WARNING
- Thread ...: Running for 5.5 secs; [No request]
+ Thread ...: Started on ...; Running for 5.5 secs; [No request]
Traceback:
...
File ".../LongRequestLogger/tests/common.py", line 41, in sleep
@@ -354,7 +352,7 @@ class TestLongRequestLogger(unittest.Tes
# and there should be no records
self.assertFalse(self.loghandler.records)
- def testMonitorWithEnvorinmentConfigutation(self):
+ def testMonitorWithEnvorinmentConfiguration(self):
from Products.LongRequestLogger.monitor import Monitor
os.environ['longrequestlogger_timeout'] = '3.5'
os.environ['longrequestlogger_interval'] = '2'
Modified: erp5/trunk/utils/Products.LongRequestLogger/README.txt
URL: http://svn.erp5.org/erp5/trunk/utils/Products.LongRequestLogger/README.txt?rev=39624&r1=39623&r2=39624&view=diff
==============================================================================
--- erp5/trunk/utils/Products.LongRequestLogger/README.txt [utf8] (original)
+++ erp5/trunk/utils/Products.LongRequestLogger/README.txt [utf8] Thu Oct 28 17:47:12 2010
@@ -19,7 +19,7 @@ Buildout Installation for Old Zope Versi
Add "Products.LongRequestLogger[python24]" to the list of eggs of the part
that defines your Zope instance. This will automatically pull in the
-'threadframe' module which is needed for Python versions less than 2.5.
+'threadframe' module which is needed for Python versions < 2.5.
Manual Installation for Old Zope Versions
-----------------------------------------
@@ -40,12 +40,12 @@ this::
longrequestlogger_interval 2
</environment>
-The following variables are recognized:
+The following variables are recognised:
* "longrequestlogger_file": This is a mandatory variable. Its absence means the
LongRequestLogger monkey-patch to the publication machinery will not be
applied. It should point to a file where you want the long requests to be
- logged
+ logged.
* "longrequestlogger_timeout": The amount of seconds after which long requests
start being logged. Accepts floating point values and defaults to 2.
@@ -54,3 +54,53 @@ The following variables are recognized:
their stack trace logged once they have exceeded their 'timeout' above.
Defaults to 1 and accepts floating point values.
+For the curious, the use of environment variables instead of ZConfig directives
+is due to two reasons:
+
+ 1. The environment variable can be changed at runtime to affect the behaviour
+ of the logger.
+
+ 2. Old Zope versions don't have the ability to use "product-config" syntax,
+ and writing a ZConfig component for just 3 keys is overkill.
+
+Runtime Configuration
+---------------------
+
+On the first point above, changing the longrequestlogger_file variable changes
+the logging destination for all subsequent requests after the change (and
+likely any ongoing request as well), but if Zope is started without that
+variable defined, then setting at runtime will not have any effect.
+
+The other two variables can also be dynamically changed as well, and will take
+effect at the following request after the change, for all threads in the same
+process.
+
+Interpreting results
+====================
+
+It's important to keep in mind a few important facts about the behaviour of
+Zope2 applications and threads while looking at the results:
+
+ 1. Each thread only handles one request at a time.
+
+ 2. Slow requests will usually have tracebacks with a common top part and a
+ variable bottom part. The key to the cause of the slowdown in a request
+ will be in the limit of both.
+
+If you're in a pinch and don't want to parse the file to rank the slowest
+URLs for investigation, pick up a time in seconds that's a multiple of your
+interval plus the timeout and grep for it. For the default settings, of
+time-out and interval, you will find log entries for 4 then 6 then 8 seconds,
+so you can do a grep like::
+
+ $ grep -n "Running for 8" longrequest.log
+
+And decide with URLs show up more. Then you can open the log file, go to the
+line number reported and navigate the tracebacks by searching up and down
+the file for the same thread id (the number after "Thread" in the reported
+lines). Then analise the difference between the tracebacks of a single request
+to get a hint on what this particular request is doing and why it is slowing
+down.
+
+By doing this for a number of similar requests you will be able to come up with
+optimisations or a caching strategy.
Modified: erp5/trunk/utils/Products.LongRequestLogger/setup.py
URL: http://svn.erp5.org/erp5/trunk/utils/Products.LongRequestLogger/setup.py?rev=39624&r1=39623&r2=39624&view=diff
==============================================================================
--- erp5/trunk/utils/Products.LongRequestLogger/setup.py [utf8] (original)
+++ erp5/trunk/utils/Products.LongRequestLogger/setup.py [utf8] Thu Oct 28 17:47:12 2010
@@ -1,12 +1,41 @@
+##############################################################################
+#
+# Copyright (c) 2010 Nexedi SA and Contributors. All Rights Reserved.
+# Leonardo Rochael Almeida <leonardo at nexedi.com>
+#
+# WARNING: This program as such is intended to be used by professional
+# programmers who take the whole responsibility of assessing all potential
+# consequences resulting from its eventual inadequacies and bugs
+# End users who are looking for a ready-to-use solution with commercial
+# guarantees and support are strongly advised to contract a Free Software
+# Service Company
+#
+# This program is Free Software; you can redistribute it and/or
+# modify it under the terms of the GNU General Public License
+# as published by the Free Software Foundation; either version 2
+# of the License, or (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, write to the Free Software
+# Foundation, Inc., 59 Temple Place - Suite 330, Boston, MA 02111-1307, USA.
+#
+##############################################################################
+
from setuptools import setup
from setuptools import find_packages
import os
-version = '0.1'
+version = '1.0'
+description = "Dumps sequential stack traces of long-running Zope2 requests"
setup(name='Products.LongRequestLogger',
version=version,
- description="Dumps stack trace of long running Zope2 requests",
+ description=description,
long_description=open("README.txt").read() + "\n" +
open(os.path.join("docs", "HISTORY.txt")).read(),
classifiers=[
@@ -17,7 +46,7 @@ setup(name='Products.LongRequestLogger',
keywords='',
author='Nexedi SA',
author_email='erp5-dev at erp5.org',
- url='http://www.erp5.org/',
+ url='http://www.erp5.com/',
license='GPL',
packages=find_packages(exclude=['ez_setup']),
namespace_packages=['Products'],
More information about the Erp5-report
mailing list