You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@geode.apache.org by Galen O'Sullivan <go...@apache.org> on 2018/09/07 17:50:39 UTC
[DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Hi all,
I've noticed a pattern in Geode where we wrap a log call in a check at the
same level, such as:
if (logger.isDebugEnabled()) {
logger.debug("cleaning up incompletely started
DistributionManager due to exception", r);
}
Is there any reason to do this? To my mind, it's an extra conditional that
should essentially be the first check inside `logger.debug(...)` anyways,
and it complicates the code and makes it less readable. I've even seen
places in the code which have `if (logger.isDebugEnabled())
logger.trace(...))` and such.
I would like to propose that unless there is a compelling reason to use
this pattern, we remove all extra checks entirely.
Galen
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Anthony Baker <ab...@pivotal.io>.
Check the recommended patterns for java8 [1], I think the lambda syntax makes the conditional less needed.
Anthony
[1] https://logging.apache.org/log4j/2.0/manual/api.html <https://logging.apache.org/log4j/2.0/manual/api.html>
> On Sep 7, 2018, at 11:38 AM, John Blum <jb...@pivotal.io> wrote:
>
> Grrr, meant...
>
> logger.debug("Logging in user {}", user);
>
>
>
> On Fri, Sep 7, 2018 at 11:37 AM, John Blum <jb...@pivotal.io> wrote:
>
>> Technically, I think that is SLF4J syntax (but maybe Log4J2 supports this
>> format now as well; anyway).
>>
>> Still, you should be careful with log statements like...
>>
>> logger.debug("Logging in user {}" + user);
>>
>> Assuming the User class itself and an "informative" and properly
>> constructed toString() method. So use it judiciously and wisely.
>>
>>
>> On Fri, Sep 7, 2018 at 11:18 AM, Dan Smith <ds...@pivotal.io> wrote:
>>
>>> I think this pattern is a holdover from using log4j 1. In that version,
>>> you
>>> added an if check to avoid unnecessary string concatenation if debug was
>>> enabled.
>>>
>>>
>>> 1. if (logger.isDebugEnabled()) {
>>> 2. logger.debug("Logging in user " + user.getName() + " with
>>> birthday " + user.getBirthdayCalendar());
>>> 3. }
>>>
>>>
>>> Log4j2 lets you pass a format string, so you can just do this:
>>>
>>> logger.debug("Logging in user {} with birthday {}", user.getName(),
>>> user.getBirthdayCalendar());
>>>
>>>
>>> These examples come from the log4j2 docs:
>>>
>>> https://logging.apache.org/log4j/2.0/manual/api.html
>>>
>>> -Dan
>>>
>>> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <go...@apache.org>
>>> wrote:
>>>
>>>> Hi all,
>>>>
>>>> I've noticed a pattern in Geode where we wrap a log call in a check at
>>> the
>>>> same level, such as:
>>>>
>>>> if (logger.isDebugEnabled()) {
>>>> logger.debug("cleaning up incompletely started
>>>> DistributionManager due to exception", r);
>>>> }
>>>>
>>>> Is there any reason to do this? To my mind, it's an extra conditional
>>> that
>>>> should essentially be the first check inside `logger.debug(...)`
>>> anyways,
>>>> and it complicates the code and makes it less readable. I've even seen
>>>> places in the code which have `if (logger.isDebugEnabled())
>>>> logger.trace(...))` and such.
>>>>
>>>> I would like to propose that unless there is a compelling reason to use
>>>> this pattern, we remove all extra checks entirely.
>>>>
>>>> Galen
>>>>
>>>
>>
>>
>>
>> --
>> -John
>> john.blum10101 (skype)
>>
>
>
>
> --
> -John
> john.blum10101 (skype)
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by John Blum <jb...@pivotal.io>.
Grrr, meant...
logger.debug("Logging in user {}", user);
On Fri, Sep 7, 2018 at 11:37 AM, John Blum <jb...@pivotal.io> wrote:
> Technically, I think that is SLF4J syntax (but maybe Log4J2 supports this
> format now as well; anyway).
>
> Still, you should be careful with log statements like...
>
> logger.debug("Logging in user {}" + user);
>
> Assuming the User class itself and an "informative" and properly
> constructed toString() method. So use it judiciously and wisely.
>
>
> On Fri, Sep 7, 2018 at 11:18 AM, Dan Smith <ds...@pivotal.io> wrote:
>
>> I think this pattern is a holdover from using log4j 1. In that version,
>> you
>> added an if check to avoid unnecessary string concatenation if debug was
>> enabled.
>>
>>
>> 1. if (logger.isDebugEnabled()) {
>> 2. logger.debug("Logging in user " + user.getName() + " with
>> birthday " + user.getBirthdayCalendar());
>> 3. }
>>
>>
>> Log4j2 lets you pass a format string, so you can just do this:
>>
>> logger.debug("Logging in user {} with birthday {}", user.getName(),
>> user.getBirthdayCalendar());
>>
>>
>> These examples come from the log4j2 docs:
>>
>> https://logging.apache.org/log4j/2.0/manual/api.html
>>
>> -Dan
>>
>> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <go...@apache.org>
>> wrote:
>>
>> > Hi all,
>> >
>> > I've noticed a pattern in Geode where we wrap a log call in a check at
>> the
>> > same level, such as:
>> >
>> > if (logger.isDebugEnabled()) {
>> > logger.debug("cleaning up incompletely started
>> > DistributionManager due to exception", r);
>> > }
>> >
>> > Is there any reason to do this? To my mind, it's an extra conditional
>> that
>> > should essentially be the first check inside `logger.debug(...)`
>> anyways,
>> > and it complicates the code and makes it less readable. I've even seen
>> > places in the code which have `if (logger.isDebugEnabled())
>> > logger.trace(...))` and such.
>> >
>> > I would like to propose that unless there is a compelling reason to use
>> > this pattern, we remove all extra checks entirely.
>> >
>> > Galen
>> >
>>
>
>
>
> --
> -John
> john.blum10101 (skype)
>
--
-John
john.blum10101 (skype)
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by John Blum <jb...@pivotal.io>.
Technically, I think that is SLF4J syntax (but maybe Log4J2 supports this
format now as well; anyway).
Still, you should be careful with log statements like...
logger.debug("Logging in user {}" + user);
Assuming the User class itself and an "informative" and properly
constructed toString() method. So use it judiciously and wisely.
On Fri, Sep 7, 2018 at 11:18 AM, Dan Smith <ds...@pivotal.io> wrote:
> I think this pattern is a holdover from using log4j 1. In that version, you
> added an if check to avoid unnecessary string concatenation if debug was
> enabled.
>
>
> 1. if (logger.isDebugEnabled()) {
> 2. logger.debug("Logging in user " + user.getName() + " with
> birthday " + user.getBirthdayCalendar());
> 3. }
>
>
> Log4j2 lets you pass a format string, so you can just do this:
>
> logger.debug("Logging in user {} with birthday {}", user.getName(),
> user.getBirthdayCalendar());
>
>
> These examples come from the log4j2 docs:
>
> https://logging.apache.org/log4j/2.0/manual/api.html
>
> -Dan
>
> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <go...@apache.org>
> wrote:
>
> > Hi all,
> >
> > I've noticed a pattern in Geode where we wrap a log call in a check at
> the
> > same level, such as:
> >
> > if (logger.isDebugEnabled()) {
> > logger.debug("cleaning up incompletely started
> > DistributionManager due to exception", r);
> > }
> >
> > Is there any reason to do this? To my mind, it's an extra conditional
> that
> > should essentially be the first check inside `logger.debug(...)` anyways,
> > and it complicates the code and makes it less readable. I've even seen
> > places in the code which have `if (logger.isDebugEnabled())
> > logger.trace(...))` and such.
> >
> > I would like to propose that unless there is a compelling reason to use
> > this pattern, we remove all extra checks entirely.
> >
> > Galen
> >
>
--
-John
john.blum10101 (skype)
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Kirk Lund <kl...@apache.org>.
Here is AsyncEventListenerDUnitTest that (latest versions of) IntelliJ and
Eclipse both complained exceeded the bytes limit for lambdas:
https://github.com/apache/geode/blob/6ef68c11fdd49e02ded0bfa2bfc072f96f7ab250/geode-core/src/distributedTest/java/org/apache/geode/internal/cache/wan/asyncqueue/AsyncEventListenerDUnitTest.java
I don't think it's a limit based on "count" but rather something to do with
byte size of the lambdas. This never failed to compile. And yes, I read up
on the same SO post when I discovered the problem in this file but that
explain it clearly to me within the context of AsyncEventListenerDUnitTest.
The JIRA ticket I filed was GEODE-5485 "AsyncEventListenerDUnitTest
$deserializeLambda$(SerializedLambda) is exceeding the 65535 bytes limit"
On Tue, Sep 11, 2018 at 9:26 AM, John Blum <jb...@pivotal.io> wrote:
> I think any arguments about what optimizations the (JIT enabled) compiler
> (HotSpot or otherwise) will perform at runtime is questionable at best.
> HotSpot can "inline" certain [frequent/hot] code paths both at
> compile/runtime thereby reducing the number of method invocations (which
> also depends on many factors, not the least of which is method size).
>
> Here is a good SO post on the subject of Lambdas...
>
> https://stackoverflow.com/questions/40860859/what-is-
> the-maximum-number-of-lambdas-used-in-one-java-class
>
> I find it somewhat surprising that Geode (in any part of its codebase) hit
> the limit on the number of Lambdas (methods). That suggests that class
> themselves need to be refactored and better organized by concern.
>
>
> On Tue, Sep 11, 2018 at 9:02 AM, Dale Emery <de...@pivotal.io> wrote:
>
> > If there’s enough duplication in the lambdas, or in the code around the
> > lambdas, extracting the duplication into methods would reduce the number
> of
> > lambdas.
> >
> > > On Sep 10, 2018, at 11:03 AM, Kirk Lund <kl...@apache.org> wrote:
> > >
> > > Alright I'm more up-to-date on this thread. Some things to consider:
> > >
> > > The lambdas look great, but we'd have to start splitting the Geode
> > clasess.
> > > They're so big right now, that if you change a bunch of log statements
> to
> > > use lambdas you'll hit the max number of lambdas on many of our
> classes.
> > We
> > > hit the lambda limit on a dunit test and it didn't really take that
> many
> > > lambdas to hit the limit (see
> > > https://issues.apache.org/jira/browse/GEODE-5485).
> > >
> > > We could change FastLogger to override every Logger method instead of
> > > isDebugEnabled and isTraceEnabled. Then we could remove every single
> > guard
> > > clause from the Geode log statements.
> > >
> > > If Log4J2 changed their implementation of debug and trace to be
> > comparable
> > > with hitting a volatile for disabled statements then we could delete
> > > FastLogger and every log statement guard clause.
> > >
> > > On Mon, Sep 10, 2018 at 10:12 AM, Kirk Lund <kl...@apache.org> wrote:
> > >
> > >> The reason we use these guards is that the Log4j2 implementation is
> more
> > >> expensive than hitting a volatile. Please don't change anything unless
> > you
> > >> start writing lots of JMH benchmarks! The existing code went through
> > lots
> > >> of iterations of perf testing that isn't part of Geode.
> > >>
> > >> Every Log4j2 Logger used by Geode classes are wrapped inside a
> > FastLogger
> > >> which uses a single volatile for those "isDebugEnabled" checks. If you
> > >> remove this, you will find that the performance of Geode will thank
> > even at
> > >> higher log levels such as INFO. Geode is currently optimized for INFO
> > level
> > >> logging. Without FastLogger, every log statement code path goes down
> > into a
> > >> hot mess of checking filters and performing file checking against
> > >> log4j2.xml (based on a mod so that it only occurs every several log
> > >> statements) to see if it has changed.
> > >>
> > >> Despite this, Log4J2 Core still out performs Logback for "disabled log
> > >> statements" and by this I mean the huge # of debug/trace level
> > statements
> > >> in Geode when running at INFO level.
> > >>
> > >> Unwrapping those "isDebugEnabled" checks will eliminate the
> optimization
> > >> provided by FastLogger. Without the guard clauses, FastLogger doesn't
> > >> improve anything because the Log4j2 code skips the "isDebugEnabled"
> > checks
> > >> and goes into filter checking which also checks the log level but
> after
> > >> much more work. My recommendation is to work with Log4j2 project to
> fix
> > >> this performance problem when using log statements without the
> > FastLogger
> > >> optimizations. For example, Log4j1 used a dedicated async thread for
> the
> > >> checking of the config file but for some reason they didn't go this
> > route
> > >> in Log4J2.
> > >>
> > >> PS: My Log4J2 code knowledge is a couple of years old so please feel
> > free
> > >> to dig into their code to see if the above issues were fixed.
> > >>
> > >> On Mon, Sep 10, 2018 at 9:35 AM, Galen O'Sullivan <
> > gosullivan@pivotal.io>
> > >> wrote:
> > >>
> > >>> I think that logging in hot paths/loops is probably something that
> > should
> > >>> be avoided. And if it is necessary, I suspect that the JIT will
> > >>> short-circuit that call since debug levels don't generally change.
> > >>>
> > >>> There probably are a few hot paths that need to optimize logging, but
> > >>> that's not the majority.
> > >>>
> > >>> Can we agree to avoid this pattern in new code, since it adversely
> > affects
> > >>> readability?
> > >>>
> > >>> Galen
> > >>>
> > >>>
> > >>> On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <
> nvallely@pivotal.io>
> > >>> wrote:
> > >>>
> > >>>> I was just randomly looking into this a couple of days ago as a
> > tangent
> > >>> to
> > >>>> 'observability' and came across this Stack Overflow:
> > >>>> https://stackoverflow.com/questions/6504407/is-there-a-need-
> > >>> to-do-a-iflog-
> > >>>> isdebugenabled-check
> > >>>> where the first answer is the most succinct in my opinion.
> > >>>>
> > >>>> In the geode code that I searched, we are not consistent with our
> use
> > of
> > >>>> the if(statement) wrapper for debug, though most do have the
> wrapper.
> > >>>>
> > >>>> Nick
> > >>>>
> > >>>> On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io>
> > >>> wrote:
> > >>>>
> > >>>>> Checking with logger.isDebugEnabled() it still a good practice for
> > hot
> > >>>>> paths to avoid the construction of intermediate object arrays to
> hold
> > >>> the
> > >>>>> var-args. Some logging libraries have fixed argument optimizations
> > for
> > >>>>> var-args up to a specific limit. In very hot paths it is nice to
> > >>>>> check logger.isDebugEnabled() once into a temp boolean value and
> then
> > >>>> check
> > >>>>> that in all the subsequent debug logging statements in the hot
> path.
> > >>>>>
> > >>>>> -Jake
> > >>>>>
> > >>>>>
> > >>>>> On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io>
> wrote:
> > >>>>>
> > >>>>>> I think this pattern is a holdover from using log4j 1. In that
> > >>> version,
> > >>>>> you
> > >>>>>> added an if check to avoid unnecessary string concatenation if
> debug
> > >>>> was
> > >>>>>> enabled.
> > >>>>>>
> > >>>>>>
> > >>>>>> 1. if (logger.isDebugEnabled()) {
> > >>>>>> 2. logger.debug("Logging in user " + user.getName() + " with
> > >>>>>> birthday " + user.getBirthdayCalendar());
> > >>>>>> 3. }
> > >>>>>>
> > >>>>>>
> > >>>>>> Log4j2 lets you pass a format string, so you can just do this:
> > >>>>>>
> > >>>>>> logger.debug("Logging in user {} with birthday {}",
> user.getName(),
> > >>>>>> user.getBirthdayCalendar());
> > >>>>>>
> > >>>>>>
> > >>>>>> These examples come from the log4j2 docs:
> > >>>>>>
> > >>>>>> https://logging.apache.org/log4j/2.0/manual/api.html
> > >>>>>>
> > >>>>>> -Dan
> > >>>>>>
> > >>>>>> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
> > >>>> gosullivan@apache.org
> > >>>>>>
> > >>>>>> wrote:
> > >>>>>>
> > >>>>>>> Hi all,
> > >>>>>>>
> > >>>>>>> I've noticed a pattern in Geode where we wrap a log call in a
> > >>> check
> > >>>> at
> > >>>>>> the
> > >>>>>>> same level, such as:
> > >>>>>>>
> > >>>>>>> if (logger.isDebugEnabled()) {
> > >>>>>>> logger.debug("cleaning up incompletely started
> > >>>>>>> DistributionManager due to exception", r);
> > >>>>>>> }
> > >>>>>>>
> > >>>>>>> Is there any reason to do this? To my mind, it's an extra
> > >>> conditional
> > >>>>>> that
> > >>>>>>> should essentially be the first check inside `logger.debug(...)`
> > >>>>> anyways,
> > >>>>>>> and it complicates the code and makes it less readable. I've even
> > >>>> seen
> > >>>>>>> places in the code which have `if (logger.isDebugEnabled())
> > >>>>>>> logger.trace(...))` and such.
> > >>>>>>>
> > >>>>>>> I would like to propose that unless there is a compelling reason
> > >>> to
> > >>>> use
> > >>>>>>> this pattern, we remove all extra checks entirely.
> > >>>>>>>
> > >>>>>>> Galen
> > >>>>>>>
> > >>>>>>
> > >>>>>
> > >>>>
> > >>>
> > >>
> > >>
> >
> >
>
>
> --
> -John
> john.blum10101 (skype)
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by John Blum <jb...@pivotal.io>.
I think any arguments about what optimizations the (JIT enabled) compiler
(HotSpot or otherwise) will perform at runtime is questionable at best.
HotSpot can "inline" certain [frequent/hot] code paths both at
compile/runtime thereby reducing the number of method invocations (which
also depends on many factors, not the least of which is method size).
Here is a good SO post on the subject of Lambdas...
https://stackoverflow.com/questions/40860859/what-is-the-maximum-number-of-lambdas-used-in-one-java-class
I find it somewhat surprising that Geode (in any part of its codebase) hit
the limit on the number of Lambdas (methods). That suggests that class
themselves need to be refactored and better organized by concern.
On Tue, Sep 11, 2018 at 9:02 AM, Dale Emery <de...@pivotal.io> wrote:
> If there’s enough duplication in the lambdas, or in the code around the
> lambdas, extracting the duplication into methods would reduce the number of
> lambdas.
>
> > On Sep 10, 2018, at 11:03 AM, Kirk Lund <kl...@apache.org> wrote:
> >
> > Alright I'm more up-to-date on this thread. Some things to consider:
> >
> > The lambdas look great, but we'd have to start splitting the Geode
> clasess.
> > They're so big right now, that if you change a bunch of log statements to
> > use lambdas you'll hit the max number of lambdas on many of our classes.
> We
> > hit the lambda limit on a dunit test and it didn't really take that many
> > lambdas to hit the limit (see
> > https://issues.apache.org/jira/browse/GEODE-5485).
> >
> > We could change FastLogger to override every Logger method instead of
> > isDebugEnabled and isTraceEnabled. Then we could remove every single
> guard
> > clause from the Geode log statements.
> >
> > If Log4J2 changed their implementation of debug and trace to be
> comparable
> > with hitting a volatile for disabled statements then we could delete
> > FastLogger and every log statement guard clause.
> >
> > On Mon, Sep 10, 2018 at 10:12 AM, Kirk Lund <kl...@apache.org> wrote:
> >
> >> The reason we use these guards is that the Log4j2 implementation is more
> >> expensive than hitting a volatile. Please don't change anything unless
> you
> >> start writing lots of JMH benchmarks! The existing code went through
> lots
> >> of iterations of perf testing that isn't part of Geode.
> >>
> >> Every Log4j2 Logger used by Geode classes are wrapped inside a
> FastLogger
> >> which uses a single volatile for those "isDebugEnabled" checks. If you
> >> remove this, you will find that the performance of Geode will thank
> even at
> >> higher log levels such as INFO. Geode is currently optimized for INFO
> level
> >> logging. Without FastLogger, every log statement code path goes down
> into a
> >> hot mess of checking filters and performing file checking against
> >> log4j2.xml (based on a mod so that it only occurs every several log
> >> statements) to see if it has changed.
> >>
> >> Despite this, Log4J2 Core still out performs Logback for "disabled log
> >> statements" and by this I mean the huge # of debug/trace level
> statements
> >> in Geode when running at INFO level.
> >>
> >> Unwrapping those "isDebugEnabled" checks will eliminate the optimization
> >> provided by FastLogger. Without the guard clauses, FastLogger doesn't
> >> improve anything because the Log4j2 code skips the "isDebugEnabled"
> checks
> >> and goes into filter checking which also checks the log level but after
> >> much more work. My recommendation is to work with Log4j2 project to fix
> >> this performance problem when using log statements without the
> FastLogger
> >> optimizations. For example, Log4j1 used a dedicated async thread for the
> >> checking of the config file but for some reason they didn't go this
> route
> >> in Log4J2.
> >>
> >> PS: My Log4J2 code knowledge is a couple of years old so please feel
> free
> >> to dig into their code to see if the above issues were fixed.
> >>
> >> On Mon, Sep 10, 2018 at 9:35 AM, Galen O'Sullivan <
> gosullivan@pivotal.io>
> >> wrote:
> >>
> >>> I think that logging in hot paths/loops is probably something that
> should
> >>> be avoided. And if it is necessary, I suspect that the JIT will
> >>> short-circuit that call since debug levels don't generally change.
> >>>
> >>> There probably are a few hot paths that need to optimize logging, but
> >>> that's not the majority.
> >>>
> >>> Can we agree to avoid this pattern in new code, since it adversely
> affects
> >>> readability?
> >>>
> >>> Galen
> >>>
> >>>
> >>> On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <nv...@pivotal.io>
> >>> wrote:
> >>>
> >>>> I was just randomly looking into this a couple of days ago as a
> tangent
> >>> to
> >>>> 'observability' and came across this Stack Overflow:
> >>>> https://stackoverflow.com/questions/6504407/is-there-a-need-
> >>> to-do-a-iflog-
> >>>> isdebugenabled-check
> >>>> where the first answer is the most succinct in my opinion.
> >>>>
> >>>> In the geode code that I searched, we are not consistent with our use
> of
> >>>> the if(statement) wrapper for debug, though most do have the wrapper.
> >>>>
> >>>> Nick
> >>>>
> >>>> On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io>
> >>> wrote:
> >>>>
> >>>>> Checking with logger.isDebugEnabled() it still a good practice for
> hot
> >>>>> paths to avoid the construction of intermediate object arrays to hold
> >>> the
> >>>>> var-args. Some logging libraries have fixed argument optimizations
> for
> >>>>> var-args up to a specific limit. In very hot paths it is nice to
> >>>>> check logger.isDebugEnabled() once into a temp boolean value and then
> >>>> check
> >>>>> that in all the subsequent debug logging statements in the hot path.
> >>>>>
> >>>>> -Jake
> >>>>>
> >>>>>
> >>>>> On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
> >>>>>
> >>>>>> I think this pattern is a holdover from using log4j 1. In that
> >>> version,
> >>>>> you
> >>>>>> added an if check to avoid unnecessary string concatenation if debug
> >>>> was
> >>>>>> enabled.
> >>>>>>
> >>>>>>
> >>>>>> 1. if (logger.isDebugEnabled()) {
> >>>>>> 2. logger.debug("Logging in user " + user.getName() + " with
> >>>>>> birthday " + user.getBirthdayCalendar());
> >>>>>> 3. }
> >>>>>>
> >>>>>>
> >>>>>> Log4j2 lets you pass a format string, so you can just do this:
> >>>>>>
> >>>>>> logger.debug("Logging in user {} with birthday {}", user.getName(),
> >>>>>> user.getBirthdayCalendar());
> >>>>>>
> >>>>>>
> >>>>>> These examples come from the log4j2 docs:
> >>>>>>
> >>>>>> https://logging.apache.org/log4j/2.0/manual/api.html
> >>>>>>
> >>>>>> -Dan
> >>>>>>
> >>>>>> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
> >>>> gosullivan@apache.org
> >>>>>>
> >>>>>> wrote:
> >>>>>>
> >>>>>>> Hi all,
> >>>>>>>
> >>>>>>> I've noticed a pattern in Geode where we wrap a log call in a
> >>> check
> >>>> at
> >>>>>> the
> >>>>>>> same level, such as:
> >>>>>>>
> >>>>>>> if (logger.isDebugEnabled()) {
> >>>>>>> logger.debug("cleaning up incompletely started
> >>>>>>> DistributionManager due to exception", r);
> >>>>>>> }
> >>>>>>>
> >>>>>>> Is there any reason to do this? To my mind, it's an extra
> >>> conditional
> >>>>>> that
> >>>>>>> should essentially be the first check inside `logger.debug(...)`
> >>>>> anyways,
> >>>>>>> and it complicates the code and makes it less readable. I've even
> >>>> seen
> >>>>>>> places in the code which have `if (logger.isDebugEnabled())
> >>>>>>> logger.trace(...))` and such.
> >>>>>>>
> >>>>>>> I would like to propose that unless there is a compelling reason
> >>> to
> >>>> use
> >>>>>>> this pattern, we remove all extra checks entirely.
> >>>>>>>
> >>>>>>> Galen
> >>>>>>>
> >>>>>>
> >>>>>
> >>>>
> >>>
> >>
> >>
>
>
--
-John
john.blum10101 (skype)
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Dale Emery <de...@pivotal.io>.
If there’s enough duplication in the lambdas, or in the code around the lambdas, extracting the duplication into methods would reduce the number of lambdas.
> On Sep 10, 2018, at 11:03 AM, Kirk Lund <kl...@apache.org> wrote:
>
> Alright I'm more up-to-date on this thread. Some things to consider:
>
> The lambdas look great, but we'd have to start splitting the Geode clasess.
> They're so big right now, that if you change a bunch of log statements to
> use lambdas you'll hit the max number of lambdas on many of our classes. We
> hit the lambda limit on a dunit test and it didn't really take that many
> lambdas to hit the limit (see
> https://issues.apache.org/jira/browse/GEODE-5485).
>
> We could change FastLogger to override every Logger method instead of
> isDebugEnabled and isTraceEnabled. Then we could remove every single guard
> clause from the Geode log statements.
>
> If Log4J2 changed their implementation of debug and trace to be comparable
> with hitting a volatile for disabled statements then we could delete
> FastLogger and every log statement guard clause.
>
> On Mon, Sep 10, 2018 at 10:12 AM, Kirk Lund <kl...@apache.org> wrote:
>
>> The reason we use these guards is that the Log4j2 implementation is more
>> expensive than hitting a volatile. Please don't change anything unless you
>> start writing lots of JMH benchmarks! The existing code went through lots
>> of iterations of perf testing that isn't part of Geode.
>>
>> Every Log4j2 Logger used by Geode classes are wrapped inside a FastLogger
>> which uses a single volatile for those "isDebugEnabled" checks. If you
>> remove this, you will find that the performance of Geode will thank even at
>> higher log levels such as INFO. Geode is currently optimized for INFO level
>> logging. Without FastLogger, every log statement code path goes down into a
>> hot mess of checking filters and performing file checking against
>> log4j2.xml (based on a mod so that it only occurs every several log
>> statements) to see if it has changed.
>>
>> Despite this, Log4J2 Core still out performs Logback for "disabled log
>> statements" and by this I mean the huge # of debug/trace level statements
>> in Geode when running at INFO level.
>>
>> Unwrapping those "isDebugEnabled" checks will eliminate the optimization
>> provided by FastLogger. Without the guard clauses, FastLogger doesn't
>> improve anything because the Log4j2 code skips the "isDebugEnabled" checks
>> and goes into filter checking which also checks the log level but after
>> much more work. My recommendation is to work with Log4j2 project to fix
>> this performance problem when using log statements without the FastLogger
>> optimizations. For example, Log4j1 used a dedicated async thread for the
>> checking of the config file but for some reason they didn't go this route
>> in Log4J2.
>>
>> PS: My Log4J2 code knowledge is a couple of years old so please feel free
>> to dig into their code to see if the above issues were fixed.
>>
>> On Mon, Sep 10, 2018 at 9:35 AM, Galen O'Sullivan <go...@pivotal.io>
>> wrote:
>>
>>> I think that logging in hot paths/loops is probably something that should
>>> be avoided. And if it is necessary, I suspect that the JIT will
>>> short-circuit that call since debug levels don't generally change.
>>>
>>> There probably are a few hot paths that need to optimize logging, but
>>> that's not the majority.
>>>
>>> Can we agree to avoid this pattern in new code, since it adversely affects
>>> readability?
>>>
>>> Galen
>>>
>>>
>>> On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <nv...@pivotal.io>
>>> wrote:
>>>
>>>> I was just randomly looking into this a couple of days ago as a tangent
>>> to
>>>> 'observability' and came across this Stack Overflow:
>>>> https://stackoverflow.com/questions/6504407/is-there-a-need-
>>> to-do-a-iflog-
>>>> isdebugenabled-check
>>>> where the first answer is the most succinct in my opinion.
>>>>
>>>> In the geode code that I searched, we are not consistent with our use of
>>>> the if(statement) wrapper for debug, though most do have the wrapper.
>>>>
>>>> Nick
>>>>
>>>> On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io>
>>> wrote:
>>>>
>>>>> Checking with logger.isDebugEnabled() it still a good practice for hot
>>>>> paths to avoid the construction of intermediate object arrays to hold
>>> the
>>>>> var-args. Some logging libraries have fixed argument optimizations for
>>>>> var-args up to a specific limit. In very hot paths it is nice to
>>>>> check logger.isDebugEnabled() once into a temp boolean value and then
>>>> check
>>>>> that in all the subsequent debug logging statements in the hot path.
>>>>>
>>>>> -Jake
>>>>>
>>>>>
>>>>> On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
>>>>>
>>>>>> I think this pattern is a holdover from using log4j 1. In that
>>> version,
>>>>> you
>>>>>> added an if check to avoid unnecessary string concatenation if debug
>>>> was
>>>>>> enabled.
>>>>>>
>>>>>>
>>>>>> 1. if (logger.isDebugEnabled()) {
>>>>>> 2. logger.debug("Logging in user " + user.getName() + " with
>>>>>> birthday " + user.getBirthdayCalendar());
>>>>>> 3. }
>>>>>>
>>>>>>
>>>>>> Log4j2 lets you pass a format string, so you can just do this:
>>>>>>
>>>>>> logger.debug("Logging in user {} with birthday {}", user.getName(),
>>>>>> user.getBirthdayCalendar());
>>>>>>
>>>>>>
>>>>>> These examples come from the log4j2 docs:
>>>>>>
>>>>>> https://logging.apache.org/log4j/2.0/manual/api.html
>>>>>>
>>>>>> -Dan
>>>>>>
>>>>>> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
>>>> gosullivan@apache.org
>>>>>>
>>>>>> wrote:
>>>>>>
>>>>>>> Hi all,
>>>>>>>
>>>>>>> I've noticed a pattern in Geode where we wrap a log call in a
>>> check
>>>> at
>>>>>> the
>>>>>>> same level, such as:
>>>>>>>
>>>>>>> if (logger.isDebugEnabled()) {
>>>>>>> logger.debug("cleaning up incompletely started
>>>>>>> DistributionManager due to exception", r);
>>>>>>> }
>>>>>>>
>>>>>>> Is there any reason to do this? To my mind, it's an extra
>>> conditional
>>>>>> that
>>>>>>> should essentially be the first check inside `logger.debug(...)`
>>>>> anyways,
>>>>>>> and it complicates the code and makes it less readable. I've even
>>>> seen
>>>>>>> places in the code which have `if (logger.isDebugEnabled())
>>>>>>> logger.trace(...))` and such.
>>>>>>>
>>>>>>> I would like to propose that unless there is a compelling reason
>>> to
>>>> use
>>>>>>> this pattern, we remove all extra checks entirely.
>>>>>>>
>>>>>>> Galen
>>>>>>>
>>>>>>
>>>>>
>>>>
>>>
>>
>>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Kirk Lund <kl...@apache.org>.
Alright I'm more up-to-date on this thread. Some things to consider:
The lambdas look great, but we'd have to start splitting the Geode clasess.
They're so big right now, that if you change a bunch of log statements to
use lambdas you'll hit the max number of lambdas on many of our classes. We
hit the lambda limit on a dunit test and it didn't really take that many
lambdas to hit the limit (see
https://issues.apache.org/jira/browse/GEODE-5485).
We could change FastLogger to override every Logger method instead of
isDebugEnabled and isTraceEnabled. Then we could remove every single guard
clause from the Geode log statements.
If Log4J2 changed their implementation of debug and trace to be comparable
with hitting a volatile for disabled statements then we could delete
FastLogger and every log statement guard clause.
On Mon, Sep 10, 2018 at 10:12 AM, Kirk Lund <kl...@apache.org> wrote:
> The reason we use these guards is that the Log4j2 implementation is more
> expensive than hitting a volatile. Please don't change anything unless you
> start writing lots of JMH benchmarks! The existing code went through lots
> of iterations of perf testing that isn't part of Geode.
>
> Every Log4j2 Logger used by Geode classes are wrapped inside a FastLogger
> which uses a single volatile for those "isDebugEnabled" checks. If you
> remove this, you will find that the performance of Geode will thank even at
> higher log levels such as INFO. Geode is currently optimized for INFO level
> logging. Without FastLogger, every log statement code path goes down into a
> hot mess of checking filters and performing file checking against
> log4j2.xml (based on a mod so that it only occurs every several log
> statements) to see if it has changed.
>
> Despite this, Log4J2 Core still out performs Logback for "disabled log
> statements" and by this I mean the huge # of debug/trace level statements
> in Geode when running at INFO level.
>
> Unwrapping those "isDebugEnabled" checks will eliminate the optimization
> provided by FastLogger. Without the guard clauses, FastLogger doesn't
> improve anything because the Log4j2 code skips the "isDebugEnabled" checks
> and goes into filter checking which also checks the log level but after
> much more work. My recommendation is to work with Log4j2 project to fix
> this performance problem when using log statements without the FastLogger
> optimizations. For example, Log4j1 used a dedicated async thread for the
> checking of the config file but for some reason they didn't go this route
> in Log4J2.
>
> PS: My Log4J2 code knowledge is a couple of years old so please feel free
> to dig into their code to see if the above issues were fixed.
>
> On Mon, Sep 10, 2018 at 9:35 AM, Galen O'Sullivan <go...@pivotal.io>
> wrote:
>
>> I think that logging in hot paths/loops is probably something that should
>> be avoided. And if it is necessary, I suspect that the JIT will
>> short-circuit that call since debug levels don't generally change.
>>
>> There probably are a few hot paths that need to optimize logging, but
>> that's not the majority.
>>
>> Can we agree to avoid this pattern in new code, since it adversely affects
>> readability?
>>
>> Galen
>>
>>
>> On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <nv...@pivotal.io>
>> wrote:
>>
>> > I was just randomly looking into this a couple of days ago as a tangent
>> to
>> > 'observability' and came across this Stack Overflow:
>> > https://stackoverflow.com/questions/6504407/is-there-a-need-
>> to-do-a-iflog-
>> > isdebugenabled-check
>> > where the first answer is the most succinct in my opinion.
>> >
>> > In the geode code that I searched, we are not consistent with our use of
>> > the if(statement) wrapper for debug, though most do have the wrapper.
>> >
>> > Nick
>> >
>> > On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io>
>> wrote:
>> >
>> > > Checking with logger.isDebugEnabled() it still a good practice for hot
>> > > paths to avoid the construction of intermediate object arrays to hold
>> the
>> > > var-args. Some logging libraries have fixed argument optimizations for
>> > > var-args up to a specific limit. In very hot paths it is nice to
>> > > check logger.isDebugEnabled() once into a temp boolean value and then
>> > check
>> > > that in all the subsequent debug logging statements in the hot path.
>> > >
>> > > -Jake
>> > >
>> > >
>> > > On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
>> > >
>> > > > I think this pattern is a holdover from using log4j 1. In that
>> version,
>> > > you
>> > > > added an if check to avoid unnecessary string concatenation if debug
>> > was
>> > > > enabled.
>> > > >
>> > > >
>> > > > 1. if (logger.isDebugEnabled()) {
>> > > > 2. logger.debug("Logging in user " + user.getName() + " with
>> > > > birthday " + user.getBirthdayCalendar());
>> > > > 3. }
>> > > >
>> > > >
>> > > > Log4j2 lets you pass a format string, so you can just do this:
>> > > >
>> > > > logger.debug("Logging in user {} with birthday {}", user.getName(),
>> > > > user.getBirthdayCalendar());
>> > > >
>> > > >
>> > > > These examples come from the log4j2 docs:
>> > > >
>> > > > https://logging.apache.org/log4j/2.0/manual/api.html
>> > > >
>> > > > -Dan
>> > > >
>> > > > On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
>> > gosullivan@apache.org
>> > > >
>> > > > wrote:
>> > > >
>> > > > > Hi all,
>> > > > >
>> > > > > I've noticed a pattern in Geode where we wrap a log call in a
>> check
>> > at
>> > > > the
>> > > > > same level, such as:
>> > > > >
>> > > > > if (logger.isDebugEnabled()) {
>> > > > > logger.debug("cleaning up incompletely started
>> > > > > DistributionManager due to exception", r);
>> > > > > }
>> > > > >
>> > > > > Is there any reason to do this? To my mind, it's an extra
>> conditional
>> > > > that
>> > > > > should essentially be the first check inside `logger.debug(...)`
>> > > anyways,
>> > > > > and it complicates the code and makes it less readable. I've even
>> > seen
>> > > > > places in the code which have `if (logger.isDebugEnabled())
>> > > > > logger.trace(...))` and such.
>> > > > >
>> > > > > I would like to propose that unless there is a compelling reason
>> to
>> > use
>> > > > > this pattern, we remove all extra checks entirely.
>> > > > >
>> > > > > Galen
>> > > > >
>> > > >
>> > >
>> >
>>
>
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Kirk Lund <kl...@apache.org>.
The reason we use these guards is that the Log4j2 implementation is more
expensive than hitting a volatile. Please don't change anything unless you
start writing lots of JMH benchmarks! The existing code went through lots
of iterations of perf testing that isn't part of Geode.
Every Log4j2 Logger used by Geode classes are wrapped inside a FastLogger
which uses a single volatile for those "isDebugEnabled" checks. If you
remove this, you will find that the performance of Geode will thank even at
higher log levels such as INFO. Geode is currently optimized for INFO level
logging. Without FastLogger, every log statement code path goes down into a
hot mess of checking filters and performing file checking against
log4j2.xml (based on a mod so that it only occurs every several log
statements) to see if it has changed.
Despite this, Log4J2 Core still out performs Logback for "disabled log
statements" and by this I mean the huge # of debug/trace level statements
in Geode when running at INFO level.
Unwrapping those "isDebugEnabled" checks will eliminate the optimization
provided by FastLogger. Without the guard clauses, FastLogger doesn't
improve anything because the Log4j2 code skips the "isDebugEnabled" checks
and goes into filter checking which also checks the log level but after
much more work. My recommendation is to work with Log4j2 project to fix
this performance problem when using log statements without the FastLogger
optimizations. For example, Log4j1 used a dedicated async thread for the
checking of the config file but for some reason they didn't go this route
in Log4J2.
PS: My Log4J2 code knowledge is a couple of years old so please feel free
to dig into their code to see if the above issues were fixed.
On Mon, Sep 10, 2018 at 9:35 AM, Galen O'Sullivan <go...@pivotal.io>
wrote:
> I think that logging in hot paths/loops is probably something that should
> be avoided. And if it is necessary, I suspect that the JIT will
> short-circuit that call since debug levels don't generally change.
>
> There probably are a few hot paths that need to optimize logging, but
> that's not the majority.
>
> Can we agree to avoid this pattern in new code, since it adversely affects
> readability?
>
> Galen
>
>
> On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <nv...@pivotal.io>
> wrote:
>
> > I was just randomly looking into this a couple of days ago as a tangent
> to
> > 'observability' and came across this Stack Overflow:
> > https://stackoverflow.com/questions/6504407/is-there-a-
> need-to-do-a-iflog-
> > isdebugenabled-check
> > where the first answer is the most succinct in my opinion.
> >
> > In the geode code that I searched, we are not consistent with our use of
> > the if(statement) wrapper for debug, though most do have the wrapper.
> >
> > Nick
> >
> > On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io>
> wrote:
> >
> > > Checking with logger.isDebugEnabled() it still a good practice for hot
> > > paths to avoid the construction of intermediate object arrays to hold
> the
> > > var-args. Some logging libraries have fixed argument optimizations for
> > > var-args up to a specific limit. In very hot paths it is nice to
> > > check logger.isDebugEnabled() once into a temp boolean value and then
> > check
> > > that in all the subsequent debug logging statements in the hot path.
> > >
> > > -Jake
> > >
> > >
> > > On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
> > >
> > > > I think this pattern is a holdover from using log4j 1. In that
> version,
> > > you
> > > > added an if check to avoid unnecessary string concatenation if debug
> > was
> > > > enabled.
> > > >
> > > >
> > > > 1. if (logger.isDebugEnabled()) {
> > > > 2. logger.debug("Logging in user " + user.getName() + " with
> > > > birthday " + user.getBirthdayCalendar());
> > > > 3. }
> > > >
> > > >
> > > > Log4j2 lets you pass a format string, so you can just do this:
> > > >
> > > > logger.debug("Logging in user {} with birthday {}", user.getName(),
> > > > user.getBirthdayCalendar());
> > > >
> > > >
> > > > These examples come from the log4j2 docs:
> > > >
> > > > https://logging.apache.org/log4j/2.0/manual/api.html
> > > >
> > > > -Dan
> > > >
> > > > On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
> > gosullivan@apache.org
> > > >
> > > > wrote:
> > > >
> > > > > Hi all,
> > > > >
> > > > > I've noticed a pattern in Geode where we wrap a log call in a check
> > at
> > > > the
> > > > > same level, such as:
> > > > >
> > > > > if (logger.isDebugEnabled()) {
> > > > > logger.debug("cleaning up incompletely started
> > > > > DistributionManager due to exception", r);
> > > > > }
> > > > >
> > > > > Is there any reason to do this? To my mind, it's an extra
> conditional
> > > > that
> > > > > should essentially be the first check inside `logger.debug(...)`
> > > anyways,
> > > > > and it complicates the code and makes it less readable. I've even
> > seen
> > > > > places in the code which have `if (logger.isDebugEnabled())
> > > > > logger.trace(...))` and such.
> > > > >
> > > > > I would like to propose that unless there is a compelling reason to
> > use
> > > > > this pattern, we remove all extra checks entirely.
> > > > >
> > > > > Galen
> > > > >
> > > >
> > >
> >
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Michael Stolz <ms...@pivotal.io>.
I doubt that the JIT can optimize the call out. That's what you're asking
it to do is optimize a method call away.
--
Mike Stolz
Principal Engineer, GemFire Product Lead
Mobile: +1-631-835-4771
Download the GemFire book here.
<https://content.pivotal.io/ebooks/scaling-data-services-with-pivotal-gemfire>
On Mon, Sep 10, 2018 at 9:35 AM, Galen O'Sullivan <go...@pivotal.io>
wrote:
> I think that logging in hot paths/loops is probably something that should
> be avoided. And if it is necessary, I suspect that the JIT will
> short-circuit that call since debug levels don't generally change.
>
> There probably are a few hot paths that need to optimize logging, but
> that's not the majority.
>
> Can we agree to avoid this pattern in new code, since it adversely affects
> readability?
>
> Galen
>
>
> On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <nv...@pivotal.io>
> wrote:
>
> > I was just randomly looking into this a couple of days ago as a tangent
> to
> > 'observability' and came across this Stack Overflow:
> > https://stackoverflow.com/questions/6504407/is-there-a-
> need-to-do-a-iflog-
> > isdebugenabled-check
> > where the first answer is the most succinct in my opinion.
> >
> > In the geode code that I searched, we are not consistent with our use of
> > the if(statement) wrapper for debug, though most do have the wrapper.
> >
> > Nick
> >
> > On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io>
> wrote:
> >
> > > Checking with logger.isDebugEnabled() it still a good practice for hot
> > > paths to avoid the construction of intermediate object arrays to hold
> the
> > > var-args. Some logging libraries have fixed argument optimizations for
> > > var-args up to a specific limit. In very hot paths it is nice to
> > > check logger.isDebugEnabled() once into a temp boolean value and then
> > check
> > > that in all the subsequent debug logging statements in the hot path.
> > >
> > > -Jake
> > >
> > >
> > > On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
> > >
> > > > I think this pattern is a holdover from using log4j 1. In that
> version,
> > > you
> > > > added an if check to avoid unnecessary string concatenation if debug
> > was
> > > > enabled.
> > > >
> > > >
> > > > 1. if (logger.isDebugEnabled()) {
> > > > 2. logger.debug("Logging in user " + user.getName() + " with
> > > > birthday " + user.getBirthdayCalendar());
> > > > 3. }
> > > >
> > > >
> > > > Log4j2 lets you pass a format string, so you can just do this:
> > > >
> > > > logger.debug("Logging in user {} with birthday {}", user.getName(),
> > > > user.getBirthdayCalendar());
> > > >
> > > >
> > > > These examples come from the log4j2 docs:
> > > >
> > > > https://logging.apache.org/log4j/2.0/manual/api.html
> > > >
> > > > -Dan
> > > >
> > > > On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
> > gosullivan@apache.org
> > > >
> > > > wrote:
> > > >
> > > > > Hi all,
> > > > >
> > > > > I've noticed a pattern in Geode where we wrap a log call in a check
> > at
> > > > the
> > > > > same level, such as:
> > > > >
> > > > > if (logger.isDebugEnabled()) {
> > > > > logger.debug("cleaning up incompletely started
> > > > > DistributionManager due to exception", r);
> > > > > }
> > > > >
> > > > > Is there any reason to do this? To my mind, it's an extra
> conditional
> > > > that
> > > > > should essentially be the first check inside `logger.debug(...)`
> > > anyways,
> > > > > and it complicates the code and makes it less readable. I've even
> > seen
> > > > > places in the code which have `if (logger.isDebugEnabled())
> > > > > logger.trace(...))` and such.
> > > > >
> > > > > I would like to propose that unless there is a compelling reason to
> > use
> > > > > this pattern, we remove all extra checks entirely.
> > > > >
> > > > > Galen
> > > > >
> > > >
> > >
> >
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Galen O'Sullivan <go...@pivotal.io>.
I think that logging in hot paths/loops is probably something that should
be avoided. And if it is necessary, I suspect that the JIT will
short-circuit that call since debug levels don't generally change.
There probably are a few hot paths that need to optimize logging, but
that's not the majority.
Can we agree to avoid this pattern in new code, since it adversely affects
readability?
Galen
On Fri, Sep 7, 2018 at 1:46 PM, Nicholas Vallely <nv...@pivotal.io>
wrote:
> I was just randomly looking into this a couple of days ago as a tangent to
> 'observability' and came across this Stack Overflow:
> https://stackoverflow.com/questions/6504407/is-there-a-need-to-do-a-iflog-
> isdebugenabled-check
> where the first answer is the most succinct in my opinion.
>
> In the geode code that I searched, we are not consistent with our use of
> the if(statement) wrapper for debug, though most do have the wrapper.
>
> Nick
>
> On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io> wrote:
>
> > Checking with logger.isDebugEnabled() it still a good practice for hot
> > paths to avoid the construction of intermediate object arrays to hold the
> > var-args. Some logging libraries have fixed argument optimizations for
> > var-args up to a specific limit. In very hot paths it is nice to
> > check logger.isDebugEnabled() once into a temp boolean value and then
> check
> > that in all the subsequent debug logging statements in the hot path.
> >
> > -Jake
> >
> >
> > On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
> >
> > > I think this pattern is a holdover from using log4j 1. In that version,
> > you
> > > added an if check to avoid unnecessary string concatenation if debug
> was
> > > enabled.
> > >
> > >
> > > 1. if (logger.isDebugEnabled()) {
> > > 2. logger.debug("Logging in user " + user.getName() + " with
> > > birthday " + user.getBirthdayCalendar());
> > > 3. }
> > >
> > >
> > > Log4j2 lets you pass a format string, so you can just do this:
> > >
> > > logger.debug("Logging in user {} with birthday {}", user.getName(),
> > > user.getBirthdayCalendar());
> > >
> > >
> > > These examples come from the log4j2 docs:
> > >
> > > https://logging.apache.org/log4j/2.0/manual/api.html
> > >
> > > -Dan
> > >
> > > On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <
> gosullivan@apache.org
> > >
> > > wrote:
> > >
> > > > Hi all,
> > > >
> > > > I've noticed a pattern in Geode where we wrap a log call in a check
> at
> > > the
> > > > same level, such as:
> > > >
> > > > if (logger.isDebugEnabled()) {
> > > > logger.debug("cleaning up incompletely started
> > > > DistributionManager due to exception", r);
> > > > }
> > > >
> > > > Is there any reason to do this? To my mind, it's an extra conditional
> > > that
> > > > should essentially be the first check inside `logger.debug(...)`
> > anyways,
> > > > and it complicates the code and makes it less readable. I've even
> seen
> > > > places in the code which have `if (logger.isDebugEnabled())
> > > > logger.trace(...))` and such.
> > > >
> > > > I would like to propose that unless there is a compelling reason to
> use
> > > > this pattern, we remove all extra checks entirely.
> > > >
> > > > Galen
> > > >
> > >
> >
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Nicholas Vallely <nv...@pivotal.io>.
I was just randomly looking into this a couple of days ago as a tangent to
'observability' and came across this Stack Overflow:
https://stackoverflow.com/questions/6504407/is-there-a-need-to-do-a-iflog-isdebugenabled-check
where the first answer is the most succinct in my opinion.
In the geode code that I searched, we are not consistent with our use of
the if(statement) wrapper for debug, though most do have the wrapper.
Nick
On Fri, Sep 7, 2018 at 11:35 AM Jacob Barrett <jb...@pivotal.io> wrote:
> Checking with logger.isDebugEnabled() it still a good practice for hot
> paths to avoid the construction of intermediate object arrays to hold the
> var-args. Some logging libraries have fixed argument optimizations for
> var-args up to a specific limit. In very hot paths it is nice to
> check logger.isDebugEnabled() once into a temp boolean value and then check
> that in all the subsequent debug logging statements in the hot path.
>
> -Jake
>
>
> On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
>
> > I think this pattern is a holdover from using log4j 1. In that version,
> you
> > added an if check to avoid unnecessary string concatenation if debug was
> > enabled.
> >
> >
> > 1. if (logger.isDebugEnabled()) {
> > 2. logger.debug("Logging in user " + user.getName() + " with
> > birthday " + user.getBirthdayCalendar());
> > 3. }
> >
> >
> > Log4j2 lets you pass a format string, so you can just do this:
> >
> > logger.debug("Logging in user {} with birthday {}", user.getName(),
> > user.getBirthdayCalendar());
> >
> >
> > These examples come from the log4j2 docs:
> >
> > https://logging.apache.org/log4j/2.0/manual/api.html
> >
> > -Dan
> >
> > On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <gosullivan@apache.org
> >
> > wrote:
> >
> > > Hi all,
> > >
> > > I've noticed a pattern in Geode where we wrap a log call in a check at
> > the
> > > same level, such as:
> > >
> > > if (logger.isDebugEnabled()) {
> > > logger.debug("cleaning up incompletely started
> > > DistributionManager due to exception", r);
> > > }
> > >
> > > Is there any reason to do this? To my mind, it's an extra conditional
> > that
> > > should essentially be the first check inside `logger.debug(...)`
> anyways,
> > > and it complicates the code and makes it less readable. I've even seen
> > > places in the code which have `if (logger.isDebugEnabled())
> > > logger.trace(...))` and such.
> > >
> > > I would like to propose that unless there is a compelling reason to use
> > > this pattern, we remove all extra checks entirely.
> > >
> > > Galen
> > >
> >
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Jacob Barrett <jb...@pivotal.io>.
Checking with logger.isDebugEnabled() it still a good practice for hot
paths to avoid the construction of intermediate object arrays to hold the
var-args. Some logging libraries have fixed argument optimizations for
var-args up to a specific limit. In very hot paths it is nice to
check logger.isDebugEnabled() once into a temp boolean value and then check
that in all the subsequent debug logging statements in the hot path.
-Jake
On Fri, Sep 7, 2018 at 11:18 AM Dan Smith <ds...@pivotal.io> wrote:
> I think this pattern is a holdover from using log4j 1. In that version, you
> added an if check to avoid unnecessary string concatenation if debug was
> enabled.
>
>
> 1. if (logger.isDebugEnabled()) {
> 2. logger.debug("Logging in user " + user.getName() + " with
> birthday " + user.getBirthdayCalendar());
> 3. }
>
>
> Log4j2 lets you pass a format string, so you can just do this:
>
> logger.debug("Logging in user {} with birthday {}", user.getName(),
> user.getBirthdayCalendar());
>
>
> These examples come from the log4j2 docs:
>
> https://logging.apache.org/log4j/2.0/manual/api.html
>
> -Dan
>
> On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <go...@apache.org>
> wrote:
>
> > Hi all,
> >
> > I've noticed a pattern in Geode where we wrap a log call in a check at
> the
> > same level, such as:
> >
> > if (logger.isDebugEnabled()) {
> > logger.debug("cleaning up incompletely started
> > DistributionManager due to exception", r);
> > }
> >
> > Is there any reason to do this? To my mind, it's an extra conditional
> that
> > should essentially be the first check inside `logger.debug(...)` anyways,
> > and it complicates the code and makes it less readable. I've even seen
> > places in the code which have `if (logger.isDebugEnabled())
> > logger.trace(...))` and such.
> >
> > I would like to propose that unless there is a compelling reason to use
> > this pattern, we remove all extra checks entirely.
> >
> > Galen
> >
>
Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled,
isTraceEnabled, etc.
Posted by Dan Smith <ds...@pivotal.io>.
I think this pattern is a holdover from using log4j 1. In that version, you
added an if check to avoid unnecessary string concatenation if debug was
enabled.
1. if (logger.isDebugEnabled()) {
2. logger.debug("Logging in user " + user.getName() + " with
birthday " + user.getBirthdayCalendar());
3. }
Log4j2 lets you pass a format string, so you can just do this:
logger.debug("Logging in user {} with birthday {}", user.getName(),
user.getBirthdayCalendar());
These examples come from the log4j2 docs:
https://logging.apache.org/log4j/2.0/manual/api.html
-Dan
On Fri, Sep 7, 2018 at 10:50 AM, Galen O'Sullivan <go...@apache.org>
wrote:
> Hi all,
>
> I've noticed a pattern in Geode where we wrap a log call in a check at the
> same level, such as:
>
> if (logger.isDebugEnabled()) {
> logger.debug("cleaning up incompletely started
> DistributionManager due to exception", r);
> }
>
> Is there any reason to do this? To my mind, it's an extra conditional that
> should essentially be the first check inside `logger.debug(...)` anyways,
> and it complicates the code and makes it less readable. I've even seen
> places in the code which have `if (logger.isDebugEnabled())
> logger.trace(...))` and such.
>
> I would like to propose that unless there is a compelling reason to use
> this pattern, we remove all extra checks entirely.
>
> Galen
>