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(a)redhat.com <mailto:slaskawi@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(a)lists.jboss.org <mailto:infinispan-dev@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(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

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(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

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 <david.lloyd(a)redhat.com&gt; 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 > > infinispan-dev(a)lists.jboss.org > > https://lists.jboss.org/mailman/listinfo/infinispan-dev > > > > -- > - DML > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

this discussion appears on this mailing list approximately every 2 years :) On 30 September 2016 at 13:41, Dan Berindei <dan.berindei(a)gmail.com&gt; 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 <wfink(a)redhat.com&gt; 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 <david.lloyd(a)redhat.com&gt; >> 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 >>>> infinispan-dev(a)lists.jboss.org >>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>>> >>> >>> -- >>> - DML >>> _______________________________________________ >>> infinispan-dev mailing list >>> infinispan-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >> >> >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

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.

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 <dan.berindei(a)gmail.com&gt; wrote: > On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd <david.lloyd(a)redhat.com&gt; > 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 > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev >

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 <slaskawi(a)redhat.com&gt; 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 <slaskawi(a)redhat.com > > 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 <dan.berindei(a)gmail.com&gt; >> wrote: >>> >>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd < david.lloyd(a)redhat.com&gt; >>> 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 >>> infinispan-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >> > > > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

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, <slaskawi(a)redhat.com&gt; 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 <dan.berindei(a)gmail.com&gt; > 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 >> <slaskawi(a)redhat.com&gt; 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/97814... >> > >> > On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec >> > <slaskawi(a)redhat.com&gt; >> > 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 <dan.berindei(a)gmail.com&gt; >> >> wrote: >> >>> >> >>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd >> >>> <david.lloyd(a)redhat.com&gt; >> >>> 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 >> >>> infinispan-dev(a)lists.jboss.org >> >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >> >> >> >> > >> > >> > _______________________________________________ >> > infinispan-dev mailing list >> > infinispan-dev(a)lists.jboss.org >> > https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > > > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

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 <sanne(a)infinispan.org&gt; 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, <slaskawi(a)redhat.com&gt; 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 <dan.berindei(a)gmail.com&gt; >>> 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 >>>> <slaskawi(a)redhat.com&gt; 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/97814... >>>>> >>>>> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec >>>>> <slaskawi(a)redhat.com&gt; >>>>> 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 <dan.berindei(a)gmail.com&gt; >>>>>> wrote: >>>>>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd >>>>>>> <david.lloyd(a)redhat.com&gt; >>>>>>> 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 >>>>>>> infinispan-dev(a)lists.jboss.org >>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>>>>> >>>>> >>>>> _______________________________________________ >>>>> infinispan-dev mailing list >>>>> infinispan-dev(a)lists.jboss.org >>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>>> _______________________________________________ >>>> infinispan-dev mailing list >>>> infinispan-dev(a)lists.jboss.org >>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>> >>> _______________________________________________ >>> infinispan-dev mailing list >>> infinispan-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev

On 10/03/2016 08:43 AM, Radim Vansa wrote: > Aren't we investing a bit too much time to this? The trace level was > cached for ages, has anyone ever complained? I have. https://issues.jboss.org/browse/JBCACHE-1625 Looks like I just never copied it over to the ISPN JIRA. :) > Turning on trace level is completely impractical in production, We do it all the time when there's no better option to debug an issue. (generally for as short a period as possible if it's production) -Dennis > 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 <sanne(a)infinispan.org&gt; 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, <slaskawi(a)redhat.com&gt; 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 <dan.berindei(a)gmail.com&gt; >>>> 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 >>>>> <slaskawi(a)redhat.com&gt; 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/6766b6e17c7a28ac8d8962293c48a5 3c >>>>>> [2] Test repository: >>>>>> https://github.com/slaskawi/jboss-logging-perf-test >>>>>> [3] https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924ba e0 >>>>>> [4] >>>>>> >>>>>> https://www.safaribooksonline.com/library/view/java- performance-the/9781449363512/ch04.html >>>>>> >>>>>> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec >>>>>> <slaskawi(a)redhat.com&gt; >>>>>> 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 < dan.berindei(a)gmail.com&gt; >>>>>>> wrote: >>>>>>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd >>>>>>>> <david.lloyd(a)redhat.com&gt; >>>>>>>> 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 >>>>>>>> infinispan-dev(a)lists.jboss.org >>>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>>>>>> >>>>>> >>>>>> _______________________________________________ >>>>>> infinispan-dev mailing list >>>>>> infinispan-dev(a)lists.jboss.org >>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>>>> _______________________________________________ >>>>> infinispan-dev mailing list >>>>> infinispan-dev(a)lists.jboss.org >>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>>> >>>> _______________________________________________ >>>> infinispan-dev mailing list >>>> infinispan-dev(a)lists.jboss.org >>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >>> >>> _______________________________________________ >>> infinispan-dev mailing list >>> infinispan-dev(a)lists.jboss.org >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > > _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

On Tue, Oct 4, 2016 at 10:44 AM, Sebastian Laskawiec <slaskawi(a)redhat.com&gt; wrote: > I think we reached the point where we mention the same arguments over and > over again... > > So let me try to sum it up and possibly iron an action plan out: > > The main reason we cache the "isTraceEnabled" value is speed. It's more than > 3 times faster then checking it before each trace invocation. Actually, if you look at the the assembly code in const.txt, all the assembly instructions are from JMH itself, not from the test method. So caching in a static final is "infinitely faster", not just 3 times faster. > This decreases maintainability since we can't change the logging level in > runtime. Dennis filed a JIRA for it: > https://issues.jboss.org/browse/JBCACHE-1625 We can change the logging level to DEBUG at runtime, which I would argue is enough in most cases. > It doesn't matter which logging backend we use (JDK, JBoss etc). > The main problem is the "translate" method in logger, which translates JBoss > Logging levels into backend's native levels. The "translate" method is used > for all logging levels (since "doLogf" method checks "isEnabled" method > result, which in turn calls "translate"). > As shown on benchmarks with JIT activity, there are two reasons why > "translate" method is not inlined - it's too big and it contains a switch > statement. > Hmmm, I thought the assembly listing in tracef.txt showed that it *is* inlined :) > If you agree with the above, I would like to propose the following action > plan: > > @Dennis - please move the JBCACHE-1625 to Infinispan project and assign it > to me. > @James - I would like to ask you to experiment with optimizing these > methods. It would be great if both "translate" and "isEnabled" methods could > be inlined. I would be more than happy to verify if it works in both my > private benchmarks and if that goes well, with Infinispan stress tests. > IMO there are way too many TRACE logs in the core, and I don't think we can avoid affecting performance without removing 80% of them. And I also think the time spent arguing about this would have been better spent trying to fix some of the random failures in the test suite, i.e. the thing that the excessive TRACE logs are supposed to help us with :) Cheers Dan > Thanks > Sebastian > > On Mon, Oct 3, 2016 at 7:31 PM, Dennis Reed <dereed(a)redhat.com&gt; wrote: >> >> On 10/03/2016 08:43 AM, Radim Vansa wrote: >> > Aren't we investing a bit too much time to this? The trace level was >> > cached for ages, has anyone ever complained? >> >> I have. https://issues.jboss.org/browse/JBCACHE-1625 >> >> Looks like I just never copied it over to the ISPN JIRA. :) >> >> > Turning on trace level is completely impractical in production, >> >> We do it all the time when there's no better option to debug an issue. >> (generally for as short a period as possible if it's production) >> >> -Dennis >> >> > 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 < sanne(a)infinispan.org&gt; >> >> 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, <slaskawi(a)redhat.com > >> >>> 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 < dan.berindei(a)gmail.com&gt; >> >>>> 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 >> >>>>> <slaskawi(a)redhat.com&gt; 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/6766b6e17c7a28ac8d8962293c48a5 3c >> >>>>>> [2] Test repository: >> >>>>>> https://github.com/slaskawi/jboss-logging-perf-test >> >>>>>> [3] >> >>>>>> https://gist.github.com/slaskawi/6f317bb05539611434bc91d66924ba e0 >> >>>>>> [4] >> >>>>>> >> >>>>>> >> >>>>>> https://www.safaribooksonline.com/library/view/java- performance-the/9781449363512/ch04.html >> >>>>>> >> >>>>>> On Mon, Oct 3, 2016 at 7:32 AM, Sebastian Laskawiec >> >>>>>> <slaskawi(a)redhat.com&gt; >> >>>>>> 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 >> >>>>>>> <dan.berindei(a)gmail.com&gt; >> >>>>>>> wrote: >> >>>>>>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd >> >>>>>>>> <david.lloyd(a)redhat.com&gt; >> >>>>>>>> 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 >> >>>>>>>> infinispan-dev(a)lists.jboss.org >> >>>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >>>>>>> >> >>>>>> >> >>>>>> _______________________________________________ >> >>>>>> infinispan-dev mailing list >> >>>>>> infinispan-dev(a)lists.jboss.org >> >>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >>>>> _______________________________________________ >> >>>>> infinispan-dev mailing list >> >>>>> infinispan-dev(a)lists.jboss.org >> >>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >>>> >> >>>> _______________________________________________ >> >>>> infinispan-dev mailing list >> >>>> infinispan-dev(a)lists.jboss.org >> >>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >>> >> >>> _______________________________________________ >> >>> infinispan-dev mailing list >> >>> infinispan-dev(a)lists.jboss.org >> >>> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> >> _______________________________________________ >> >> infinispan-dev mailing list >> >> infinispan-dev(a)lists.jboss.org >> >> https://lists.jboss.org/mailman/listinfo/infinispan-dev >> > >> > >> >> _______________________________________________ >> infinispan-dev mailing list >> infinispan-dev(a)lists.jboss.org >> https://lists.jboss.org/mailman/listinfo/infinispan-dev > > > > _______________________________________________ > infinispan-dev mailing list > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev

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 > infinispan-dev(a)lists.jboss.org > https://lists.jboss.org/mailman/listinfo/infinispan-dev > -- - DML _______________________________________________ infinispan-dev mailing list infinispan-dev(a)lists.jboss.org https://lists.jboss.org/mailman/listinfo/infinispan-dev