Python logging module - time since last log

Question

I would like to add to the logs generated by Python's logging module the time (seconds/ms) passed since the last entry was made to the logs.

This is useful, so you can look at a log file to see whether the same step always takes the same amount of time or changing, indicating that something has changed in the environment (e.g. database performance).

I know about the %(relativeCreated)d, but that is only showing the time passed since the initiation of the logger and not since the last logs was made. Basically the %(relativeCreated)d is the cumulated value, what I would like to see is the difference between each %(relativeCreated)d.

This is what you get with %(relativeCreated)d:

2015-07-20 12:31:07,037 (7ms) - INFO - Process started....
2015-07-20 12:31:07,116 (87ms) - INFO - Starting working on xyz
2015-07-20 12:31:07,886 (857ms) - INFO - Progress so far

And this is what I would need:

2015-07-20 12:31:07,037 (duration: 7ms) - INFO - Process started....
2015-07-20 12:31:07,116 (duration: 80ms) - INFO - Starting working on xyz
2015-07-20 12:31:07,886 (duration: 770ms) - INFO - Progress so far

Answer 1

Expanding on the answer from @Simeon Visser -- the filter is a simple storage device to store the last message's relative time since script start (see self.last in TimeFilter class).

import datetime
import logging

class TimeFilter(logging.Filter):

    def filter(self, record):
        try:
          last = self.last
        except AttributeError:
          last = record.relativeCreated

        delta = datetime.datetime.fromtimestamp(record.relativeCreated/1000.0) - datetime.datetime.fromtimestamp(last/1000.0)

        record.relative = '{0:.2f}'.format(delta.seconds + delta.microseconds/1000000.0)

        self.last = record.relativeCreated
        return True

Then apply that filter to each log handler and access the relative time in the log format string for each log handler.

fmt = logging.Formatter(fmt="%(asctime)s (%(relative)ss) %(message)s")
log = logging.getLogger()
[hndl.addFilter(TimeFilter()) for hndl in log.handlers]
[hndl.setFormatter(fmt) for hndl in log.handlers]