Erick Erickson created SOLR-12286:
-------------------------------------
Summary: 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
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: [email protected]
For additional commands, e-mail: [email protected]
