[infinispan-dev] if (trace) logger.tracef - it makes sense

[Sebastian Laskawiec]

Yes, exactly - Radim is correct.

I added also one test - "if(logger.isTraceEnabled()) logger.trace(...)".
The results look like the following:
Benchmark                             Mode  Cnt           Score
Error  Units
MyBenchmark.noVariable               thrpt   20   725265655.062 ±
1777607.124  ops/s
*MyBenchmark.withIsTraceEnabledCheck  thrpt   20   725116016.785 ±
2812327.685  ops/s*
MyBenchmark.withVariable             thrpt   20  2415571350.540 ±
7052276.025  ops/s

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.

Thanks
Sebastian

On Fri, Sep 30, 2016 at 10:36 AM, Radim Vansa <rvansa at redhat.com> wrote:

> Wolf, the isTraceEnabled() is called only once during class
> initialization (if that's a static field) or instance creation, but it
> is usually stored as final field and therefore the JVM is likely to
> optimize the calls.
>
> It's possible to change final fields, and in this case it's not as
> unsafe (the only risk is not logging something and the cost related to
> recompiling the class), but the problematic part is finding them :) In
> Infinispan, you get close to all logging if you inspect all classes in
> component registry (and global component registry). It's not as easy as
> setting the level through JMX, though.
>
> R.
>
> On 09/30/2016 09:43 AM, Wolf Fink wrote:
> > I understand the impact of this, but we should keep in mind that there
> > are some important points where it is worse if you can't change the
> > logging on the fly for a few moments to check something and switch back.
> >
> > For the test my understanding is that you use
> > - the logger.tracef direct
> > - check logger.isTraceEnabled() first
> >
> > I see the variable stored but not used - or am I wrong and the
> > benchmark test do something extra?
> >
> >
> > So interesting would be the difference between
> > - log.trace("xyz")
> > - if(log.isTraceEnabled) log.trace("xyz")
> > - log.tracef("xyz %s", var)
> > - if(log.isTraceEnabled) log.tracef("xyz %s",var)
> > and the construct with storing the log level in a static field
> > - boolean isTrace=log.isTraceEnabled()
> >    if(isTrace) log.tracef("xyz %s",var)
> >
> >
> > On Fri, Sep 30, 2016 at 8:53 AM, Sebastian Laskawiec
> > <slaskawi at redhat.com <mailto:slaskawi at redhat.com>> wrote:
> >
> >     Hey!
> >
> >     A while ago I asked Radim and Dan about these kind of constructs [1]:
> >
> >     private boolean trace = logger.isTraceEnabled(); //stored in a field
> >
> >     ... called in some method ...
> >         if(trace)
> >             logger.tracef(...);
> >     ...
> >
> >     At first they seemed wrong to me, because if one changes logging
> >     level (using JMX for example), the code won't notice it. I also
> >     though it's quite ok to use tracef directly, because JIT will
> >     inline and optimize it.
> >
> >     Unfortunately my benchmarks [2] show that I was wrong.
> >     Logger#tracef indeed checks if the logging level is enabled but
> >     since JBoss Logging may use different backends, the check is not
> >     trivial and is not inlined (at least with default settings). The
> >     performance results look like this:
> >     Benchmark                  Mode  Cnt Score          Error  Units
> >     MyBenchmark.noVariable    thrpt   20 *717252060.124* ±
> >     13420522.229  ops/s
> >     MyBenchmark.withVariable  thrpt   20 *2358360244.627* ±
> >     50214969.572  ops/s
> >
> >     So if you even see a construct like this: logger.debuf or
> >     logger.tracef - make sure you check if the logging level is
> >     enabled (and the check result is stored in a field).
> >
> >     That was a bit surprising and interesting lesson :D
> >
> >     Thanks
> >     Sebastian
> >
> >     [1]
> >     https://github.com/infinispan/infinispan/pull/4538#
> discussion_r80666086
> >     <https://github.com/infinispan/infinispan/pull/
> 4538#discussion_r80666086>
> >     [2] https://github.com/slaskawi/jboss-logging-perf-test
> >     <https://github.com/slaskawi/jboss-logging-perf-test>
> >
> >     _______________________________________________
> >     infinispan-dev mailing list
> >     infinispan-dev at lists.jboss.org <mailto:infinispan-dev at lists.
> jboss.org>
> >     https://lists.jboss.org/mailman/listinfo/infinispan-dev
> >     <https://lists.jboss.org/mailman/listinfo/infinispan-dev>
> >
> >
> >
> >
> > _______________________________________________
> > infinispan-dev mailing list
> > infinispan-dev at lists.jboss.org
> > https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
>
> --
> Radim Vansa <rvansa at redhat.com>
> JBoss Performance Team
>
> _______________________________________________
> infinispan-dev mailing list
> infinispan-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: http://lists.jboss.org/pipermail/infinispan-dev/attachments/20160930/b63714a5/attachment.html