Hi Volkan, On Mon, 5 Feb 2024 at 16:18, Volkan Yazıcı <vol...@yazi.ci> wrote: > I thought of matching the behavior between the two log event factories by > making the `DefaultLogEventFactory` format the message at creation. This > would imply both message factories will be formatting the message eagerly. > (Formatting the message at the logger thread was also suggested by Nitsan > Wakart > <https://github.com/apache/logging-log4j2/issues/2220#issuecomment-1902035073>, > the JVM performance celebrity, too.)
I would prefer for the two event factories **not** to call `Message#getFormattedMessage` at all. During the processing of a log event, filters are applied up to 4 times: 1. Logger: checks global filter and level, 2. Logger: creates message and calls LoggerConfig, 3. LoggerConfig: checks filter and level, 4. LoggerConfig: creates log event and calls AppenderControl, 5. AppenderControl: checks filter and level, 6. AppenderControl: calls appender, 7. AppenderControl: checks filter and level of the Appender, 8. Appender: appends message. If all messages are formatted in 4, we have a huge performance loss for messages that are filtered out in 5 and 7. > While examining the code base on this subject, I came across the > `log4j2.formatMsgAsync` property (flag that *"will make sure the message is > formatted in the caller thread"*) and the `@AsynchronouslyFormattable` > annotation. This gets the things even more complicated: > > ... (omissis) ... > 2. If `log4j2.formatMsgAsync=true`, nested logging does not work > anymore. That is, postponing the message formatting to `log(logEvent)` > causes recursion and hence the nested `log(logEvent)` gets skipped. > (`DefaultLogEventFactory` fails to log the nested call exactly due to the > same reason.) > 3. One would expect these configuration knobs to be effective somewhere > in my nested logging example above. But they surprisingly play no role in > this entire flow in almost all cases. That is, there is > `InternalAsyncUtil.makeMessageImmutable()` taking these configuration knobs > into account, but it is only called in async. contexts (e.g., > `AsyncAppender` or `AsyncLogger) when a message is not reusable. It makes > sense that the configuration is taken into account only when the context is > async. But it should *not* depend on if-the-message-is-reusable > condition. That is, the fact that reusable messages are *always* > formatted eagerly violates the `log4j2.formatMsgAsync=true` condition, if > provided. As Ralph said, I wouldn't care much about nested logging, especially nested logging in a `toString()` method. The contract should be: every nested log event is delivered **or** a warning is submitted to the status logger. Or even better: using logging in a `toString` method causes undefined behavior. https://en.cppreference.com/w/cpp/language/ub > There is a performance issue in the design > of `InternalAsyncUtil.makeMessageImmutable()` too. It invokes > `Message#getFormattedMessage()` to indicate to the message that it can > format the message and cache the result, if possible. Yet, > `getFormattedMessage()` has a return type of `String`, forcing the message > to allocate a string unnecessarily. I guess we could improve that: * AsyncLogger can format the message to `RingBufferLogEvent#messageText`, * AsyncLoggerConfig can do the same if `mutable == true` (i.e. the ring buffer uses mutable objects), * AsyncAppender could also use mutable objects in its queue. Piotr
