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 <gosulli...@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 <nvall...@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 <jbarr...@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 <dsm...@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 < > > gosulli...@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 > > > > > > > > > > > > > > >
