You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by "Uwe Schindler (JIRA)" <ji...@apache.org> on 2018/05/01 08:21:00 UTC
[jira] [Comment Edited] (SOLR-12286) Wrap log instances in "if
(LOG.isLevelEnabled) { log... }
[ https://issues.apache.org/jira/browse/SOLR-12286?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16459524#comment-16459524 ]
Uwe Schindler edited comment on SOLR-12286 at 5/1/18 8:20 AM:
--------------------------------------------------------------
Unfortunately we use slf4j, because log4j has a better feature on top (I hope it gets added to slf4j, too): As said before paramters with {{"\{\}"}} make much sense, but won't help if you want to pass a complex string generated on-they fly. In this case, log4j offers to pass a Java8 lambda:
{code:java}
log.trace("My complex operation took {} and produces no additional objects in production when you print a list!",
() -> Duration.between(startInstant, Instant.now()), () -> String.join("; ", list));
{code}
Of course this generates the lambda using the invokedynamic, but it's not executed. It is static and compiled one time. I use this now all the time for stuff like the above (when the string is complex to be generated, like if you print contents of a List or Set).
P.S.: BTW in the initial description of the issue:
{quote}
{code:java}
// "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");
{code}
{quote}
The comment is wrong: the method toString() is *not* called! The {{info()}} method takes {{Object}} as parameter, so {{test}} is passed as is, with no object generated. The problem is more the {{rand.nextInt()}} as it does autoboxing (which should be eliminated by Hotspot). Keep in mind: When you run this stuff with a debugger it produces more objects than in production, as hotspot can't jump in and eliminate those objects. Autoboxing is in those cases 100% removed by Hotspot, unless you use a debugger!
was (Author: thetaphi):
Unfortunately we use slf4j, because log4j has a better feature on top (I hope it gets added to slf4j, too): As said before paramters with {{"\{\}"}} make much sense, but won't help if you want to pass a complex string generated on-they fly. In this case, log4j offers to pass a Java8 lambda:
{code:java}
log.trace("My complex operation took {} and produces no additional objects in production when you print a list!",
() -> Duration.between(startInstant, Instant.now()), () -> String.join("; ", list));
{code}
Of course this generates the lambda using the invokedynamic, but it's not executed. It is static and compiled one time. I use this now all the time for stuff like the above (when the string is complex to be generated, like if you print contents of a List or Set).
P.S.: BTW in the initial description of the issue:
{quote}
{code:java}
// "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");
{code}
The comment is wrong: the method toString() is *not* called! The {{info()}} method takes {{Object}} as parameter, so {{test}} is passed as is, with no object generated. The problem is more the {{rand.nextInt()}} as it does autoboxing (which should be eliminated by Hotspot). Keep in mind: When you run this stuff with a debugger it produces more objects than in production, as hotspot can't jump in and eliminate those objects. Autoboxing is in those cases 100% removed by Hotspot, unless you use a debugger!
> 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-unsubscribe@lucene.apache.org
For additional commands, e-mail: dev-help@lucene.apache.org