When using Python logging, asctime
is very handy in looking at the hotspots in code. However, I have to decode or post-process the log to show incremental time taken between each log message.
logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s')
Is there a way to print incremental time instead?
I understand logging is meant to handle parallel threads etc., so incremental may not make much sense, but it helps a lot in simple cases.
What I get now
2024-09-13 12:37:19,981 - INFO - Got a Chunk of Data in 1.662097 seconds
2024-09-13 12:37:19,989 - INFO - Processed the Chunk in 0.008471 seconds
2024-09-13 12:37:19,993 - INFO - Optimized the Data in 0.002940 seconds
What I am looking for
1.662097 - INFO - Got a Chunk of Data in 1.662097 seconds
0.008471 - INFO - Processed the Chunk in 0.008471 seconds
0.002940 - INFO - Optimized the Data in 0.002940 seconds
Or something similar
3
You can use log record factories to add custom attributes. This way any module can use the custom logging without having to pass Filter or Adapter objects around, tying yourself to one type of logging (e.g., Stream, HTTP, etc), or forcing a single format string.
import logging
import time
def getLogRecordFactory():
'Returns a custom log record factory that adds a deltaTime attribute to the log record'
oldLogRecordFactory = logging.getLogRecordFactory()
def recordFactory(*args, **kwargs):
# For the first time, create the lastLogTime attribute (makes delta=0)
if not hasattr(recordFactory, 'lastLogTime'):
recordFactory.lastLogTime = time.perf_counter()
# Calculate the time difference between the current log and the previous log
currentTime = time.perf_counter()
delta = currentTime - recordFactory.lastLogTime
recordFactory.lastLogTime = currentTime
# Create the log record and add the deltaTime attribute
record = oldLogRecordFactory(*args, **kwargs)
record.deltaTime = f'{delta:6.4f} sec'
return record
return recordFactory
logging.setLogRecordFactory(getLogRecordFactory())
# Usage:
logging.basicConfig(level=logging.INFO, format='%(deltaTime)s - %(levelname)s - %(message)s')
logging.info("hello 1")
time.sleep(1)
logging.info("hello 2")
logging.info("hello 3")
Sample Output
# 0.0000 - INFO - hello 1
# 1.0008 - INFO - hello 2
# 0.0002 - INFO - hello 3
3
This solution might not be perfect if you log several messages comming from different sources. But you can achieve the desired output by using a custom logging formatter that calculates the incremental time between log messages.
The idea is to subclass logging.Formatter and override its format method to compute the elapsed time since the last log message.
import logging
import time
class IncrementalTimeFormatter(logging.Formatter):
def __init__(self, fmt=None, datefmt=None):
super().__init__(fmt, datefmt)
self.last_time = time.perf_counter()
def format(self, record):
current_time = time.perf_counter()
incremental_time = current_time - self.last_time
self.last_time = current_time
record.incremental_time = f"{incremental_time:.6f}"
return super().format(record)
logger = logging.getLogger()
logger.setLevel(logging.INFO)
formatter = IncrementalTimeFormatter('%(incremental_time)s - %(levelname)s - %(message)s')
# Create a console handler with the custom formatter
ch = logging.StreamHandler()
ch.setFormatter(formatter)
logger.addHandler(ch)
Testing
logger.info("First time")
time.sleep(1.662097)
logger.info("Got a Chunk of Data in 1.662097 seconds")
time.sleep(0.008471) # Simulate processing time
logger.info("Processed the Chunk in 0.008471 seconds")
time.sleep(0.002940) # Simulate processing time
logger.info("Optimized the Data in 0.002940 seconds")
>>>
0.000000 - INFO - First time
1.665573 - INFO - Got a Chunk of Data in 1.662097 seconds
0.012226 - INFO - Processed the Chunk in 0.008471 seconds
0.005708 - INFO - Optimized the Data in 0.002940 seconds
Note, the timing is not perfect with very short times
1