Quantcast

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

classic Classic list List threaded Threaded
25 messages Options
12
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sebastian Laskawiec
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


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [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 <[hidden email]> 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


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Radim Vansa
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
> <[hidden email] <mailto:[hidden email]>> 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
>     [hidden email] <mailto:[hidden email]>
>     https://lists.jboss.org/mailman/listinfo/infinispan-dev
>     <https://lists.jboss.org/mailman/listinfo/infinispan-dev>
>
>
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev


--
Radim Vansa <[hidden email]>
JBoss Performance Team

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

Re: [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 <[hidden email]> 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
> <[hidden email] <mailto:[hidden email]>> 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
>     [hidden email] <mailto:[hidden email]>
>     https://lists.jboss.org/mailman/listinfo/infinispan-dev
>     <https://lists.jboss.org/mailman/listinfo/infinispan-dev>
>
>
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev


--
Radim Vansa <[hidden email]>
JBoss Performance Team

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

David M. Lloyd
In reply to this post by Sebastian Laskawiec
On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).

What backend where you using with your test?

> 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
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>

--
- DML
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Wolf Fink
Ok,

thanks for clarifying it.

So there is a factor of 3 for the test if no trace is enabled, just for checking.
It makes sense to use it.
But my concern is still that it is sometimes good to have the possibility to enable debug for some important information in production just on the fly and switch it of to prevent from throtteling the server by that log statements or restart the server.
We have the same issue in EAP but here a restart is not that bad as here you don't have to load the cache or rebalance the cluster for stop/start.

- Wolf

On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]> wrote:
On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).

What backend where you using with your test?

> 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
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>

--
- DML
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sebastian Laskawiec
In reply to this post by David M. Lloyd
Hey David!

It's Java Util Logging (so the JDKLogger implementation).

Thanks
Sebastian

On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]> wrote:
On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).

What backend where you using with your test?

> 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
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>

--
- DML
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Dan Berindei
In reply to this post by Wolf Fink
I should stress that we only cache `isTraceEnabled()` in a static
field. Debug logging can still be enabled or disabled on the fly.


Cheers
Dan


On Fri, Sep 30, 2016 at 3:14 PM, Wolf Fink <[hidden email]> wrote:

> Ok,
>
> thanks for clarifying it.
>
> So there is a factor of 3 for the test if no trace is enabled, just for
> checking.
> It makes sense to use it.
> But my concern is still that it is sometimes good to have the possibility to
> enable debug for some important information in production just on the fly
> and switch it of to prevent from throtteling the server by that log
> statements or restart the server.
> We have the same issue in EAP but here a restart is not that bad as here you
> don't have to load the cache or rebalance the cluster for stop/start.
>
> - Wolf
>
> On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]>
> wrote:
>>
>> On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).
>>
>> What backend where you using with your test?
>>
>> > 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
>> > [hidden email]
>> > https://lists.jboss.org/mailman/listinfo/infinispan-dev
>> >
>>
>> --
>> - DML
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sanne Grinovero-3
this discussion appears on this mailing list approximately every 2 years :)

On 30 September 2016 at 13:41, Dan Berindei <[hidden email]> wrote:

> I should stress that we only cache `isTraceEnabled()` in a static
> field. Debug logging can still be enabled or disabled on the fly.
>
>
> Cheers
> Dan
>
>
> On Fri, Sep 30, 2016 at 3:14 PM, Wolf Fink <[hidden email]> wrote:
>> Ok,
>>
>> thanks for clarifying it.
>>
>> So there is a factor of 3 for the test if no trace is enabled, just for
>> checking.
>> It makes sense to use it.
>> But my concern is still that it is sometimes good to have the possibility to
>> enable debug for some important information in production just on the fly
>> and switch it of to prevent from throtteling the server by that log
>> statements or restart the server.
>> We have the same issue in EAP but here a restart is not that bad as here you
>> don't have to load the cache or rebalance the cluster for stop/start.
>>
>> - Wolf
>>
>> On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]>
>> wrote:
>>>
>>> On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).
>>>
>>> What backend where you using with your test?
>>>
>>> > 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
>>> > [hidden email]
>>> > https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>> >
>>>
>>> --
>>> - DML
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>>
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Dennis Reed
As Wolf noted, caching the trace flag is bad when trying to debug issues.

Don't do it!  It's not worth breaking the logging semantics for a
nano-second level performance difference.  (if your trace is being
called enough for that tiny impact to make any real difference, that
trace logging is going to be WAY too verbose to be of any use anyways).

If I see it done, I'm going to open a BZ.

-Dennis


On 09/30/2016 08:23 AM, Sanne Grinovero wrote:

> this discussion appears on this mailing list approximately every 2 years :)
>
> On 30 September 2016 at 13:41, Dan Berindei <[hidden email]> wrote:
>> I should stress that we only cache `isTraceEnabled()` in a static
>> field. Debug logging can still be enabled or disabled on the fly.
>>
>>
>> Cheers
>> Dan
>>
>>
>> On Fri, Sep 30, 2016 at 3:14 PM, Wolf Fink <[hidden email]> wrote:
>>> Ok,
>>>
>>> thanks for clarifying it.
>>>
>>> So there is a factor of 3 for the test if no trace is enabled, just for
>>> checking.
>>> It makes sense to use it.
>>> But my concern is still that it is sometimes good to have the possibility to
>>> enable debug for some important information in production just on the fly
>>> and switch it of to prevent from throtteling the server by that log
>>> statements or restart the server.
>>> We have the same issue in EAP but here a restart is not that bad as here you
>>> don't have to load the cache or rebalance the cluster for stop/start.
>>>
>>> - Wolf
>>>
>>> On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]>
>>> wrote:
>>>>
>>>> On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).
>>>>
>>>> What backend where you using with your test?
>>>>
>>>>> 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
>>>>> [hidden email]
>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>>
>>>>
>>>> --
>>>> - DML
>>>> _______________________________________________
>>>> infinispan-dev mailing list
>>>> [hidden email]
>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>
>>>
>>>
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

