[
https://issues.apache.org/jira/browse/SOLR-12286?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16458706#comment-16458706
]
Erick Erickson commented on SOLR-12286:
---------------------------------------
bq. Short lived objects are dealt with efficiently by the garbage collector.
My turn for a "visceral -1" ;) I vastly prefer not generating useless work
regardless of how efficient cleanup is afterwards.
bq. BTW rand.nextInt() has side-effects; most code you'd put in a log statement
does not. This is likely a factor.
Well, that's largely my point. It's not obvious at all that rand.nextInt()
would have this side effect on logging, at least not to me. What about side
effect N+1? That said I'll concede this one.
The parameterized versions of log messages do help a lot and should be used.
And this pattern generates the string object and throws it away for fairly
obvious reasons:
logger.info("This is a test {} {}", test.toString(), "whatever");
Peruse the current code and you'll see a bunch of the log.info("message" +
"another message") patterns. I count 300 without even straining. My take is
that we _haven't_ done a very good job of paying attention to this. Why do you
think we'll do a better job in future? Who's going to police this?
Then there's also another 300 or so debug and trace level messages with the
same pattern.
Admittedly the above 600 messages are simple greps, perhaps some of them _are_
wrapped in if statements.
This all came to light with some work with JFR.
Now maybe the right thing to do is enhance the forbidden APIs to fail the known
bad logging patterns: any log.whatever calls with plus signs outside of quotes
and any log.whatever that has a toString() in it etc. That'd probably take care
of 99+% of my concerns and the remaining fraction of a percent isn't worth the
trouble.
If that's the consensus we can probably close this or change it to "add
forbidden API check for log messages that create spurious objects". It still
requires that we parameterize all the log.whatever calls.
> 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
