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

David M. Lloyd david.lloyd at redhat.com
Fri Sep 30 15:15:45 EDT 2016


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

On 09/30/2016 11:16 AM, Dennis Reed wrote:
> As Wolf noted, caching the trace flag is bad when trying to debug issues.
>
> Don't do it!  It's not worth breaking the logging semantics for a
> nano-second level performance difference.  (if your trace is being
> called enough for that tiny impact to make any real difference, that
> trace logging is going to be WAY too verbose to be of any use anyways).
>
> If I see it done, I'm going to open a BZ.
>
> -Dennis
>
>
> On 09/30/2016 08:23 AM, Sanne Grinovero wrote:
>> this discussion appears on this mailing list approximately every 2 years :)
>>
>> On 30 September 2016 at 13:41, Dan Berindei <dan.berindei at gmail.com> 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 at redhat.com> 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 at redhat.com>
>>>> 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 at lists.jboss.org
>>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>>>
>>>>>
>>>>> --
>>>>> - DML
>>>>> _______________________________________________
>>>>> infinispan-dev mailing list
>>>>> infinispan-dev at lists.jboss.org
>>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>>
>>>>
>>>>
>>>> _______________________________________________
>>>> infinispan-dev mailing list
>>>> infinispan-dev at lists.jboss.org
>>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>>
>>> _______________________________________________
>>> infinispan-dev mailing list
>>> infinispan-dev at lists.jboss.org
>>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>> _______________________________________________
>> infinispan-dev mailing list
>> infinispan-dev at lists.jboss.org
>> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>>
>
> _______________________________________________
> infinispan-dev mailing list
> infinispan-dev at lists.jboss.org
> https://lists.jboss.org/mailman/listinfo/infinispan-dev
>

-- 
- DML


More information about the infinispan-dev mailing list