David M. Lloyd
The performance problem that this trick is meant to resolve is really a
problem in the logging backend.  It *should* be faster inside of
WildFly, where JBoss LogManager is used, because that project just
checks a single volatile field for the level check... and the path to
that code *should* be inline-friendly.

On 09/30/2016 11:16 AM, Dennis Reed wrote:

> As Wolf noted, caching the trace flag is bad when trying to debug issues.
>
> Don't do it!  It's not worth breaking the logging semantics for a
> nano-second level performance difference.  (if your trace is being
> called enough for that tiny impact to make any real difference, that
> trace logging is going to be WAY too verbose to be of any use anyways).
>
> If I see it done, I'm going to open a BZ.
>
> -Dennis
>
>
> On 09/30/2016 08:23 AM, Sanne Grinovero wrote:
>> this discussion appears on this mailing list approximately every 2 years :)
>>
>> On 30 September 2016 at 13:41, Dan Berindei <[hidden email]> wrote:
>>> I should stress that we only cache `isTraceEnabled()` in a static
>>> field. Debug logging can still be enabled or disabled on the fly.
>>>
>>>
>>> Cheers
>>> Dan
>>>
>>>
>>> On Fri, Sep 30, 2016 at 3:14 PM, Wolf Fink <[hidden email]> wrote:
>>>> Ok,
>>>>
>>>> thanks for clarifying it.
>>>>
>>>> So there is a factor of 3 for the test if no trace is enabled, just for
>>>> checking.
>>>> It makes sense to use it.
>>>> But my concern is still that it is sometimes good to have the possibility to
>>>> enable debug for some important information in production just on the fly
>>>> and switch it of to prevent from throtteling the server by that log
>>>> statements or restart the server.
>>>> We have the same issue in EAP but here a restart is not that bad as here you
>>>> don't have to load the cache or rebalance the cluster for stop/start.
>>>>
>>>> - Wolf
>>>>
>>>> On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]>
>>>> wrote:
>>>>>
>>>>> On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).
>>>>>
>>>>> What backend where you using with your test?
>>>>>
>>>>>> 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
>>>>>> [hidden email]
>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>>>
>>>>>
>>>>> --
>>>>> - DML
>>>>> _______________________________________________
>>>>> infinispan-dev mailing list
>>>>> [hidden email]
>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> infinispan-dev mailing list
>>>> [hidden email]
>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>

--
- DML
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Dan Berindei
In reply to this post by Dennis Reed
Dennis, this has been done in Infinispan ever since 4.0, so feel free
to open a BZ :)

Cheers
Dan


On Fri, Sep 30, 2016 at 7:16 PM, Dennis Reed <[hidden email]> wrote:

> As Wolf noted, caching the trace flag is bad when trying to debug issues.
>
> Don't do it!  It's not worth breaking the logging semantics for a
> nano-second level performance difference.  (if your trace is being
> called enough for that tiny impact to make any real difference, that
> trace logging is going to be WAY too verbose to be of any use anyways).
>
> If I see it done, I'm going to open a BZ.
>
> -Dennis
>
>
> On 09/30/2016 08:23 AM, Sanne Grinovero wrote:
>> this discussion appears on this mailing list approximately every 2 years :)
>>
>> On 30 September 2016 at 13:41, Dan Berindei <[hidden email]> wrote:
>>> I should stress that we only cache `isTraceEnabled()` in a static
>>> field. Debug logging can still be enabled or disabled on the fly.
>>>
>>>
>>> Cheers
>>> Dan
>>>
>>>
>>> On Fri, Sep 30, 2016 at 3:14 PM, Wolf Fink <[hidden email]> wrote:
>>>> Ok,
>>>>
>>>> thanks for clarifying it.
>>>>
>>>> So there is a factor of 3 for the test if no trace is enabled, just for
>>>> checking.
>>>> It makes sense to use it.
>>>> But my concern is still that it is sometimes good to have the possibility to
>>>> enable debug for some important information in production just on the fly
>>>> and switch it of to prevent from throtteling the server by that log
>>>> statements or restart the server.
>>>> We have the same issue in EAP but here a restart is not that bad as here you
>>>> don't have to load the cache or rebalance the cluster for stop/start.
>>>>
>>>> - Wolf
>>>>
>>>> On Fri, Sep 30, 2016 at 1:53 PM, David M. Lloyd <[hidden email]>
>>>> wrote:
>>>>>
>>>>> On 09/30/2016 01:53 AM, Sebastian Laskawiec 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).
>>>>>
>>>>> What backend where you using with your test?
>>>>>
>>>>>> 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
>>>>>> [hidden email]
>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>>>
>>>>>
>>>>> --
>>>>> - DML
>>>>> _______________________________________________
>>>>> infinispan-dev mailing list
>>>>> [hidden email]
>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> infinispan-dev mailing list
>>>> [hidden email]
>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Dan Berindei
In reply to this post by David M. Lloyd
On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <[hidden email]> wrote:
> The performance problem that this trick is meant to resolve is really a
> problem in the logging backend.  It *should* be faster inside of
> WildFly, where JBoss LogManager is used, because that project just
> checks a single volatile field for the level check... and the path to
> that code *should* be inline-friendly.
>

Indeed, we started using this trick because of log4j 1.2, which needs
to walk the logger hierarchy in order to check the level, and it made
a significant difference there.

Nowadays I think it's pretty close to optimal in all logging
frameworks. The only nitpick is that they all use enums for the
levels, and the JIT can't inline Level.TRACE.value as it would with a
Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going to
be more or less equivalent to using a volatile "trace" field in each
class, so it should be suitable even for local read operations that
take < 200ns.

We'd probably still need to weed out some of the trace messages, as we
probably have more than 10 of them during such a read operation. I
confess that I added way too many trace logs myself, precisely because
I knew we are using a static final field and the JIT compiler doesn't
even generate code for that branch.

