[
https://issues.apache.org/jira/browse/SOLR-12286?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16458283#comment-16458283
]
Mark Miller commented on SOLR-12286:
------------------------------------
Yeah, I think the first step here is to figure out what is going on. This
information seems to conflict with
https://www.slf4j.org/faq.html#logging_performance, so we want to know exactly
what is up before we change or enforce anything.
I think it's obvious in java that if you construct an expensive object in a
trace method, you probably want that creation wrapped with an if trace - it has
to be constructed before the method is called. It's much more normal to pass
existing objects or simple strings.
It would be great to know what those objects are and the actual affect of
them, especially more real world vs micro benchmark.
> 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-unsubscr...@lucene.apache.org
For additional commands, e-mail: dev-h...@lucene.apache.org
