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