<div dir="ltr">Yes, exactly - Radim is correct.<div><br></div><div>I added also one test - "if(logger.isTraceEnabled()) logger.trace(...)". The results look like the following:</div><div><div>Benchmark Mode Cnt Score Error Units</div><div>MyBenchmark.noVariable thrpt 20 725265655.062 ± 1777607.124 ops/s</div><div><b>MyBenchmark.withIsTraceEnabledCheck thrpt 20 725116016.785 ± 2812327.685 ops/s</b></div><div>MyBenchmark.withVariable thrpt 20 2415571350.540 ± 7052276.025 ops/s</div></div><div><br></div><div>Both results (logger.tracef(...) and if(logger.isTraceEnabled()) logger.tracef(...)) look exactly the same. This is expected because logger.tracef checks if proper level is enabled before processing input.</div><div><br></div><div>Thanks</div><div>Sebastian</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Fri, Sep 30, 2016 at 10:36 AM, Radim Vansa <span dir="ltr"><<a href="mailto:rvansa@redhat.com" target="_blank">rvansa@redhat.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Wolf, the isTraceEnabled() is called only once during class<br>
initialization (if that's a static field) or instance creation, but it<br>
is usually stored as final field and therefore the JVM is likely to<br>
optimize the calls.<br>
<br>
It's possible to change final fields, and in this case it's not as<br>
unsafe (the only risk is not logging something and the cost related to<br>
recompiling the class), but the problematic part is finding them :) In<br>
Infinispan, you get close to all logging if you inspect all classes in<br>
component registry (and global component registry). It's not as easy as<br>
setting the level through JMX, though.<br>
<br>
R.<br>
<span class=""><br>
On 09/30/2016 09:43 AM, Wolf Fink wrote:<br>
> I understand the impact of this, but we should keep in mind that there<br>
> are some important points where it is worse if you can't change the<br>
> logging on the fly for a few moments to check something and switch back.<br>
><br>
> For the test my understanding is that you use<br>
> - the logger.tracef direct<br>
> - check logger.isTraceEnabled() first<br>
><br>
> I see the variable stored but not used - or am I wrong and the<br>
> benchmark test do something extra?<br>
><br>
><br>
> So interesting would be the difference between<br>
> - log.trace("xyz")<br>
> - if(log.isTraceEnabled) log.trace("xyz")<br>
> - log.tracef("xyz %s", var)<br>
> - if(log.isTraceEnabled) log.tracef("xyz %s",var)<br>
> and the construct with storing the log level in a static field<br>
> - boolean isTrace=log.isTraceEnabled()<br>
> if(isTrace) log.tracef("xyz %s",var)<br>
><br>
><br>
> On Fri, Sep 30, 2016 at 8:53 AM, Sebastian Laskawiec<br>
</span><span class="">> <<a href="mailto:slaskawi@redhat.com">slaskawi@redhat.com</a> <mailto:<a href="mailto:slaskawi@redhat.com">slaskawi@redhat.com</a>>> wrote:<br>
><br>
> Hey!<br>
><br>
> A while ago I asked Radim and Dan about these kind of constructs [1]:<br>
><br>
> private boolean trace = logger.isTraceEnabled(); //stored in a field<br>
><br>
> ... called in some method ...<br>
> if(trace)<br>
> logger.tracef(...);<br>
> ...<br>
><br>
> At first they seemed wrong to me, because if one changes logging<br>
> level (using JMX for example), the code won't notice it. I also<br>
> though it's quite ok to use tracef directly, because JIT will<br>
> inline and optimize it.<br>
><br>
> Unfortunately my benchmarks [2] show that I was wrong.<br>
> Logger#tracef indeed checks if the logging level is enabled but<br>
> since JBoss Logging may use different backends, the check is not<br>
> trivial and is not inlined (at least with default settings). The<br>
> performance results look like this:<br>
> Benchmark Mode Cnt Score Error Units<br>
</span>> MyBenchmark.noVariable thrpt 20 *717252060.124* ±<br>
> 13420522.229 ops/s<br>
> MyBenchmark.withVariable thrpt 20 *2358360244.627* ±<br>
<span class="">> 50214969.572 ops/s<br>
><br>
> So if you even see a construct like this: logger.debuf or<br>
> logger.tracef - make sure you check if the logging level is<br>
> enabled (and the check result is stored in a field).<br>
><br>
> That was a bit surprising and interesting lesson :D<br>
><br>
> Thanks<br>
> Sebastian<br>
><br>
> [1]<br>
> <a href="https://github.com/infinispan/infinispan/pull/4538#discussion_r80666086" rel="noreferrer" target="_blank">https://github.com/infinispan/<wbr>infinispan/pull/4538#<wbr>discussion_r80666086</a><br>
> <<a href="https://github.com/infinispan/infinispan/pull/4538#discussion_r80666086" rel="noreferrer" target="_blank">https://github.com/<wbr>infinispan/infinispan/pull/<wbr>4538#discussion_r80666086</a>><br>
> [2] <a href="https://github.com/slaskawi/jboss-logging-perf-test" rel="noreferrer" target="_blank">https://github.com/slaskawi/<wbr>jboss-logging-perf-test</a><br>
> <<a href="https://github.com/slaskawi/jboss-logging-perf-test" rel="noreferrer" target="_blank">https://github.com/slaskawi/<wbr>jboss-logging-perf-test</a>><br>
><br>
> ______________________________<wbr>_________________<br>
> infinispan-dev mailing list<br>
</span>> <a href="mailto:infinispan-dev@lists.jboss.org">infinispan-dev@lists.jboss.org</a> <mailto:<a href="mailto:infinispan-dev@lists.jboss.org">infinispan-dev@lists.<wbr>jboss.org</a>><br>
> <a href="https://lists.jboss.org/mailman/listinfo/infinispan-dev" rel="noreferrer" target="_blank">https://lists.jboss.org/<wbr>mailman/listinfo/infinispan-<wbr>dev</a><br>
> <<a href="https://lists.jboss.org/mailman/listinfo/infinispan-dev" rel="noreferrer" target="_blank">https://lists.jboss.org/<wbr>mailman/listinfo/infinispan-<wbr>dev</a>><br>
<span class="im HOEnZb">><br>
><br>
><br>
><br>
> ______________________________<wbr>_________________<br>
> infinispan-dev mailing list<br>
> <a href="mailto:infinispan-dev@lists.jboss.org">infinispan-dev@lists.jboss.org</a><br>
> <a href="https://lists.jboss.org/mailman/listinfo/infinispan-dev" rel="noreferrer" target="_blank">https://lists.jboss.org/<wbr>mailman/listinfo/infinispan-<wbr>dev</a><br>
<br>
<br>
</span><span class="HOEnZb"><font color="#888888">--<br>
Radim Vansa <<a href="mailto:rvansa@redhat.com">rvansa@redhat.com</a>><br>
JBoss Performance Team<br>
</font></span><div class="HOEnZb"><div class="h5"><br>
______________________________<wbr>_________________<br>
infinispan-dev mailing list<br>
<a href="mailto:infinispan-dev@lists.jboss.org">infinispan-dev@lists.jboss.org</a><br>
<a href="https://lists.jboss.org/mailman/listinfo/infinispan-dev" rel="noreferrer" target="_blank">https://lists.jboss.org/<wbr>mailman/listinfo/infinispan-<wbr>dev</a><br>
</div></div></blockquote></div><br></div>