[
https://issues.apache.org/jira/browse/LOG4J2-1718?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=15682515#comment-15682515
]
Remko Popma commented on LOG4J2-1718:
-------------------------------------
Actually, the performance story seems a bit more subtle: if the queried class
actually implements the interface, {{instanceof}} is fastest. If _not_
implemented, {{instanceof}} is quite a bit slower... For annotations it is the
other way around: _missing_ annotation is detected fast, _present_ takes longer
(presumably the extra equility check).
Since Messages being {{AsynchronouslyFormattable}} is the exception, this still
looks like a win for using an annotation.
*Java 1.8.0_60 on Windows*
{code}
Benchmark Mode Samples
Score Score error Units
(throughput results omitted)
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationMissing avgt 10
3.666 0.152 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationPresent avgt 10
7.159 0.257 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceImplemented avgt 10
1.646 0.073 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceNotImpl avgt 10
27.423 1.345 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationMissing sample 118069
21.254 0.949 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationPresent sample 112766
27.807 1.163 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceImplemented sample 116673
23.903 1.053 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceNotImpl sample 156893
65.075 1.693 ns/op
(single shot results omitted)
{code}
*1.8.0_45 on Linux*
{code}
Benchmark Mode Samples
Score Score error Units
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationMissing avgt 10
3.337 0.705 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationPresent avgt 10
6.765 0.929 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceImplemented avgt 10
0.945 0.183 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceNotImpl avgt 10
21.985 3.639 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationMissing sample 167913
36.389 5.389 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.annotationPresent sample 127687
76.845 0.317 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceImplemented sample 181215
34.011 0.224 ns/op
o.a.l.l.p.j.AnnotationVsMarkerInterface.interfaceNotImpl sample 110100
69.493 0.568 ns/op
{code}
Updated benchmark code:
{code}
@OutputTimeUnit(TimeUnit.NANOSECONDS)
@Warmup(iterations = 5, time = 1, timeUnit = TimeUnit.SECONDS)
@Measurement(iterations = 10, time = 1, timeUnit = TimeUnit.SECONDS)
@Fork(1)
@State(Scope.Benchmark)
public class AnnotationVsMarkerInterface {
private final SortedArrayStringMap map = new SortedArrayStringMap();
@Benchmark
@BenchmarkMode({Mode.Throughput, Mode.AverageTime, Mode.SampleTime,
Mode.SingleShotTime})
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public Object annotationMissing() {
return map.getClass().isAnnotationPresent(PerformanceSensitive.class);
}
@Benchmark
@BenchmarkMode({Mode.Throughput, Mode.AverageTime, Mode.SampleTime,
Mode.SingleShotTime})
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public Object annotationPresent() {
return this.getClass().isAnnotationPresent(State.class);
}
@Benchmark
@BenchmarkMode({Mode.Throughput, Mode.AverageTime, Mode.SampleTime,
Mode.SingleShotTime})
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public boolean interfaceNotImpl() {
return map instanceof StringBuilderFormattable;
}
@Benchmark
@BenchmarkMode({Mode.Throughput, Mode.AverageTime, Mode.SampleTime,
Mode.SingleShotTime})
@OutputTimeUnit(TimeUnit.NANOSECONDS)
public boolean interfaceImplemented() {
return map instanceof StringMap;
}
}
{code}
> Introduce marker interface AsynchronouslyFormattable
> ----------------------------------------------------
>
> Key: LOG4J2-1718
> URL: https://issues.apache.org/jira/browse/LOG4J2-1718
> Project: Log4j 2
> Issue Type: Improvement
> Components: API
> Affects Versions: 2.7
> Reporter: Remko Popma
> Assignee: Remko Popma
> Fix For: 2.8
>
>
> Logging mutable objects asynchronously always has the risk that the object is
> modified between the time the logger is called and the time the log message
> is formatted and written to disk.
> Log4j built-in Message implementation classes prevent this race condition in
> one of two ways:
> * Implement the {{ReusableMessage}} interface. Asynchronous logging
> components in log4j cooperate with ReusableMessages by copying their
> _content_ (formatted message, parameters) into the LogEvent rather than
> passing the Message instance itself. This ensures the formatted message will
> not change when the mutable object is modified.
> * Cache the formatted message when the {{getFormattedMessage}} method is
> called. Asynchronous logging components in log4j will call this method before
> passing the Message object to another thread. (See LOG4J2-763.) For example,
> FormattedMessage, LocalizedMessage, MessageFormatMessage, ObjectArrayMessage,
> ObjectMessage, ParameterizedMessage, SimpleMessage and StringFormattedMessage
> take this approach. Once initialized, {{getFormattedMessage}} returns the
> cached String, so changes to the mutable object will not impact the formatted
> message.
> For performance reasons, users can choose to format _all_ messages in the
> background by setting system property {{log4j.format.msg.async}} to true.
> (See LOG4J2-898.)
> Some messages do not capture mutable objects and are not at risk of the above
> race condition.
> This ticket proposes to introduce interface {{AsynchronouslyFormattable}} as
> a marker interface to signal to asynchronous logging components that messages
> of this type can safely be passed to a background thread without calling
> {{getFormattedMessage}} first.
> This benefits performance and avoids creating unnecessary (unused) objects.
> Candidates for implementing this interface are message implementations which
> do not cache anything in {{getFormattedMessage}}:
> * flow messages (SimpleEntryMessage and SimpleExitMessage)
> * MapMessage
> * StructuredDataMessage
> * ThreadDumpMessage (threads are cached in the constructor)
--
This message was sent by Atlassian JIRA
(v6.3.4#6332)
---------------------------------------------------------------------
To unsubscribe, e-mail: log4j-dev-unsubscr...@logging.apache.org
For additional commands, e-mail: log4j-dev-h...@logging.apache.org
