lucene-dev mailing list archives

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

     [ https://issues.apache.org/jira/browse/SOLR-12286?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]

Erick Erickson resolved SOLR-12286.
-----------------------------------
    Resolution: Won't Fix

Using parameterized logging will take care of almost all the cases.

> Wrap log instances in "if (LOG.isLevelEnabled) { log... }
> ---------------------------------------------------------
>
>                 Key: SOLR-12286
>                 URL: https://issues.apache.org/jira/browse/SOLR-12286
>             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.
>       logger.info("This is a test {} {} {}", test, rand.nextInt(), "whatever");
>       logger.info("This is a test {}", rand.nextInt());
>       logger.info("This is really bad" + test);
>       
>       // These don't generate spurious objects
>       logger.info("This is a test {} {}", test, "whatever");
>       logger.info("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.
>         logger.info("This is a test {} {} {}", test, rand.nextInt(), "whatever");
>         logger.info("This is a test {}", rand.nextInt());
>         logger.info("This is really bad" + test);
>         // These generates no spurious objects
>         logger.info("This is a test {} {}", test, "whatever");
>         logger.info("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
(v7.6.3#76005)

---------------------------------------------------------------------
To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org


Mime
View raw message