[ 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-unsubscr...@lucene.apache.org For additional commands, e-mail: dev-h...@lucene.apache.org