Uploaded image for project: 'Solr'
  1. Solr
  2. SOLR-12286

Wrap log instances in "if (LOG.isLevelEnabled) { log... }

    XMLWordPrintableJSON

Details

    • Improvement
    • Status: Closed
    • Major
    • Resolution: Won't Fix
    • None
    • None
    • None
    • None

    Description

      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:

        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");
        }
      

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

      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();
        }
      }
      

      Attachments

        Issue Links

          Activity

            People

              erickerickson Erick Erickson
              erickerickson Erick Erickson
              Votes:
              0 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved: