[
https://issues.apache.org/jira/browse/SOLR-12286?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16459993#comment-16459993
]
Erick Erickson commented on SOLR-12286:
---------------------------------------
Uwe: I can always count on you to further my education!
That comment was confused, I wanted to make sure people knew there was a
"toString()" method on the class in case it mattered, I hadn't really figured
out that the rand.nextInt() was where the problem came from.
I still have some evidence though that this construct is _not_ eliminated by
HotSpot:
logger.info("This is a test {}",rand.nextInt());
.vs.
logger.info("stuff {}", eoe++);
For both cases I put a sleep in before my tight loop that let me get attached
with visualVM. In the first case, as soon as the sleep is done the number of
generated Integer objects shoots up. In the second there's a noticeable delay
(seconds long). Michael's comment about the Integer cache?
But that's a nit, I don't think it's worth any more time. I don't see much
value in going any further with it. rand.nextInt() is totally artificial......
Michael: You're probably right there. Interestingly if I put a sleep for long
enough to get VisualVM attached to the program, there are a few seconds after
the sleep that don't show object creation (compiled and run outside the IDE)
with the below, then it shoots up, but it looks like after we generate a
billion distinct integers or something.
int eoe = 0;
logger.info("stuff {}", eoe++)
So integers aren't all that interesting, Bad Test!
This construct is still evil, no surprise there. Uwe's lambda trick might do
it, but that's not available:
logger.info("stuff {}", test.toString()));
So all in all, I think this is a tempest in a teapot. I didn't particularly
_like_ the suggestion that we wrap all these calls, but OTOH I also didn't like
the idea of creating lots of spurious objects.
I'll close this "won't fix" and we'll deal with this by doing the parameterized
logging calls. I think that'll be sufficient.
> 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: [email protected]
For additional commands, e-mail: [email protected]
