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

[Wolf Fink]

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>
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
> [2] https://github.com/slaskawi/jboss-logging-perf-test
>
> _______________________________________________
> 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/74194acb/attachment.html