Cheers
Dan
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sebastian Laskawiec
Hey!

Adding James to this thread.

@Dennis - I think Dan has a point here. The trick with checking a field in a class is 3 times faster. Most of the checks are done in core so they are executed multiple times per operation. Changing all those places is probably not an option.

@David - Let me run a test with JBoss Log Manager and get back to you with some results. But if Dan is right, and the problem is with enum mapping, I will get similar results.

Thanks
Sebastian

On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]> wrote:
On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <[hidden email]> wrote:
> The performance problem that this trick is meant to resolve is really a
> problem in the logging backend.  It *should* be faster inside of
> WildFly, where JBoss LogManager is used, because that project just
> checks a single volatile field for the level check... and the path to
> that code *should* be inline-friendly.
>

Indeed, we started using this trick because of log4j 1.2, which needs
to walk the logger hierarchy in order to check the level, and it made
a significant difference there.

Nowadays I think it's pretty close to optimal in all logging
frameworks. The only nitpick is that they all use enums for the
levels, and the JIT can't inline Level.TRACE.value as it would with a
Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going to
be more or less equivalent to using a volatile "trace" field in each
class, so it should be suitable even for local read operations that
take < 200ns.

We'd probably still need to weed out some of the trace messages, as we
probably have more than 10 of them during such a read operation. I
confess that I added way too many trace logs myself, precisely because
I knew we are using a static final field and the JIT compiler doesn't
even generate code for that branch.

Cheers
Dan
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sebastian Laskawiec
Hey!

Please have a look at the latest perf test results [1][2]:

Benchmark                             Mode  Cnt           Score          Error  Units
MyBenchmark.noVariable               thrpt   20   681131269.875 ±  3961932.923  ops/s
MyBenchmark.withIsTraceEnabledCheck  thrpt   20   676307984.921 ± 14305970.393  ops/s
MyBenchmark.withVariable             thrpt   20  2411000894.582 ± 17382438.635  ops/s

I think there is no surprise here.. using a field, which stores the result of `logger.isTraceEnabled()` evaluation is 3 times faster than other options.

If anyone is interested in printing out JIT stuff, I also ran it with "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and "-XX:+PrintInlining" here [3]. 

I'm not a performance expert but it seems that JIT could not inline the "translate" method because of its size (see line 1861). However it tried several times with different optimizations (and some of them were thrown away - "made not entrant" messages [4]).

Let's wait for James' opinion on this, but I think we should address this issue on JBoss Logging/LogManager side (so I agree with David here) and make those parts inlinable (wow, does this word even exist? :D). Once this is done, we could experiment further in Infinispan codebase and see how this relates to some real world benchmarks...

Thanks
Sebastian


On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec <[hidden email]> wrote:
Hey!

Adding James to this thread.

@Dennis - I think Dan has a point here. The trick with checking a field in a class is 3 times faster. Most of the checks are done in core so they are executed multiple times per operation. Changing all those places is probably not an option.

@David - Let me run a test with JBoss Log Manager and get back to you with some results. But if Dan is right, and the problem is with enum mapping, I will get similar results.

Thanks
Sebastian

On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]> wrote:
On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <[hidden email]> wrote:
> The performance problem that this trick is meant to resolve is really a
> problem in the logging backend.  It *should* be faster inside of
> WildFly, where JBoss LogManager is used, because that project just
> checks a single volatile field for the level check... and the path to
> that code *should* be inline-friendly.
>

Indeed, we started using this trick because of log4j 1.2, which needs
to walk the logger hierarchy in order to check the level, and it made
a significant difference there.

Nowadays I think it's pretty close to optimal in all logging
frameworks. The only nitpick is that they all use enums for the
levels, and the JIT can't inline Level.TRACE.value as it would with a
Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going to
be more or less equivalent to using a volatile "trace" field in each
class, so it should be suitable even for local read operations that
take < 200ns.

We'd probably still need to weed out some of the trace messages, as we
probably have more than 10 of them during such a read operation. I
confess that I added way too many trace logs myself, precisely because
I knew we are using a static final field and the JIT compiler doesn't
even generate code for that branch.

Cheers
Dan
_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev



_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Dan Berindei
Hi Sebastian

I modified your benchmark so that the logger and the trace field are
static final and looked at the generated assembly with JITWatch [1].
Based on the attached assembly listings, caching isTraceEnabled() in a
constant field is "infinitely faster", because there are no assembly
instructions that can be traced back to the test method.

JBossLogManagerLogger::translate() is inlined in this listing, but it
still goes through the switch machinery, I'm guessing because the
ordinal of an Enum is not considered a constant.

Cheers
Dan


[1]: https://github.com/AdoptOpenJDK/jitwatch

On Mon, Oct 3, 2016 at 11:28 AM, Sebastian Laskawiec
<[hidden email]> wrote:

