geode-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From John Blum <jb...@pivotal.io>
Subject Re: [DISCUSS] Wrapping log calls in Conditionals like isDebugEnabled, isTraceEnabled, etc.
Date Tue, 11 Sep 2018 16:26:30 GMT
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 <demery@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 <klund@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 <klund@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 <jbarrett@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 <dsmith@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)

Mime
  • Unnamed multipart/alternative (inline, None, 0 bytes)
View raw message