<div dir="ltr">ahhh, for some reason I missed that. Sorry guys...<div><br></div><div>In that case there's probably not much we can do. The only missing bit is what to do with JBCACHE-1625?</div></div><div class="gmail_extra"><br><div class="gmail_quote">On Tue, Oct 4, 2016 at 12:24 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"><span class="">On Tue, Oct 4, 2016 at 10:44 AM, Sebastian Laskawiec<br>
<<a href="mailto:slaskawi@redhat.com">slaskawi@redhat.com</a>> wrote:<br>
> I think we reached the point where we mention the same arguments over and<br>
> over again...<br>
><br>
> So let me try to sum it up and possibly iron an action plan out:<br>
><br>
> The main reason we cache the "isTraceEnabled" value is speed. It's more than<br>
> 3 times faster then checking it before each trace invocation.<br>
<br>
</span>Actually, if you look at the the assembly code in const.txt, all the<br>
assembly instructions are from JMH itself, not from the test method.<br>
So caching in a static final is "infinitely faster", not just 3 times<br>
faster.<br>
<span class=""><br>
> This decreases maintainability since we can't change the logging level in<br>
> runtime. Dennis filed a JIRA for it:<br>
> <a href="https://issues.jboss.org/browse/JBCACHE-1625" rel="noreferrer" target="_blank">https://issues.jboss.org/<wbr>browse/JBCACHE-1625</a><br>
<br>
</span>We can change the logging level to DEBUG at runtime, which I would<br>
argue is enough in most cases.<br>
<span class=""><br>
> It doesn't matter which logging backend we use (JDK, JBoss etc).<br>
> The main problem is the "translate" method in logger, which translates JBoss<br>
> Logging levels into backend's native levels. The "translate" method is used<br>
> for all logging levels (since "doLogf" method checks "isEnabled" method<br>
> result, which in turn calls "translate").<br>
> As shown on benchmarks with JIT activity, there are two reasons why<br>
> "translate" method is not inlined - it's too big and it contains a switch<br>
> statement.<br>
><br>
<br>
</span>Hmmm, I thought the assembly listing in tracef.txt showed that it *is*<br>
inlined :)<br>
<span class=""><br>
> If you agree with the above, I would like to propose the following action<br>
> plan:<br>
><br>
> @Dennis - please move the JBCACHE-1625 to Infinispan project and assign it<br>
> to me.<br>
> @James - I would like to ask you to experiment with optimizing these<br>
> methods. It would be great if both "translate" and "isEnabled" methods could<br>
> be inlined. I would be more than happy to verify if it works in both my<br>
> private benchmarks and if that goes well, with Infinispan stress tests.<br>
><br>
<br>
</span>IMO there are way too many TRACE logs in the core, and I don't think<br>
we can avoid affecting performance without removing 80% of them. And I<br>
also think the time spent arguing about this would have been better<br>
spent trying to fix some of the random failures in the test suite,<br>
i.e. the thing that the excessive TRACE logs are supposed to help us<br>
with :)<br>
<br>
Cheers<br>
<span class="HOEnZb"><font color="#888888">Dan<br>
</font></span><div class="HOEnZb"><div class="h5"><br>
<br>
> Thanks<br>
> Sebastian<br>
><br>
> On Mon, Oct 3, 2016 at 7:31 PM, Dennis Reed <<a href="mailto:dereed@redhat.com">dereed@redhat.com</a>> wrote:<br>
>><br>
>> On 10/03/2016 08:43 AM, Radim Vansa wrote:<br>
>> > Aren't we investing a bit too much time to this? The trace level was<br>
>> > cached for ages, has anyone ever complained?<br>
>><br>
>> I have. <a href="https://issues.jboss.org/browse/JBCACHE-1625" rel="noreferrer" target="_blank">https://issues.jboss.org/<wbr>browse/JBCACHE-1625</a><br>
>><br>
>> Looks like I just never copied it over to the ISPN JIRA. :)<br>
>><br>
>> > Turning on trace level is completely impractical in production,<br>
>><br>
>> We do it all the time when there's no better option to debug an issue.<br>
>> (generally for as short a period as possible if it's production)<br>
>><br>
>> -Dennis<br>
>><br>
>> > but that info (or, I'd say 80% of<br>
>> > that) is very useful when debugging race conditions etc., so it makes<br>
>> > sense to keep it there and reduce the cost to minimum.<br>
>> ><br>
>> > My 2c<br>
>> ><br>
>> > Radim<br>
>> ><br>
>> > On 10/03/2016 03:25 PM, Dan Berindei wrote:<br>
>> >> On Mon, Oct 3, 2016 at 3:58 PM, Sanne Grinovero <<a href="mailto:sanne@infinispan.org">sanne@infinispan.org</a>><br>
>> >> wrote:<br>
>> >>> I've not looked at any such details but I always assumed that since<br>
>> >>> the<br>
>> >>> logger frameworks (any of them) need to be able to change the logging<br>
>> >>> level,<br>
>> >>> there must be some way of switching state - at least a volatile read?<br>
>> >>><br>
>> >>> And while that could be very cheap, I doubt it would be as easily<br>
>> >>> optimised<br>
>> >>> as a constant.<br>
>> >>><br>
>> >> True, at some point you need a volatile read -- you can only avoid<br>
>> >> that by caching isTraceEnabled(), like we do in Infinispan.<br>
>> >><br>
>> >> My point was related to this assembly instruction, which reads the<br>
>> >> ordinal of Level.TRACE:<br>
>> >><br>
>> >> 0x00007f93951e9fdf: mov rdi,0x76d4e6d48 ; {oop(a<br>
>> >> 'org/jboss/logging/Logger$<wbr>Level')}<br>
>> >> 0x00007f93951e9fe9: mov ebp << missing an operand here >>; -<br>
>> >> java.lang.Enum::ordinal@1 (line 103)<br>
>> >> ; -<br>
>> >> org.jboss.logging.<wbr>JBossLogManagerLogger::<wbr>translate@8 (line 58)<br>
>> >> ; -<br>
>> >> org.jboss.logging.<wbr>JBossLogManagerLogger::<wbr>isEnabled@5 (line 35)<br>
>> >> ; - org.jboss.logging.Logger::<wbr>tracef@4<br>
>> >> (line 287)<br>
>> >> ; - org.infinispan.MyBenchmark::<wbr>tracef@7<br>
>> >> (line 26)<br>
>> >> ; -<br>
>> >><br>
>> >> org.infinispan.generated.<wbr>MyBenchmark_tracef_jmhTest::<wbr>tracef_thrpt_jmhStub@15<br>
>> >> (line 113)<br>
>> >><br>
>> >> In an ideal world, the JIT would replace translate(Level.TRACE) with a<br>
>> >> constant. But here, even though `0x76d4e6d48` is clearly a constant,<br>
>> >> the ordinal is still loaded and checked every time.<br>
>> >><br>
>> >>> Since we might not be interested only in the logger method to be<br>
>> >>> inlined, we<br>
>> >>> also want most of the client methods to be considered for inlining..<br>
>> >>> some of<br>
>> >>> these can be extremely sensitive so such a decision requires a full<br>
>> >>> Infinispan performance test rather than a microbenchmark. (which is<br>
>> >>> useful<br>
>> >>> too but more for the sake of optimising JBoss Logging, not to proof if<br>
>> >>> it's<br>
>> >>> OK to switch all of Infinispan 's internal conventions)<br>
>> >>><br>
>> >> Based on the testing both myself and Radim did WRT inlining, it<br>
>> >> doesn't make a huge difference. But I agree 100% that before removing<br>
>> >> the isTraceEnabled() caching we'd have to benchmark the whole of<br>
>> >> Infinispan, and not just JBoss Logging in isolation.<br>
>> >><br>
>> >> Cheers<br>
>> >> Dan<br>
>> >><br>
>> >>> On Mon, 3 Oct 2016, 13:45 Sebastian Laskawiec, <<a href="mailto:slaskawi@redhat.com">slaskawi@redhat.com</a>><br>
>> >>> wrote:<br>
>> >>>> Awesome Dan! May I ask for a Pull Request:<br>
>> >>>> <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>
>> >>>><br>
>> >>>><br>
>> >>>><br>
>> >>>> On Mon, Oct 3, 2016 at 2:40 PM, Dan Berindei <<a href="mailto:dan.berindei@gmail.com">dan.berindei@gmail.com</a>><br>
>> >>>> wrote:<br>
>> >>>>> 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<br>
>> >>>>> 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<br>
>> >>>>> 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>
>> >>>>> <<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<br>
>> >>>>>> result<br>
>> >>>>>> of `logger.isTraceEnabled()` evaluation is 3 times faster than<br>
>> >>>>>> other<br>
>> >>>>>> options.<br>
>> >>>>>><br>
>> >>>>>> If anyone is interested in printing out JIT stuff, I also ran it<br>
>> >>>>>> with<br>
>> >>>>>> "-XX:+PrintCompilation", "-XX:+PrintCompilation2" and<br>
>> >>>>>> "-XX:+PrintInlining"<br>
>> >>>>>> here [3].<br>
>> >>>>>><br>
>> >>>>>> I'm not a performance expert but it seems that JIT could not inline<br>
>> >>>>>> the<br>
>> >>>>>> "translate" method because of its size (see line 1861). However it<br>
>> >>>>>> tried<br>
>> >>>>>> several times with different optimizations (and some of them were<br>
>> >>>>>> thrown<br>
>> >>>>>> away - "made not entrant" messages [4]).<br>
>> >>>>>><br>
>> >>>>>> Let's wait for James' opinion on this, but I think we should<br>
>> >>>>>> address<br>
>> >>>>>> this<br>
>> >>>>>> issue on JBoss Logging/LogManager side (so I agree with David here)<br>
>> >>>>>> and<br>
>> >>>>>> make<br>
>> >>>>>> those parts inlinable (wow, does this word even exist? :D). Once<br>
>> >>>>>> this<br>
>> >>>>>> is<br>
>> >>>>>> done, we could experiment further in Infinispan codebase and see<br>
>> >>>>>> how<br>
>> >>>>>> this<br>
>> >>>>>> relates to some real world benchmarks...<br>
>> >>>>>><br>
>> >>>>>> Thanks<br>
>> >>>>>> Sebastian<br>
>> >>>>>><br>
>> >>>>>> [1]<br>
>> >>>>>> <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:<br>
>> >>>>>> <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]<br>
>> >>>>>> <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>
>> >>>>>><br>
>> >>>>>><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<br>
>> >>>>>> <<a href="mailto:slaskawi@redhat.com">slaskawi@redhat.com</a>><br>
>> >>>>>> wrote:<br>
>> >>>>>>> Hey!<br>
>> >>>>>>><br>
>> >>>>>>> Adding James to this thread.<br>
>> >>>>>>><br>
>> >>>>>>> @Dennis - I think Dan has a point here. The trick with checking a<br>
>> >>>>>>> field in<br>
>> >>>>>>> a class is 3 times faster. Most of the checks are done in core so<br>
>> >>>>>>> they<br>
>> >>>>>>> are<br>
>> >>>>>>> executed multiple times per operation. Changing all those places<br>
>> >>>>>>> is<br>
>> >>>>>>> probably<br>
>> >>>>>>> not an option.<br>
>> >>>>>>><br>
>> >>>>>>> @David - Let me run a test with JBoss Log Manager and get back to<br>
>> >>>>>>> you<br>
>> >>>>>>> with<br>
>> >>>>>>> some results. But if Dan is right, and the problem is with enum<br>
>> >>>>>>> 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<br>
>> >>>>>>> <<a href="mailto:dan.berindei@gmail.com">dan.berindei@gmail.com</a>><br>
>> >>>>>>> wrote:<br>
>> >>>>>>>> On Fri, Sep 30, 2016 at 10:15 PM, David M. Lloyd<br>
>> >>>>>>>> <<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<br>
>> >>>>>>>>> really a<br>
>> >>>>>>>>> problem in the logging backend. It *should* be faster inside of<br>
>> >>>>>>>>> WildFly, where JBoss LogManager is used, because that project<br>
>> >>>>>>>>> just<br>
>> >>>>>>>>> checks a single volatile field for the level check... and the<br>
>> >>>>>>>>> path<br>
>> >>>>>>>>> to<br>
>> >>>>>>>>> that code *should* be inline-friendly.<br>
>> >>>>>>>>><br>
>> >>>>>>>> Indeed, we started using this trick because of log4j 1.2, which<br>
>> >>>>>>>> needs<br>
>> >>>>>>>> to walk the logger hierarchy in order to check the level, and it<br>
>> >>>>>>>> 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<br>
>> >>>>>>>> with a<br>
>> >>>>>>>> Level.TRACE_VALUE int constant. If JDK9 fixes that, then it's<br>
>> >>>>>>>> going<br>
>> >>>>>>>> to<br>
>> >>>>>>>> be more or less equivalent to using a volatile "trace" field in<br>
>> >>>>>>>> each<br>
>> >>>>>>>> class, so it should be suitable even for local read operations<br>
>> >>>>>>>> that<br>
>> >>>>>>>> take < 200ns.<br>
>> >>>>>>>><br>
>> >>>>>>>> We'd probably still need to weed out some of the trace messages,<br>
>> >>>>>>>> as<br>
>> >>>>>>>> we<br>
>> >>>>>>>> probably have more than 10 of them during such a read operation.<br>
>> >>>>>>>> I<br>
>> >>>>>>>> confess that I added way too many trace logs myself, precisely<br>
>> >>>>>>>> because<br>
>> >>>>>>>> I knew we are using a static final field and the JIT compiler<br>
>> >>>>>>>> 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>
>> >>>>>> ______________________________<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>
>> >>>>> ______________________________<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>
>> >>>> ______________________________<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>
>> >>> ______________________________<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>
>> >> ______________________________<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>
>> ______________________________<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>
> ______________________________<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>
______________________________<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></div></div></blockquote></div><br></div>