> Hey!
>
> Please have a look at the latest perf test results [1][2]:
>
> Benchmark                             Mode  Cnt           Score
> Error  Units
> MyBenchmark.noVariable               thrpt   20   681131269.875 ±
> 3961932.923  ops/s
> MyBenchmark.withIsTraceEnabledCheck  thrpt   20   676307984.921 ±
> 14305970.393  ops/s
> MyBenchmark.withVariable             thrpt   20  2411000894.582 ±
> 17382438.635  ops/s
>
> I think there is no surprise here.. using a field, which stores the result
> of `logger.isTraceEnabled()` evaluation is 3 times faster than other
> options.
>
> If anyone is interested in printing out JIT stuff, I also ran it with
> "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and "-XX:+PrintInlining"
> here [3].
>
> I'm not a performance expert but it seems that JIT could not inline the
> "translate" method because of its size (see line 1861). However it tried
> several times with different optimizations (and some of them were thrown
> away - "made not entrant" messages [4]).
>
> Let's wait for James' opinion on this, but I think we should address this
> issue on JBoss Logging/LogManager side (so I agree with David here) and make
> those parts inlinable (wow, does this word even exist? :D). Once this is
> done, we could experiment further in Infinispan codebase and see how this
> relates to some real world benchmarks...
>
> Thanks
> Sebastian
>
> [1] https://gist.github.com/slaskawi/6766b6e17c7a28ac8d8962293c48a53c
> [2] Test repository: https://github.com/slaskawi/jboss-logging-perf-test
> [3] https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924bae0
> [4]
> https://www.safaribooksonline.com/library/view/java-performance-the/9781449363512/ch04.html
>
> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec <[hidden email]>
> wrote:
>>
>> Hey!
>>
>> Adding James to this thread.
>>
>> @Dennis - I think Dan has a point here. The trick with checking a field in
>> a class is 3 times faster. Most of the checks are done in core so they are
>> executed multiple times per operation. Changing all those places is probably
>> not an option.
>>
>> @David - Let me run a test with JBoss Log Manager and get back to you with
>> some results. But if Dan is right, and the problem is with enum mapping, I
>> will get similar results.
>>
>> Thanks
>> Sebastian
>>
>> On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]>
>> wrote:
>>>
>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <[hidden email]>
>>> wrote:
>>> > The performance problem that this trick is meant to resolve is really a
>>> > problem in the logging backend.  It *should* be faster inside of
>>> > WildFly, where JBoss LogManager is used, because that project just
>>> > checks a single volatile field for the level check... and the path to
>>> > that code *should* be inline-friendly.
>>> >
>>>
>>> Indeed, we started using this trick because of log4j 1.2, which needs
>>> to walk the logger hierarchy in order to check the level, and it made
>>> a significant difference there.
>>>
>>> Nowadays I think it's pretty close to optimal in all logging
>>> frameworks. The only nitpick is that they all use enums for the
>>> levels, and the JIT can't inline Level.TRACE.value as it would with a
>>> Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going to
>>> be more or less equivalent to using a volatile "trace" field in each
>>> class, so it should be suitable even for local read operations that
>>> take < 200ns.
>>>
>>> We'd probably still need to weed out some of the trace messages, as we
>>> probably have more than 10 of them during such a read operation. I
>>> confess that I added way too many trace logs myself, precisely because
>>> I knew we are using a static final field and the JIT compiler doesn't
>>> even generate code for that branch.
>>>
>>> Cheers
>>> Dan
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>>
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev

const.txt (7K) Download Attachment
tracef.txt (42K) Download Attachment
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sebastian Laskawiec
Awesome Dan! May I ask for a Pull Request: https://github.com/slaskawi/jboss-logging-perf-test?



On Mon, Oct 3, 2016 at 2:40 PM, Dan Berindei <[hidden email]> wrote:
Hi Sebastian

I modified your benchmark so that the logger and the trace field are
static final and looked at the generated assembly with JITWatch [1].
Based on the attached assembly listings, caching isTraceEnabled() in a
constant field is "infinitely faster", because there are no assembly
instructions that can be traced back to the test method.

JBossLogManagerLogger::translate() is inlined in this listing, but it
still goes through the switch machinery, I'm guessing because the
ordinal of an Enum is not considered a constant.

Cheers
Dan


[1]: https://github.com/AdoptOpenJDK/jitwatch

On Mon, Oct 3, 2016 at 11:28 AM, Sebastian Laskawiec
<[hidden email]> wrote:
> Hey!
>
> Please have a look at the latest perf test results [1][2]:
>
> Benchmark                             Mode  Cnt           Score
> Error  Units
> MyBenchmark.noVariable               thrpt   20   681131269.875 ±
> 3961932.923  ops/s
> MyBenchmark.withIsTraceEnabledCheck  thrpt   20   676307984.921 ±
> 14305970.393  ops/s
> MyBenchmark.withVariable             thrpt   20  2411000894.582 ±
> 17382438.635  ops/s
>
> I think there is no surprise here.. using a field, which stores the result
> of `logger.isTraceEnabled()` evaluation is 3 times faster than other
> options.
>
> If anyone is interested in printing out JIT stuff, I also ran it with
> "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and "-XX:+PrintInlining"
> here [3].
>
> I'm not a performance expert but it seems that JIT could not inline the
> "translate" method because of its size (see line 1861). However it tried
> several times with different optimizations (and some of them were thrown
> away - "made not entrant" messages [4]).
>
> Let's wait for James' opinion on this, but I think we should address this
> issue on JBoss Logging/LogManager side (so I agree with David here) and make
> those parts inlinable (wow, does this word even exist? :D). Once this is
> done, we could experiment further in Infinispan codebase and see how this
> relates to some real world benchmarks...
>
> Thanks
> Sebastian
>
> [1] https://gist.github.com/slaskawi/6766b6e17c7a28ac8d8962293c48a53c
> [2] Test repository: https://github.com/slaskawi/jboss-logging-perf-test
> [3] https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924bae0
> [4]
> https://www.safaribooksonline.com/library/view/java-performance-the/9781449363512/ch04.html
>
> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec <[hidden email]>
> wrote:
>>
>> Hey!
>>
>> Adding James to this thread.
>>
>> @Dennis - I think Dan has a point here. The trick with checking a field in
>> a class is 3 times faster. Most of the checks are done in core so they are
>> executed multiple times per operation. Changing all those places is probably
>> not an option.
>>
>> @David - Let me run a test with JBoss Log Manager and get back to you with
>> some results. But if Dan is right, and the problem is with enum mapping, I
>> will get similar results.
>>
>> Thanks
>> Sebastian
>>
>> On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]>
>> wrote:
>>>
>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <[hidden email]>
>>> wrote:
>>> > The performance problem that this trick is meant to resolve is really a
>>> > problem in the logging backend.  It *should* be faster inside of
>>> > WildFly, where JBoss LogManager is used, because that project just
>>> > checks a single volatile field for the level check... and the path to
>>> > that code *should* be inline-friendly.
>>> >
>>>
>>> Indeed, we started using this trick because of log4j 1.2, which needs
>>> to walk the logger hierarchy in order to check the level, and it made
>>> a significant difference there.
>>>
>>> Nowadays I think it's pretty close to optimal in all logging
>>> frameworks. The only nitpick is that they all use enums for the
>>> levels, and the JIT can't inline Level.TRACE.value as it would with a
>>> Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going to
>>> be more or less equivalent to using a volatile "trace" field in each
>>> class, so it should be suitable even for local read operations that
>>> take < 200ns.
>>>
>>> We'd probably still need to weed out some of the trace messages, as we
>>> probably have more than 10 of them during such a read operation. I
>>> confess that I added way too many trace logs myself, precisely because
>>> I knew we are using a static final field and the JIT compiler doesn't
>>> even generate code for that branch.
>>>
>>> Cheers
>>> Dan
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>>
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev


