From dev-return-320684-archive-asf-public=cust-asf.ponee.io@lucene.apache.org Tue May 1 10:21:11 2018 Return-Path: X-Original-To: archive-asf-public@cust-asf.ponee.io Delivered-To: archive-asf-public@cust-asf.ponee.io Received: from mail.apache.org (hermes.apache.org [140.211.11.3]) by mx-eu-01.ponee.io (Postfix) with SMTP id 9681E180645 for ; Tue, 1 May 2018 10:21:10 +0200 (CEST) Received: (qmail 99886 invoked by uid 500); 1 May 2018 08:21:04 -0000 Mailing-List: contact dev-help@lucene.apache.org; run by ezmlm Precedence: bulk List-Help: List-Unsubscribe: List-Post: List-Id: Reply-To: dev@lucene.apache.org Delivered-To: mailing list dev@lucene.apache.org Received: (qmail 99876 invoked by uid 99); 1 May 2018 08:21:04 -0000 Received: from pnap-us-west-generic-nat.apache.org (HELO spamd4-us-west.apache.org) (209.188.14.142) by apache.org (qpsmtpd/0.29) with ESMTP; Tue, 01 May 2018 08:21:04 +0000 Received: from localhost (localhost [127.0.0.1]) by spamd4-us-west.apache.org (ASF Mail Server at spamd4-us-west.apache.org) with ESMTP id 92252C0334 for ; Tue, 1 May 2018 08:21:03 +0000 (UTC) X-Virus-Scanned: Debian amavisd-new at spamd4-us-west.apache.org X-Spam-Flag: NO X-Spam-Score: -110.311 X-Spam-Level: X-Spam-Status: No, score=-110.311 tagged_above=-999 required=6.31 tests=[ENV_AND_HDR_SPF_MATCH=-0.5, RCVD_IN_DNSWL_MED=-2.3, SPF_PASS=-0.001, T_RP_MATCHES_RCVD=-0.01, USER_IN_DEF_SPF_WL=-7.5, USER_IN_WHITELIST=-100] autolearn=disabled Received: from mx1-lw-eu.apache.org ([10.40.0.8]) by localhost (spamd4-us-west.apache.org [10.40.0.11]) (amavisd-new, port 10024) with ESMTP id 8VZSn_5izpaQ for ; Tue, 1 May 2018 08:21:01 +0000 (UTC) Received: from mailrelay1-us-west.apache.org (mailrelay1-us-west.apache.org [209.188.14.139]) by mx1-lw-eu.apache.org (ASF Mail Server at mx1-lw-eu.apache.org) with ESMTP id 5B33C5F5B1 for ; Tue, 1 May 2018 08:21:01 +0000 (UTC) Received: from jira-lw-us.apache.org (unknown [207.244.88.139]) by mailrelay1-us-west.apache.org (ASF Mail Server at mailrelay1-us-west.apache.org) with ESMTP id 8BE2DE0181 for ; Tue, 1 May 2018 08:21:00 +0000 (UTC) Received: from jira-lw-us.apache.org (localhost [127.0.0.1]) by jira-lw-us.apache.org (ASF Mail Server at jira-lw-us.apache.org) with ESMTP id 4927B21291 for ; Tue, 1 May 2018 08:21:00 +0000 (UTC) Date: Tue, 1 May 2018 08:21:00 +0000 (UTC) From: "Uwe Schindler (JIRA)" To: dev@lucene.apache.org Message-ID: In-Reply-To: References: Subject: [jira] [Commented] (SOLR-12286) Wrap log instances in "if (LOG.isLevelEnabled) { log... } MIME-Version: 1.0 Content-Type: text/plain; charset=utf-8 Content-Transfer-Encoding: 7bit X-JIRA-FingerPrint: 30527f35849b9dde25b450d4833f0394 [ https://issues.apache.org/jira/browse/SOLR-12286?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16459524#comment-16459524 ] Uwe Schindler commented on SOLR-12286: -------------------------------------- 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