Response times in log files.

[pytrade]

Is there an easy way to add response times to the log files?

[Michiel Overtoom]

On 2011-06-17 20:23, pytrade wrote:
> Is there an easy way to add response times to the log files?

I use this module for that:

http://www.michielovertoom.com/incoming/timing.py

...but it's meant to be used from the page handler, and the
(hierarchical) timing report is meant to be shown at the bottom of the
page. But you could call 'cherrypy.log(...)' with the result. Hope it
helps!

--
"Good programming is not learned from generalities, but by seeing how
significant programs can be made clean, easy to read, easy to maintain
and modify, human-engineered, efficient, and reliable, by the application
of common sense and good programming practices. Careful study and
imitation of good programs leads to better writing."
- Kernighan and Plauger, motto of 'Software Tools'

[David Bolen]

pytrade <vinj...@gmail.com> writes:

> Is there an easy way to add response times to the log files?

I use a small custom tool to provide an overall duration log for any
requests that take longer than some number of ms. I tend to only care
about "slow" response times, but a limit of 0 will log everything.

No changes to any existing code - just enable the tool globally or for
any resources you wish. Oh, I keep application logs in different
loggers than CherryPy logging, so this retrieves my logger ("portald")
initially - feel free to switch to a different logger or just use
normal CherryPy log calls instead.

This is still from CherryPy 3.1 - not sure if later versions require any
changes.
- - - - -

class RequestDurationTool(cherrypy.Tool):
"""Tool to provide logging if a request exceeds a configured duration
(in ms) set by the threshold configuration parameter"""

CFG_THRESHOLD="tools.request_duration.threshold"

def __init__(self):
cherrypy.Tool.__init__(self, 'before_request_body', self._start_request)
self.logger = logging.getLogger('portald')

def _setup(self):
cherrypy.Tool._setup(self)
# Attach extra hook to compute timing after both raw processing and I/O
cherrypy.request.hooks.attach('on_end_resource', self._end_resource)
cherrypy.request.hooks.attach('on_end_request', self._end_request)

def _start_request(self, **kwargs):
cherrypy.request.request_start = time.time()

def _end_resource(self):
cherrypy.request.request_stop = time.time()

def _end_request(self):
# Elapsed time and threshold is in ms
elapsed = round((time.time() - cherrypy.request.request_start) * 1000)
limit = cherrypy.request.config.get(self.CFG_THRESHOLD, None)
if (limit is not None and elapsed > limit):
rsc_elapsed = round((cherrypy.request.request_stop -
cherrypy.request.request_start) * 1000)
self.logger.log(logging.WARNING,
'Request duration: %d [%d] ms (%s)' %
(elapsed, rsc_elapsed,
cherrypy.request.request_line))

cherrypy.tools.request_duration = RequestDurationTool()

- - - - -

Then I enable globally for my application in the CherryPy config file, as:

[global]
# Log any requests that take more than 1s
tools.request_duration.on = True
tools.request_duration.threshold = 1000

though of course you can choose to apply to more limited areas of your site
or with different timing parameters as with any other tool or configuration
parameter.

-- David