logging should cache LogRecord.message

[SmartHypercube]

Bug report

Bug description:

logging currently does not cache LogRecord.message:

cpython/Lib/logging/__init__.py

Lines 391 to 401 in 0dcbc83

	def getMessage(self):
	"""
	Return the message for this LogRecord.
	Return the message for this LogRecord after merging any user-supplied
	arguments with the message.
	"""
	msg = str(self.msg)
	if self.args:
	msg = msg % self.args
	return msg

cpython/Lib/logging/__init__.py

Line 711 in 0dcbc83

record.message = record.getMessage()

Since logging caches other string-formatting related results such as LogRecord.asctime and LogRecord.exc_text, I would like to suggest:

1. LogRecord.getMessage should check self.message first. If it is not computed yet, it should compute the message and set this attribute before returning.
2. Formatter shouldn't set record.message. It only needs to call LogRecord.getMessage to get the message.

How to reproduce

import logging

class A:
    def __repr__(self):
        print('repr called')
        return '<A>'

logger = logging.getLogger()
logger.addHandler(logging.StreamHandler())
logger.addHandler(logging.StreamHandler())
logger.error('%r', A())

Expected output

repr called
<A>
<A>

Actual output

repr called
<A>
repr called
<A>

CPython versions tested on:

3.12

Operating systems tested on:

Linux

Linked PRs

• GH-122089: Cache LogRecord.getMessage() the first time the message is formatted #134367

[ZeroIntensity]

This looks like a feature, not a bug. Is there any reason to cache this? str and % are not expensive operations.

[SmartHypercube]

I don't have strong opinion about whether this should be a bug report or a feature request. Please change it if needed.

• str may be expensive, if user uses a custom class for msg with an expensive __str__ method.
• % may also be expensive, for example, when %r is used with a nested class structure.
• User may want to pretty-print a nested structure with different kinds of classes. As long as there is one datetime object, LogRecord.message will be more expensive than LogRecord.asctime, which is currently cached.

https://docs.python.org/3/howto/logging-cookbook.html#implementing-structured-logging shows 2 examples involving expensive __str__ methods. That's actually very similar to my use case. Currently, each Handler in my program calls json.dumps on the same structure repeatedly. I do think it is wasteful and impacting latency.

[ZeroIntensity]

I'm wondering if this would be a breaking change -- could people be relying on getMessage() to call __str__ every time, or something along those lines?

[Zheaoli]

I think this is a breaking change, we may need to discuss it in https://discuss.python.org/

[charfa]

I happen to have a class that I want to log that has an expensive __str__ implementation. In fact right now I'm using f-string to build a log message (like so: logger.debug(f"Data: {data}")) and I was hoping to improve performance by switching to a %-style log (logger.debug("Data: %s", data)). Only to find out that performance with debug logs enabled is actually worse, because data.__str__ is called multiple times.

It's kind of amusing that you'll often hear that using f-strings in logs is bad for performance and you should use % formatting, whereas if you have more than one handler then f-strings are actually better.

[pR0Ps]

I'd like to see this as well. I've submitted a PR that implements it in the event that it's not considered breaking enough that it can't be accepted.

[vsajip]

that it's not considered breaking enough

Hard to say what "enough" is, in this scenario. We have no way of knowing how many people's code could break by implementing this change - and the breakage might be hard to diagnose in practice. I'm not sure the performance improvement is worth it - anyone have any hard numbers? Iif a small number of people have expensive __str__operations, there's nothing stopping them from implementing caching in their code, is there, rather than making a stdlib change which might adversely affect others?