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