logging module -- better timestamp accuracy on Windows

[benhoyt]

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.

 

[Ross Ridge]

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