[
https://issues.apache.org/jira/browse/LOG4J2-2399?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16577391#comment-16577391
]
ASF GitHub Bot commented on LOG4J2-2399:
----------------------------------------
Github user cakofony commented on the issue:
https://github.com/apache/logging-log4j2/pull/208
That is correct for this input, though it is entirely dependent on the cost
of converting parameters into string values.
A benchmark with eight string values rather than beans with allocation in
the tostring implementation is much closer, though both of the asynchronously
formatted benchmarks are identical, because the work on the application thread
is the same:
```
Benchmark
(asyncFormatting) (messageFactory) Mode
Cnt Score Error Units
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams
false ParameterizedMessageFactory sample
227620 2754.177 ± 411.508 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.00
false ParameterizedMessageFactory sample
2036.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.50
false ParameterizedMessageFactory sample
2252.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.90
false ParameterizedMessageFactory sample
2492.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.95
false ParameterizedMessageFactory sample
2832.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.99
false ParameterizedMessageFactory sample
5792.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.999
false ParameterizedMessageFactory sample 23968.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.9999
false ParameterizedMessageFactory sample 51095.994
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p1.00
false ParameterizedMessageFactory sample
16596992.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams
false ReusableMessageFactory sample
230147 2444.984 ± 15.601 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.00
false ReusableMessageFactory sample
1938.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.50
false ReusableMessageFactory sample
2264.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.90
false ReusableMessageFactory sample
2456.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.95
false ReusableMessageFactory sample
2580.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.99
false ReusableMessageFactory sample
5008.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.999
false ReusableMessageFactory sample 23328.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.9999
false ReusableMessageFactory sample 53684.634
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p1.00
false ReusableMessageFactory sample
702464.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams
true ParameterizedMessageFactory sample
247582 1183.063 ± 8.424 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.00
true ParameterizedMessageFactory sample
941.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.50
true ParameterizedMessageFactory sample
1036.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.90
true ParameterizedMessageFactory sample
1130.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.95
true ParameterizedMessageFactory sample
1212.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.99
true ParameterizedMessageFactory sample
3512.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.999
true ParameterizedMessageFactory sample 20941.344
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.9999
true ParameterizedMessageFactory sample 34140.813
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p1.00
true ParameterizedMessageFactory sample
108544.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams
true ReusableMessageFactory sample
195230 441.564 ± 8.628 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.00
true ReusableMessageFactory sample
270.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.50
true ReusableMessageFactory sample
366.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.90
true ReusableMessageFactory sample
432.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.95
true ReusableMessageFactory sample
492.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.99
true ReusableMessageFactory sample
1258.000 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.999
true ReusableMessageFactory sample 18848.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p0.9999
true ReusableMessageFactory sample 30772.650
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput8StringParams:throughput8StringParams·p1.00
true ReusableMessageFactory sample
242944.000 ns/op
```
A test with fewer parameters shows a much smaller difference:
Updated to `log("Hello {}", "World")`
```
Benchmark
(asyncFormatting) (messageFactory) Mode
Cnt Score Error Units
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam
false ParameterizedMessageFactory sample
313489 535.499 ± 7.370 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.00
false ParameterizedMessageFactory sample 368.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.50
false ParameterizedMessageFactory sample 454.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.90
false ParameterizedMessageFactory sample 520.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.95
false ParameterizedMessageFactory sample 596.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.99
false ParameterizedMessageFactory sample 1124.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.999
false ParameterizedMessageFactory sample 19104.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.9999
false ParameterizedMessageFactory sample 53600.640
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p1.00
false ParameterizedMessageFactory sample 130432.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam
false ReusableMessageFactory sample
323033 509.602 ± 10.065 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.00
false ReusableMessageFactory sample 290.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.50
false ReusableMessageFactory sample 426.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.90
false ReusableMessageFactory sample 575.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.95
false ReusableMessageFactory sample 630.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.99
false ReusableMessageFactory sample 1068.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.999
false ReusableMessageFactory sample 16800.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.9999
false ReusableMessageFactory sample 38904.077
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p1.00
false ReusableMessageFactory sample 619520.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam
true ParameterizedMessageFactory sample
192159 463.767 ± 8.593 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.00
true ParameterizedMessageFactory sample 255.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.50
true ParameterizedMessageFactory sample 386.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.90
true ParameterizedMessageFactory sample 452.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.95
true ParameterizedMessageFactory sample 516.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.99
true ParameterizedMessageFactory sample 1476.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.999
true ParameterizedMessageFactory sample 17109.760
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.9999
true ParameterizedMessageFactory sample 43423.232
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p1.00
true ParameterizedMessageFactory sample 131584.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam
true ReusableMessageFactory sample
221207 381.790 ± 5.879 ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.00
true ReusableMessageFactory sample 180.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.50
true ReusableMessageFactory sample 320.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.90
true ReusableMessageFactory sample 419.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.95
true ReusableMessageFactory sample 472.000
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.99
true ReusableMessageFactory sample 1119.840
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.999
true ReusableMessageFactory sample 14268.032
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p0.9999
true ReusableMessageFactory sample 29352.806
ns/op
BackgroundFormattingAsyncLoggersBenchmark.throughput1StringParam:throughput1StringParam·p1.00
true ReusableMessageFactory sample 123648.000
ns/op
```
Is the additional complexity worthwhile? I defer to your judgement @remkop.
> 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)
