[
https://issues.apache.org/jira/browse/LOG4J2-2399?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16576791#comment-16576791
]
ASF GitHub Bot commented on LOG4J2-2399:
----------------------------------------
Github user bjlaub commented on the issue:
https://github.com/apache/logging-log4j2/pull/208
@remkop @cakofony if i'm understanding correctly the goal here is to make
sure the work of formatting messages is moved off of the application logging
thread and on to a background thread. I've tried to add a benchmark to
demonstrate that - the total amount of work ends up the same in practice, but
the benchmark should show that we're offloading the work of formatting to a
background thread when using ReusableMessages and async formatting. Results are
below:
```
# Run complete. Total time: 00:06:05
Benchmark
(asyncFormatting) (messageFactory) Mode
Cnt Score Error Units
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams
false ParameterizedMessageFactory sample
983443 3963.993 ± 122.528 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.00
false ParameterizedMessageFactory sample
3244.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.50
false ParameterizedMessageFactory sample
3488.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.90
false ParameterizedMessageFactory sample
3724.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.95
false ParameterizedMessageFactory sample
4296.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.99
false ParameterizedMessageFactory sample
12224.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.999
false ParameterizedMessageFactory sample 25728.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.9999
false ParameterizedMessageFactory sample 55913.958
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p1.00
false ParameterizedMessageFactory sample
7651328.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams
false ReusableMessageFactory sample
904581 4452.558 ± 553.731 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.00
false ReusableMessageFactory sample
3132.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.50
false ReusableMessageFactory sample
3500.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.90
false ReusableMessageFactory sample
4832.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.95
false ReusableMessageFactory sample
5416.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.99
false ReusableMessageFactory sample
16640.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.999
false ReusableMessageFactory sample 41216.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.9999
false ReusableMessageFactory sample 176149.402
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p1.00
false ReusableMessageFactory sample
85590016.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams
true ParameterizedMessageFactory sample
813313 1322.547 ± 166.508 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.00
true ParameterizedMessageFactory sample
935.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.50
true ParameterizedMessageFactory sample
1038.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.90
true ParameterizedMessageFactory sample
1264.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.95
true ParameterizedMessageFactory sample
1538.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.99
true ParameterizedMessageFactory sample
4192.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.999
true ParameterizedMessageFactory sample 23061.952
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.9999
true ParameterizedMessageFactory sample 48597.581
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p1.00
true ParameterizedMessageFactory sample
21561344.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams
true ReusableMessageFactory sample
612640 449.432 ± 4.292 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.00
true ReusableMessageFactory sample
273.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.50
true ReusableMessageFactory sample
381.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.90
true ReusableMessageFactory sample
498.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.95
true ReusableMessageFactory sample
549.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.99
true ReusableMessageFactory sample
791.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.999
true ReusableMessageFactory sample 13621.744
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p0.9999
true ReusableMessageFactory sample 27040.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8ComplexParams:throughput8ComplexParams·p1.00
true ReusableMessageFactory sample
384512.000 ns/op
```
> Reusable Messages do not respect log4j.format.msg.async
> -------------------------------------------------------
>
> Key: LOG4J2-2399
> URL: https://issues.apache.org/jira/browse/LOG4J2-2399
> Project: Log4j 2
> Issue Type: Task
> Components: Core
> Reporter: Carter Kozak
> Assignee: Carter Kozak
> Priority: Major
>
> Setting "log4j.format.msg.async" applies only to messages that do not
> implement ReusableMessage.
> On applications using asynchronous logging with message formatting in the
> background there is a measurable performance cost to using
> ReusableParameterizedMessages instead of ParameterizedMessages due to
> formatting on the application thread
> (MutableLogEvent/RingBufferLogEvent.setMessage).
> I have a custom layout which does not log formatted messages in most cases,
> but the format string and parameter values separately in order to analyze
> values logged over time bucketed by logger name and format string. In this
> case the formatting is unnecessary work. It is possible to implement a custom
> message factory which doesn't format message data, however that would break
> the ability to add a standard pattern layout in addition to the custom
> formatter.
> h2. Proposed Design
> Our reusable events (MutableLogEvent and RingBufferLogEvent) currently
> capture most of the required information, the format string and parameter
> array, but are missing a bit of context for how the original message
> implementation would format that data.
> ReusableMessage implementations may optionally extend
> "MessageContentFormatterProvider"
> {code:java}
> interface MessageContentFormatterProvider {
> MessageContentFormatter getMessageContentFormatter();
> }{code}
> Where MessageContentFormatter takes the form:
> {code:java}
> interface MessageContentFormatter {
> void appendTo(StringBuilder dest, String format, Object[] params, short
> paramCount);
> }{code}
> Reusable log event implementations will be updated to hold a reference to the
> content formatter (instead of formatting to the local event buffer) when
> asynchronous formatting is enabled _and_ the message is an instance of
> MessageContentFormatterProvider.
>
--
This message was sent by Atlassian JIRA
(v7.6.3#76005)
