CODEWITHSUNDEEP
pythonlogging
dpington
dpington

Reputation: 1884

Python logging time since start of program

I'm using the logging module to create loggers and output data. Instead of using $(asctime)s in logging.Formatter, is there a good way to log the timestamp relative to the creation of the logger?

Upvotes: 24

Views: 13250

Answers (6)

Dmitry Bravikov
Dmitry Bravikov

Reputation: 140

I had a slightly different task. I need a calculate a time delta between messages. That is, I had to save the time of the last message. To do this, I had to add thread locking.

There are a logger level filter and a handler level filter. Both, a logger and a handler, call a filter function without a thread locking.

import threading
import time
import datetime

class MyFilter(logging.Filter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.delta_lock = threading.RLock
        self.previous_record_created = time.time_ns() / 1e9
    
    def filter(self, record):
        with self.delta_lock:
            delta = datetime.datetime.fromtimestamp(record.created - self.previous_record_created)
            self.previous_record_created = record.created
        record.delta = delta.strftime('%Hh%Mm%S.%f')
        return True

Upvotes: 0

Shary
Shary

Reputation: 31

I have modified the above code of formatter to work as a filter. This is better because you can now use existing formatting of logger and see the elapsed time as part of the existing logging statement; otherwise, formatter prints on a different line and you can't leverage existing formatting functionality




from datetime import timedelta
import logging
import time


class ElapsedFilter(logging.Filter):
    def __init__(self):
        self.start_time = time.time()
    
    def filter(self, record):
   
        elapsed_seconds = record.created - self.start_time
        #using timedelta here for convenient default formatting
        elapsed = timedelta(seconds = elapsed_seconds)
        record.elapsed=elapsed
        return True


logging.basicConfig(
                level=logging.INFO,
                format="%(asctime)s %(levelname)s %(name)s line %(lineno)d  %(message)s  Elapsed: %(elapsed)s",
                datefmt="%H:%M:%S")


log = logging.getLogger('test')
f = ElapsedFilter()
log.addFilter(f)
log.error("Message 1")

time.sleep(5)

log.error("Message 2")
time.sleep(2)
log.info("Message 3")

Output of this program:

17:59:53 ERROR test line 36  Message 1  Elapsed: 0:00:00.000029
17:59:58 ERROR test line 40  Message 2  Elapsed: 0:00:05.002165
18:00:00 INFO test line 42  Message 3  Elapsed: 0:00:07.004427

Upvotes: 1

Vinay Sajip
Vinay Sajip

Reputation: 99465

Using %(relativeCreated)d field in a conventional Formatter format string will display the milliseconds elapsed since the logging module was loaded. While milliseconds might not be what you want, there's no additional coding required.

Upvotes: 33

Keith
Keith

Reputation: 673

I liked Franky1's answer but I didn't want to lose %(asctime)s style in the log format. Here's a solution that adds a %(delta)s style.

import datetime
import logging
import time

class DeltaTimeFormatter(logging.Formatter):
    def format(self, record):
        duration = datetime.datetime.utcfromtimestamp(record.relativeCreated / 1000)
        record.delta = duration.strftime("%H:%M:%S")
        return super().format(record)

# add custom formatter to root logger
handler = logging.StreamHandler()
LOGFORMAT = '+%(delta)s - %(asctime)s - %(levelname)-9s: %(message)s'
fmt = DeltaTimeFormatter(LOGFORMAT)
handler.setFormatter(fmt)
logging.getLogger().addHandler(handler)
logger = logging.getLogger()

# test of the logger output
logger.error('Test')
for sleep in (1, 2, 3, 4, 5):
    time.sleep(sleep)
    logger.error('logging')

Upvotes: 6

Franky1
Franky1

Reputation: 484

I wrote my own solution based on some stackoverflow ideas.
It is a subclass of logging.Formatter

import datetime
import logging
import time

# subclass of logging.Formatter
class RuntimeFormatter(logging.Formatter):
    def __init__(self, *args, **kwargs):
        super().__init__(*args, **kwargs)
        self.start_time = time.time()
    def formatTime(self, record, datefmt=None):
        duration = datetime.datetime.utcfromtimestamp(record.created - self.start_time)
        elapsed = duration.strftime('%H:%M:%S')
        return "{}".format(elapsed)

# add custom formatter to root logger
LOGFORMAT = '%(asctime)s - %(levelname)-9s: %(message)s'
handler = logging.StreamHandler()
fmt = RuntimeFormatter(LOGFORMAT)
handler.setFormatter(fmt)
logging.getLogger().addHandler(handler)
logger = logging.getLogger()

# test of the logger output
logger.error('Test')

Upvotes: 0

Jeremy Allen
Jeremy Allen

Reputation: 6644

You could write your own formatter:

from datetime import timedelta
import logging
import time

class ElapsedFormatter():

    def __init__(self):
        self.start_time = time.time()

    def format(self, record):
        elapsed_seconds = record.created - self.start_time
        #using timedelta here for convenient default formatting
        elapsed = timedelta(seconds = elapsed_seconds)
        return "{} {}".format(elapsed, record.getMessage())

#add custom formatter to root logger for simple demonstration
handler = logging.StreamHandler()
handler.setFormatter(ElapsedFormatter())
logging.getLogger().addHandler(handler)

log = logging.getLogger('test')
log.error("Message 1")

time.sleep(5)

log.error("Message 2")

Your question refers to the elapsed time from the 'start of program' as well as 'creation of logger' which could mean different things.

This will measure the time elapsed from the creation of CustomFormatter which you could do close to the start of the program or when a logger is created.

Upvotes: 15

Related Questions