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
- is related to
-
SOLR-10415 Within solr-core, debug/trace level logging should use parameterized log messages
- Closed
-
LUCENE-7788 fail precommit on unparameterised log messages and examine for wasted work/objects
- Closed