_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Sanne Grinovero-3
I've not looked at any such details but I always  assumed that since the logger frameworks (any of them) need to be able to change the logging level, there must be some way of switching state - at least a volatile read?

And while that could be very cheap, I doubt it would be as easily optimised as a constant.

Since we might not be interested only in the logger method to be inlined, we also want most of the client methods to be considered for inlining.. some of these can be extremely sensitive so such a decision requires a full Infinispan performance test rather than a microbenchmark. (which is useful too but more for the sake of optimising JBoss Logging, not to proof if it's OK to switch all of Infinispan 's internal conventions)


On Mon, 3 Oct 2016, 13:45 Sebastian Laskawiec, <[hidden email]> wrote:
Awesome Dan! May I ask for a Pull Request: https://github.com/slaskawi/jboss-logging-perf-test?



On Mon, Oct 3, 2016 at 2:40 PM, Dan Berindei <[hidden email]> wrote:
Hi Sebastian

I modified your benchmark so that the logger and the trace field are
static final and looked at the generated assembly with JITWatch [1].
Based on the attached assembly listings, caching isTraceEnabled() in a
constant field is "infinitely faster", because there are no assembly
instructions that can be traced back to the test method.

JBossLogManagerLogger::translate() is inlined in this listing, but it
still goes through the switch machinery, I'm guessing because the
ordinal of an Enum is not considered a constant.

Cheers
Dan


[1]: https://github.com/AdoptOpenJDK/jitwatch

On Mon, Oct 3, 2016 at 11:28 AM, Sebastian Laskawiec
<[hidden email]> wrote:
> Hey!
>
> Please have a look at the latest perf test results [1][2]:
>
> Benchmark                             Mode  Cnt           Score
> Error  Units
> MyBenchmark.noVariable               thrpt   20   681131269.875 ±
> 3961932.923  ops/s
> MyBenchmark.withIsTraceEnabledCheck  thrpt   20   676307984.921 ±
> 14305970.393  ops/s
> MyBenchmark.withVariable             thrpt   20  2411000894.582 ±
> 17382438.635  ops/s
>
> I think there is no surprise here.. using a field, which stores the result
> of `logger.isTraceEnabled()` evaluation is 3 times faster than other
> options.
>
> If anyone is interested in printing out JIT stuff, I also ran it with
> "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and "-XX:+PrintInlining"
> here [3].
>
> I'm not a performance expert but it seems that JIT could not inline the
> "translate" method because of its size (see line 1861). However it tried
> several times with different optimizations (and some of them were thrown
> away - "made not entrant" messages [4]).
>
> Let's wait for James' opinion on this, but I think we should address this
> issue on JBoss Logging/LogManager side (so I agree with David here) and make
> those parts inlinable (wow, does this word even exist? :D). Once this is
> done, we could experiment further in Infinispan codebase and see how this
> relates to some real world benchmarks...
>
> Thanks
> Sebastian
>
> [1] https://gist.github.com/slaskawi/6766b6e17c7a28ac8d8962293c48a53c
> [2] Test repository: https://github.com/slaskawi/jboss-logging-perf-test
> [3] https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924bae0
> [4]
> https://www.safaribooksonline.com/library/view/java-performance-the/9781449363512/ch04.html
>
> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec <[hidden email]>
> wrote:
>>
>> Hey!
>>
>> Adding James to this thread.
>>
>> @Dennis - I think Dan has a point here. The trick with checking a field in
>> a class is 3 times faster. Most of the checks are done in core so they are
>> executed multiple times per operation. Changing all those places is probably
>> not an option.
>>
>> @David - Let me run a test with JBoss Log Manager and get back to you with
>> some results. But if Dan is right, and the problem is with enum mapping, I
>> will get similar results.
>>
>> Thanks
>> Sebastian
>>
>> On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]>
>> wrote:
>>>
>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <[hidden email]>
>>> wrote:
>>> > The performance problem that this trick is meant to resolve is really a
>>> > problem in the logging backend.  It *should* be faster inside of
>>> > WildFly, where JBoss LogManager is used, because that project just
>>> > checks a single volatile field for the level check... and the path to
>>> > that code *should* be inline-friendly.
>>> >
>>>
>>> Indeed, we started using this trick because of log4j 1.2, which needs
>>> to walk the logger hierarchy in order to check the level, and it made
>>> a significant difference there.
>>>
>>> Nowadays I think it's pretty close to optimal in all logging
>>> frameworks. The only nitpick is that they all use enums for the
>>> levels, and the JIT can't inline Level.TRACE.value as it would with a
>>> Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going to
>>> be more or less equivalent to using a volatile "trace" field in each
>>> class, so it should be suitable even for local read operations that
>>> take < 200ns.
>>>
>>> We'd probably still need to weed out some of the trace messages, as we
>>> probably have more than 10 of them during such a read operation. I
>>> confess that I added way too many trace logs myself, precisely because
>>> I knew we are using a static final field and the JIT compiler doesn't
>>> even generate code for that branch.
>>>
>>> Cheers
>>> Dan
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>>
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Dan Berindei
On Mon, Oct 3, 2016 at 3:58 PM, Sanne Grinovero <[hidden email]> wrote:
> I've not looked at any such details but I always  assumed that since the
> logger frameworks (any of them) need to be able to change the logging level,
> there must be some way of switching state - at least a volatile read?
>
> And while that could be very cheap, I doubt it would be as easily optimised
> as a constant.
>

True, at some point you need a volatile read -- you can only avoid
that by caching isTraceEnabled(), like we do in Infinispan.

My point was related to this assembly instruction, which reads the
ordinal of Level.TRACE:

0x00007f93951e9fdf: mov rdi,0x76d4e6d48  ;   {oop(a
'org/jboss/logging/Logger$Level')}
0x00007f93951e9fe9: mov ebp  << missing an operand here >>; -
java.lang.Enum::ordinal@1 (line 103)
                             ; -
org.jboss.logging.JBossLogManagerLogger::translate@8 (line 58)
                             ; -
org.jboss.logging.JBossLogManagerLogger::isEnabled@5 (line 35)
                             ; - org.jboss.logging.Logger::tracef@4 (line 287)
                             ; - org.infinispan.MyBenchmark::tracef@7 (line 26)
                             ; -
org.infinispan.generated.MyBenchmark_tracef_jmhTest::tracef_thrpt_jmhStub@15
(line 113)

In an ideal world, the JIT would replace translate(Level.TRACE) with a
constant. But here, even though `0x76d4e6d48` is clearly a constant,
the ordinal is still loaded and checked every time.

> Since we might not be interested only in the logger method to be inlined, we
> also want most of the client methods to be considered for inlining.. some of
> these can be extremely sensitive so such a decision requires a full
> Infinispan performance test rather than a microbenchmark. (which is useful
> too but more for the sake of optimising JBoss Logging, not to proof if it's
> OK to switch all of Infinispan 's internal conventions)
>

Based on the testing both myself and Radim did WRT inlining, it
doesn't make a huge difference. But I agree 100% that before removing
the isTraceEnabled() caching we'd have to benchmark the whole of
Infinispan, and not just JBoss Logging in isolation.

Cheers
Dan

>
> On Mon, 3 Oct 2016, 13:45 Sebastian Laskawiec, <[hidden email]> wrote:
>>
>> Awesome Dan! May I ask for a Pull Request:
>> https://github.com/slaskawi/jboss-logging-perf-test?
>>
>>
>>
>> On Mon, Oct 3, 2016 at 2:40 PM, Dan Berindei <[hidden email]>
>> wrote:
>>>
>>> Hi Sebastian
>>>
>>> I modified your benchmark so that the logger and the trace field are
>>> static final and looked at the generated assembly with JITWatch [1].
>>> Based on the attached assembly listings, caching isTraceEnabled() in a
>>> constant field is "infinitely faster", because there are no assembly
>>> instructions that can be traced back to the test method.
>>>
>>> JBossLogManagerLogger::translate() is inlined in this listing, but it
>>> still goes through the switch machinery, I'm guessing because the
>>> ordinal of an Enum is not considered a constant.
>>>
>>> Cheers
>>> Dan
>>>
>>>
>>> [1]: https://github.com/AdoptOpenJDK/jitwatch
>>>
>>> On Mon, Oct 3, 2016 at 11:28 AM, Sebastian Laskawiec
>>> <[hidden email]> wrote:
>>> > Hey!
>>> >
>>> > Please have a look at the latest perf test results [1][2]:
>>> >
>>> > Benchmark                             Mode  Cnt           Score
>>> > Error  Units
>>> > MyBenchmark.noVariable               thrpt   20   681131269.875 ±
>>> > 3961932.923  ops/s
>>> > MyBenchmark.withIsTraceEnabledCheck  thrpt   20   676307984.921 ±
>>> > 14305970.393  ops/s
>>> > MyBenchmark.withVariable             thrpt   20  2411000894.582 ±
>>> > 17382438.635  ops/s
>>> >
>>> > I think there is no surprise here.. using a field, which stores the
>>> > result
>>> > of `logger.isTraceEnabled()` evaluation is 3 times faster than other
>>> > options.
>>> >
>>> > If anyone is interested in printing out JIT stuff, I also ran it with
>>> > "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and
>>> > "-XX:+PrintInlining"
>>> > here [3].
>>> >
>>> > I'm not a performance expert but it seems that JIT could not inline the
>>> > "translate" method because of its size (see line 1861). However it
>>> > tried
>>> > several times with different optimizations (and some of them were
>>> > thrown
>>> > away - "made not entrant" messages [4]).
>>> >
>>> > Let's wait for James' opinion on this, but I think we should address
>>> > this
>>> > issue on JBoss Logging/LogManager side (so I agree with David here) and
>>> > make
>>> > those parts inlinable (wow, does this word even exist? :D). Once this
>>> > is
>>> > done, we could experiment further in Infinispan codebase and see how
>>> > this
>>> > relates to some real world benchmarks...
>>> >
>>> > Thanks
>>> > Sebastian
>>> >
>>> > [1] https://gist.github.com/slaskawi/6766b6e17c7a28ac8d8962293c48a53c
>>> > [2] Test repository:
>>> > https://github.com/slaskawi/jboss-logging-perf-test
>>> > [3] https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924bae0
>>> > [4]
>>> >
>>> > https://www.safaribooksonline.com/library/view/java-performance-the/9781449363512/ch04.html
>>> >
>>> > On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec
>>> > <[hidden email]>
>>> > wrote:
>>> >>
>>> >> Hey!
>>> >>
>>> >> Adding James to this thread.
>>> >>
>>> >> @Dennis - I think Dan has a point here. The trick with checking a
>>> >> field in
>>> >> a class is 3 times faster. Most of the checks are done in core so they
>>> >> are
>>> >> executed multiple times per operation. Changing all those places is
>>> >> probably
>>> >> not an option.
>>> >>
>>> >> @David - Let me run a test with JBoss Log Manager and get back to you
>>> >> with
>>> >> some results. But if Dan is right, and the problem is with enum
>>> >> mapping, I
>>> >> will get similar results.
>>> >>
>>> >> Thanks
>>> >> Sebastian
>>> >>
>>> >> On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]>
>>> >> wrote:
>>> >>>
>>> >>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd
>>> >>> <[hidden email]>
>>> >>> wrote:
>>> >>> > The performance problem that this trick is meant to resolve is
>>> >>> > really a
>>> >>> > problem in the logging backend.  It *should* be faster inside of
>>> >>> > WildFly, where JBoss LogManager is used, because that project just
>>> >>> > checks a single volatile field for the level check... and the path
>>> >>> > to
>>> >>> > that code *should* be inline-friendly.
>>> >>> >
>>> >>>
>>> >>> Indeed, we started using this trick because of log4j 1.2, which needs
>>> >>> to walk the logger hierarchy in order to check the level, and it made
>>> >>> a significant difference there.
>>> >>>
>>> >>> Nowadays I think it's pretty close to optimal in all logging
>>> >>> frameworks. The only nitpick is that they all use enums for the
>>> >>> levels, and the JIT can't inline Level.TRACE.value as it would with a
>>> >>> Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going
>>> >>> to
>>> >>> be more or less equivalent to using a volatile "trace" field in each
>>> >>> class, so it should be suitable even for local read operations that
>>> >>> take < 200ns.
>>> >>>
>>> >>> We'd probably still need to weed out some of the trace messages, as
>>> >>> we
>>> >>> probably have more than 10 of them during such a read operation. I
>>> >>> confess that I added way too many trace logs myself, precisely
>>> >>> because
>>> >>> I knew we are using a static final field and the JIT compiler doesn't
>>> >>> even generate code for that branch.
>>> >>>
>>> >>> Cheers
>>> >>> Dan
>>> >>> _______________________________________________
>>> >>> infinispan-dev mailing list
>>> >>> [hidden email]
>>> >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>> >>
>>> >>
>>> >
>>> >
>>> > _______________________________________________
>>> > infinispan-dev mailing list
>>> > [hidden email]
>>> > https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>
>
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
Reply | Threaded
Open this post in threaded view
|  
Report Content as Inappropriate

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

