lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Uwe Schindler (JIRA)" <j...@apache.org>
Subject [jira] [Comment Edited] (SOLR-12286) Wrap log instances in "if (LOG.isLevelEnabled) { log... }
Date Tue, 01 May 2018 08:21:00 GMT

    [ 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


Mime
View raw message