Velocity Reviews - Computer Hardware Reviews

Velocity Reviews > Newsgroups > Programming > Python > logging module -- better timestamp accuracy on Windows

Reply
Thread Tools

logging module -- better timestamp accuracy on Windows

 
 
benhoyt
Guest
Posts: n/a
 
      02-15-2011
The Python logging module calls time.time() in LogRecord.__init__ to fetch the timestamp of the log record. However, time.time() isn't particularly accurate on Windows. We're logging start and end of our requests in our web server, which can be milliseconds apart, and the log timestamps often show up as identical, but time.clock() is telling us several milliseconds have actually elapsed.

The fix is to use time.clock() if running on win32 (like "timeit" does). Here's how I've improved the accuracy for us:

-----
if sys.platform == 'win32':
# Running on win32, time.clock() is much more accurate than
# time.time(), use it for LogRecord timestamps

# Get the initial time and call time.clock() once to "start" it
_start_time = time.time()
time.clock()

def _formatTimeAccurate(self, record, datefmt):
# This is a bit nasty, as it modifies record.created and
# record.msecs, but apart from monkey-patching Formatter.__init__,
# how else do we do it?
accurate_time = _start_time + time.clock()
record.created = time.localtime(accurate_time)
record.msecs = (accurate_time - int(accurate_time)) * 1000
return time.strftime(datefmt, record.created)

# Override logging.Formatter's formatTime() so all logging calls
# go through this
logging.Formatter.formatTime = _formatTimeAccurate
-----

This works, but as you can see, it's a bit hacky. Is there a better way to fix it? (I'd like the fix to affect all loggers, including the root logger.)

I'm somewhat surprised that no one else has run into this before. Maybe I'm the only one who uses logging heavily under Windows ...

Thanks,
Ben.
 
Reply With Quote
 
 
 
 
Ross Ridge
Guest
Posts: n/a
 
      02-16-2011
benhoyt <(E-Mail Removed)> wrote:
>This works, but as you can see, it's a bit hacky. Is there a better way to =
>fix it? (I'd like the fix to affect all loggers, including the root logger.=
>)


A simpler solution would be to caclulate the time it takes to the handle
the request using time.clock() and include it in the log message.
Something like:

timer = time.time
if sys.platform == 'win32':
timer = time.clock

def handler(...):
start = timer()
...
logging.debug("processing time %.0fms",
(timer() - start) * 1000)

Saves you from having to do the math in your head when you look at
the logs.

Ross Ridge

--
l/ // Ross Ridge -- The Great HTMU
[oo][oo] http://www.velocityreviews.com/forums/(E-Mail Removed)
-()-/()/ http://www.csclub.uwaterloo.ca/~rridge/
db //
 
Reply With Quote
 
 
 
Reply

Thread Tools

Posting Rules
You may not post new threads
You may not post replies
You may not post attachments
You may not edit your posts

BB code is On
Smilies are On
[IMG] code is On
HTML code is Off
Trackbacks are On
Pingbacks are On
Refbacks are Off


Similar Threads
Thread Thread Starter Forum Replies Last Post
why the accuracy of float is weakened in module kou Python 0 02-27-2012 07:51 PM
Re: Logging to a file and closing it again properly (logging module) Christoph Haas Python 1 06-14-2006 08:47 AM
Logging to a file and closing it again properly (logging module) Christoph Haas Python 0 06-12-2006 09:58 PM
Build a Better Blair (like Build a Better Bush, only better) Kenny Computer Support 0 05-06-2005 04:50 AM
PIX logging without timestamp Ste Cisco 2 09-04-2004 01:08 AM



Advertisments