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 <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 >> > > > > >> > > > >> > > >> > >> > >
