Is there a way to print incremental time instead of absolute time with Python logging

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.

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code>logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s')
</code>
<code>logging.basicConfig(level=logging.INFO, format='%(asctime)s - %(levelname)s - %(message)s') </code>
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

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code>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
</code>
<code>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 </code>
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

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code>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
</code>
<code>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 </code>
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.

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code>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")
</code>
<code>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") </code>
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

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code># 0.0000 - INFO - hello 1
# 1.0008 - INFO - hello 2
# 0.0002 - INFO - hello 3
</code>
<code># 0.0000 - INFO - hello 1 # 1.0008 - INFO - hello 2 # 0.0002 - INFO - hello 3 </code>
# 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.

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code>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)
</code>
<code>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) </code>
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

Plain text
Copy to clipboard
Open code in new window
EnlighterJS 3 Syntax Highlighter
<code>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
</code>
<code>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 </code>
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

Trang chủ Giới thiệu Sinh nhật bé trai Sinh nhật bé gái Tổ chức sự kiện Biểu diễn giải trí Dịch vụ khác Trang trí tiệc cưới Tổ chức khai trương Tư vấn dịch vụ Thư viện ảnh Tin tức - sự kiện Liên hệ Chú hề sinh nhật Trang trí YEAR END PARTY công ty Trang trí tất niên cuối năm Trang trí tất niên xu hướng mới nhất Trang trí sinh nhật bé trai Hải Đăng Trang trí sinh nhật bé Khánh Vân Trang trí sinh nhật Bích Ngân Trang trí sinh nhật bé Thanh Trang Thuê ông già Noel phát quà Biểu diễn xiếc khỉ Xiếc quay đĩa Dịch vụ tổ chức sự kiện 5 sao Thông tin về chúng tôi Dịch vụ sinh nhật bé trai Dịch vụ sinh nhật bé gái Sự kiện trọn gói Các tiết mục giải trí Dịch vụ bổ trợ Tiệc cưới sang trọng Dịch vụ khai trương Tư vấn tổ chức sự kiện Hình ảnh sự kiện Cập nhật tin tức Liên hệ ngay Thuê chú hề chuyên nghiệp Tiệc tất niên cho công ty Trang trí tiệc cuối năm Tiệc tất niên độc đáo Sinh nhật bé Hải Đăng Sinh nhật đáng yêu bé Khánh Vân Sinh nhật sang trọng Bích Ngân Tiệc sinh nhật bé Thanh Trang Dịch vụ ông già Noel Xiếc thú vui nhộn Biểu diễn xiếc quay đĩa Dịch vụ tổ chức tiệc uy tín Khám phá dịch vụ của chúng tôi Tiệc sinh nhật cho bé trai Trang trí tiệc cho bé gái Gói sự kiện chuyên nghiệp Chương trình giải trí hấp dẫn Dịch vụ hỗ trợ sự kiện Trang trí tiệc cưới đẹp Khởi đầu thành công với khai trương Chuyên gia tư vấn sự kiện Xem ảnh các sự kiện đẹp Tin mới về sự kiện Kết nối với đội ngũ chuyên gia Chú hề vui nhộn cho tiệc sinh nhật Ý tưởng tiệc cuối năm Tất niên độc đáo Trang trí tiệc hiện đại Tổ chức sinh nhật cho Hải Đăng Sinh nhật độc quyền Khánh Vân Phong cách tiệc Bích Ngân Trang trí tiệc bé Thanh Trang Thuê dịch vụ ông già Noel chuyên nghiệp Xem xiếc khỉ đặc sắc Xiếc quay đĩa thú vị
Trang chủ Giới thiệu Sinh nhật bé trai Sinh nhật bé gái Tổ chức sự kiện Biểu diễn giải trí Dịch vụ khác Trang trí tiệc cưới Tổ chức khai trương Tư vấn dịch vụ Thư viện ảnh Tin tức - sự kiện Liên hệ Chú hề sinh nhật Trang trí YEAR END PARTY công ty Trang trí tất niên cuối năm Trang trí tất niên xu hướng mới nhất Trang trí sinh nhật bé trai Hải Đăng Trang trí sinh nhật bé Khánh Vân Trang trí sinh nhật Bích Ngân Trang trí sinh nhật bé Thanh Trang Thuê ông già Noel phát quà Biểu diễn xiếc khỉ Xiếc quay đĩa
Thiết kế website Thiết kế website Thiết kế website Cách kháng tài khoản quảng cáo Mua bán Fanpage Facebook Dịch vụ SEO Tổ chức sinh nhật