Radim Vansa
Aren't we investing a bit too much time to this? The trace level was
cached for ages, has anyone ever complained? Turning on trace level is
completely impractical in production, but that info (or, I'd say 80% of
that) is very useful when debugging race conditions etc., so it makes
sense to keep it there and reduce the cost to minimum.

My 2c

Radim

On 10/03/2016 03:25 PM, Dan Berindei wrote:

> On Mon, Oct 3, 2016 at 3:58 PM, Sanne Grinovero <[hidden email]> wrote:
>> I've not looked at any such details but I always  assumed that since the
>> logger frameworks (any of them) need to be able to change the logging level,
>> there must be some way of switching state - at least a volatile read?
>>
>> And while that could be very cheap, I doubt it would be as easily optimised
>> as a constant.
>>
> True, at some point you need a volatile read -- you can only avoid
> that by caching isTraceEnabled(), like we do in Infinispan.
>
> My point was related to this assembly instruction, which reads the
> ordinal of Level.TRACE:
>
> 0x00007f93951e9fdf: mov rdi,0x76d4e6d48  ;   {oop(a
> 'org/jboss/logging/Logger$Level')}
> 0x00007f93951e9fe9: mov ebp  << missing an operand here >>; -
> java.lang.Enum::ordinal@1 (line 103)
>                               ; -
> org.jboss.logging.JBossLogManagerLogger::translate@8 (line 58)
>                               ; -
> org.jboss.logging.JBossLogManagerLogger::isEnabled@5 (line 35)
>                               ; - org.jboss.logging.Logger::tracef@4 (line 287)
>                               ; - org.infinispan.MyBenchmark::tracef@7 (line 26)
>                               ; -
> org.infinispan.generated.MyBenchmark_tracef_jmhTest::tracef_thrpt_jmhStub@15
> (line 113)
>
> In an ideal world, the JIT would replace translate(Level.TRACE) with a
> constant. But here, even though `0x76d4e6d48` is clearly a constant,
> the ordinal is still loaded and checked every time.
>
>> Since we might not be interested only in the logger method to be inlined, we
>> also want most of the client methods to be considered for inlining.. some of
>> these can be extremely sensitive so such a decision requires a full
>> Infinispan performance test rather than a microbenchmark. (which is useful
>> too but more for the sake of optimising JBoss Logging, not to proof if it's
>> OK to switch all of Infinispan 's internal conventions)
>>
> Based on the testing both myself and Radim did WRT inlining, it
> doesn't make a huge difference. But I agree 100% that before removing
> the isTraceEnabled() caching we'd have to benchmark the whole of
> Infinispan, and not just JBoss Logging in isolation.
>
> Cheers
> Dan
>
>> On Mon, 3 Oct 2016, 13:45 Sebastian Laskawiec, <[hidden email]> wrote:
>>> Awesome Dan! May I ask for a Pull Request:
>>> https://github.com/slaskawi/jboss-logging-perf-test?
>>>
>>>
>>>
>>> On Mon, Oct 3, 2016 at 2:40 PM, Dan Berindei <[hidden email]>
>>> wrote:
>>>> Hi Sebastian
>>>>
>>>> I modified your benchmark so that the logger and the trace field are
>>>> static final and looked at the generated assembly with JITWatch [1].
>>>> Based on the attached assembly listings, caching isTraceEnabled() in a
>>>> constant field is "infinitely faster", because there are no assembly
>>>> instructions that can be traced back to the test method.
>>>>
>>>> JBossLogManagerLogger::translate() is inlined in this listing, but it
>>>> still goes through the switch machinery, I'm guessing because the
>>>> ordinal of an Enum is not considered a constant.
>>>>
>>>> Cheers
>>>> Dan
>>>>
>>>>
>>>> [1]: https://github.com/AdoptOpenJDK/jitwatch
>>>>
>>>> On Mon, Oct 3, 2016 at 11:28 AM, Sebastian Laskawiec
>>>> <[hidden email]> wrote:
>>>>> Hey!
>>>>>
>>>>> Please have a look at the latest perf test results [1][2]:
>>>>>
>>>>> Benchmark                             Mode  Cnt           Score
>>>>> Error  Units
>>>>> MyBenchmark.noVariable               thrpt   20   681131269.875 ±
>>>>> 3961932.923  ops/s
>>>>> MyBenchmark.withIsTraceEnabledCheck  thrpt   20   676307984.921 ±
>>>>> 14305970.393  ops/s
>>>>> MyBenchmark.withVariable             thrpt   20  2411000894.582 ±
>>>>> 17382438.635  ops/s
>>>>>
>>>>> I think there is no surprise here.. using a field, which stores the
>>>>> result
>>>>> of `logger.isTraceEnabled()` evaluation is 3 times faster than other
>>>>> options.
>>>>>
>>>>> If anyone is interested in printing out JIT stuff, I also ran it with
>>>>> "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and
>>>>> "-XX:+PrintInlining"
>>>>> here [3].
>>>>>
>>>>> I'm not a performance expert but it seems that JIT could not inline the
>>>>> "translate" method because of its size (see line 1861). However it
>>>>> tried
>>>>> several times with different optimizations (and some of them were
>>>>> thrown
>>>>> away - "made not entrant" messages [4]).
>>>>>
>>>>> Let's wait for James' opinion on this, but I think we should address
>>>>> this
>>>>> issue on JBoss Logging/LogManager side (so I agree with David here) and
>>>>> make
>>>>> those parts inlinable (wow, does this word even exist? :D). Once this
>>>>> is
>>>>> done, we could experiment further in Infinispan codebase and see how
>>>>> this
>>>>> relates to some real world benchmarks...
>>>>>
>>>>> Thanks
>>>>> Sebastian
>>>>>
>>>>> [1] https://gist.github.com/slaskawi/6766b6e17c7a28ac8d8962293c48a53c
>>>>> [2] Test repository:
>>>>> https://github.com/slaskawi/jboss-logging-perf-test
>>>>> [3] https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924bae0
>>>>> [4]
>>>>>
>>>>> https://www.safaribooksonline.com/library/view/java-performance-the/9781449363512/ch04.html
>>>>>
>>>>> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec
>>>>> <[hidden email]>
>>>>> wrote:
>>>>>> Hey!
>>>>>>
>>>>>> Adding James to this thread.
>>>>>>
>>>>>> @Dennis - I think Dan has a point here. The trick with checking a
>>>>>> field in
>>>>>> a class is 3 times faster. Most of the checks are done in core so they
>>>>>> are
>>>>>> executed multiple times per operation. Changing all those places is
>>>>>> probably
>>>>>> not an option.
>>>>>>
>>>>>> @David - Let me run a test with JBoss Log Manager and get back to you
>>>>>> with
>>>>>> some results. But if Dan is right, and the problem is with enum
>>>>>> mapping, I
>>>>>> will get similar results.
>>>>>>
>>>>>> Thanks
>>>>>> Sebastian
>>>>>>
>>>>>> On Sat, Oct 1, 2016 at 11:53 AM, Dan Berindei <[hidden email]>
>>>>>> wrote:
>>>>>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd
>>>>>>> <[hidden email]>
>>>>>>> wrote:
>>>>>>>> The performance problem that this trick is meant to resolve is
>>>>>>>> really a
>>>>>>>> problem in the logging backend.  It *should* be faster inside of
>>>>>>>> WildFly, where JBoss LogManager is used, because that project just
>>>>>>>> checks a single volatile field for the level check... and the path
>>>>>>>> to
>>>>>>>> that code *should* be inline-friendly.
>>>>>>>>
>>>>>>> Indeed, we started using this trick because of log4j 1.2, which needs
>>>>>>> to walk the logger hierarchy in order to check the level, and it made
>>>>>>> a significant difference there.
>>>>>>>
>>>>>>> Nowadays I think it's pretty close to optimal in all logging
>>>>>>> frameworks. The only nitpick is that they all use enums for the
>>>>>>> levels, and the JIT can't inline Level.TRACE.value as it would with a
>>>>>>> Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's going
>>>>>>> to
>>>>>>> be more or less equivalent to using a volatile "trace" field in each
>>>>>>> class, so it should be suitable even for local read operations that
>>>>>>> take < 200ns.
>>>>>>>
>>>>>>> We'd probably still need to weed out some of the trace messages, as
>>>>>>> we
>>>>>>> probably have more than 10 of them during such a read operation. I
>>>>>>> confess that I added way too many trace logs myself, precisely
>>>>>>> because
>>>>>>> I knew we are using a static final field and the JIT compiler doesn't
>>>>>>> even generate code for that branch.
>>>>>>>
>>>>>>> Cheers
>>>>>>> Dan
>>>>>>> _______________________________________________
>>>>>>> infinispan-dev mailing list
>>>>>>> [hidden email]
>>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>>>
>>>>>
>>>>> _______________________________________________
>>>>> infinispan-dev mailing list
>>>>> [hidden email]
>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>> _______________________________________________
>>>> infinispan-dev mailing list
>>>> [hidden email]
>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> [hidden email]
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> [hidden email]
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
> _______________________________________________
> infinispan-dev mailing list
> [hidden email]
> https://lists.jboss.org/mailman/listinfo/infinispan-dev


--
Radim Vansa <[hidden email]>
JBoss Performance Team

_______________________________________________
infinispan-dev mailing list
[hidden email]
https://lists.jboss.org/mailman/listinfo/infinispan-dev
12
Loading...