lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Erick Erickson (JIRA)" <>
Subject [jira] [Commented] (SOLR-12286) Wrap log instances in "if (LOG.isLevelEnabled) { log... }
Date Tue, 01 May 2018 18:34:00 GMT


Erick Erickson commented on SOLR-12286:

Uwe: I can always count on you to further my education!

That comment was confused, I wanted to make sure people knew there was a "toString()" method
on the class in case it mattered, I hadn't really figured out that the rand.nextInt() was
where the problem came from.

I still have some evidence though that this construct is _not_ eliminated by HotSpot:"This is a test {}",rand.nextInt());
.vs."stuff {}", eoe++);

For both cases I put a sleep in before my tight loop that let me get attached with visualVM.
In the first case, as soon as the sleep is done the number of generated Integer objects shoots
up. In the second there's a noticeable delay (seconds long). Michael's comment about the Integer

But that's a nit, I don't think it's worth any more time. I don't see much value in going
any further with it. rand.nextInt() is totally artificial......

Michael: You're probably right there. Interestingly if I put a sleep for long enough to get
VisualVM attached to the program, there are a few seconds after the sleep that don't show
object creation (compiled and run outside the IDE) with the below, then it shoots up, but
it looks like after we generate a billion distinct integers or something.

int eoe = 0;"stuff {}", eoe++)

So integers aren't all that interesting, Bad Test!

This construct is still evil, no surprise there. Uwe's lambda trick might do it, but that's
not available:"stuff {}", test.toString()));

So all in all, I think this is  a tempest in a teapot. I didn't particularly _like_ the suggestion
that we wrap all these calls, but OTOH I also didn't like the idea of creating lots of spurious

I'll close this "won't fix" and we'll deal with this by doing the parameterized logging calls.
I think that'll be sufficient.

> Wrap log instances in "if (LOG.isLevelEnabled) { log... }
> ---------------------------------------------------------
>                 Key: SOLR-12286
>                 URL:
>             Project: Solr
>          Issue Type: Improvement
>      Security Level: Public(Default Security Level. Issues are Public) 
>            Reporter: Erick Erickson
>            Assignee: Erick Erickson
>            Priority: Major
> I've been playing around with the question "are objects generated when logging if I use
pattern....." and "it depends" (tm). I'll attach a test program for anyone to use. Attach
VisualVM to it and sample memory when various patterns are enabled.
> The nub of it is this: with the log level set at ERROR, no messages from any of these
are printed, yet the number of objects created is vastly different:
> {code}
>   while (true) {
>       // "test" is an instance of a class with an overridden toString() method.
>       // These generate a zillion spurious objects.
>"This is a test {} {} {}", test, rand.nextInt(), "whatever");
>"This is a test {}", rand.nextInt());
>"This is really bad" + test);
>       // These don't generate spurious objects
>"This is a test {} {}", test, "whatever");
>"This is really bad" + "whatever");
>   }
> {code}
> Simply generating a new random number doesn't create zillions of objects.
> I don't particularly care _why_ the differences exist, the take-away is that if we simply
establish the rule "wrap log.level() messages with if..." then we'll avoid the problems altogether.
That's _much_ easier to both remember and enforce than trying to understand and remember when
pattern A is acceptable and pattern B is not.
> Maybe we could even make this a precommit failure?
> Solr has enough "interesting" things happen re: GC that we don't need to needlessly add
to GC pressure.
> Parameterizing is still a good idea as in SOLR-10415 (I'll link)
> Here's the full program, there's not a lot of sophistication here....:
> {code}
> import org.apache.logging.log4j.Level;
> import org.apache.logging.log4j.Logger;
> import org.apache.logging.log4j.LogManager;
> import org.apache.logging.log4j.core.LoggerContext;
> import org.apache.logging.log4j.core.config.Configuration;
> import org.apache.logging.log4j.core.config.LoggerConfig;
> import java.util.Random;
> public class Log4J2Test {
>   // Define a static logger variable so that it references the
>   // Logger instance named "MyApp".
>   private static final Logger logger = LogManager.getLogger(Log4J2Test.class);
>   static Random rand = new Random();
>   public static void main(final String... args) {
>     // Set up a simple configuration that logs on the console.
>     logger.trace("Entering application.");
>     LoggerContext ctx = (LoggerContext) LogManager.getContext(false);
>     Configuration config = ctx.getConfiguration();
>     LoggerConfig loggerConfig = config.getLoggerConfig(LogManager.ROOT_LOGGER_NAME);
>     loggerConfig.setLevel(Level.ERROR);
>     ctx.updateLoggers();
>     Test test = new Test();
>     logger.error("Ensure something comes out.");
>     while (true) {
>       if (logger.isInfoEnabled()) {
>         // These generate a zillion objects.
>"This is a test {} {} {}", test, rand.nextInt(), "whatever");
>"This is a test {}", rand.nextInt());
>"This is really bad" + test);
>         // These generates no spurious objects
>"This is a test {} {}", test, "whatever");
>"This is really bad" + "whatever");
>       }
>     }
>   }
> }
> class Test {
>   static Random rand = new Random();
>   public String toString() {
>     return "This is some random string" + rand.nextInt();
>   }
> }
> {code}

This message was sent by Atlassian JIRA

To unsubscribe, e-mail:
For additional commands, e-mail:

View raw message