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.