logging module -- better timestamp accuracy on Windows

Discussion in 'Python' started by benhoyt, Feb 15, 2011.

  1. benhoyt

    benhoyt Guest

    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.
    benhoyt, Feb 15, 2011
    #1
    1. Advertising

  2. benhoyt

    Ross Ridge Guest

    benhoyt <> 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.csclub.uwaterloo.ca/~rridge/
    db //
    Ross Ridge, Feb 16, 2011
    #2
    1. Advertising

Want to reply to this thread or ask your own question?

It takes just 2 minutes to sign up (and it's free!). Just click the sign up button to choose a username and then you can ask your own questions on the forum.
Similar Threads
  1. =?Utf-8?B?Q2hhcmxlc0E=?=

    Accuracy and CSS

    =?Utf-8?B?Q2hhcmxlc0E=?=, Jan 16, 2006, in forum: ASP .Net
    Replies:
    5
    Views:
    665
  2. Alessandro Bottoni

    Is there a better/simpler logging module?

    Alessandro Bottoni, Aug 8, 2005, in forum: Python
    Replies:
    2
    Views:
    247
    Michael Hoffman
    Aug 8, 2005
  3. Christoph Haas
    Replies:
    0
    Views:
    438
    Christoph Haas
    Jun 12, 2006
  4. Christoph Haas
    Replies:
    1
    Views:
    448
    Vinay Sajip
    Jun 14, 2006
  5. kou
    Replies:
    0
    Views:
    193
Loading...

Share This Page