[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16464564#comment-16464564 ] Erick Erickson commented on SOLR-11884: --- Not yet. We're going through the uses of log.info("message" + blahblahblah) type calls. Although that could be another JIRA. > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) > Components: logging >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16464233#comment-16464233 ] Varun Thacker commented on SOLR-11884: -- > NOTE: SOLR-7887 fixed the %C issues, or at least when I checked on 27-Mar > there were no instances of %C in any of the log4j configuration files. Confirmed. The performance implications of %C were documented [https://logging.apache.org/log4j/2.x/manual/layouts.html#LocationInformation] and up until Solr 7.3 the example log4j.properties had %C ( [https://github.com/apache/lucene-solr/blob/releases/lucene-solr/7.3.0/solr/example/resources/log4j.properties#L18] ) but we no longer have any %C starting Solr 7.4 Can we close out this issue? > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) > Components: logging >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16385372#comment-16385372 ] Erick Erickson commented on SOLR-11884: --- NOTE: SOLR-7887 fixed the %C issues > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) > Components: logging >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16336676#comment-16336676 ] Erick Erickson commented on SOLR-11884: --- I pretty much expect this to become an umbrella Jira with sub-tasks, so that'd be fine. And SOLR-10415 may even get a bunch of sub-tasks. > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16336544#comment-16336544 ] Varun Thacker commented on SOLR-11884: -- Hi Erick, How about we split this discussion into two parts? part1: where the %C is grabbing a stack tace and we should disable that by default and tackle that in this jira part2: where expensive log messages should be parameterized . This could be addressed via SOLR-10415 and jiras linked from there If you think this is a good idea then we could edit the Description/Title of the Jira to only cover the first part so that when we look back at this Jira we'll be more clear as to what this was addressing > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16335266#comment-16335266 ] Erick Erickson commented on SOLR-11884: --- Thanks Michael, at least they're linked now > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16334977#comment-16334977 ] Michael Braun commented on SOLR-11884: -- [~erickerickson] I previously logged SOLR-10415 to track some of the issues I found in solr core. > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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
[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging
[ https://issues.apache.org/jira/browse/SOLR-11884?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16334859#comment-16334859 ] Erick Erickson commented on SOLR-11884: --- Forgot to say two things: 1> Assigning to myself to track, don't know when I'll get to it, especially the larger issues of the rest of the code base. 2> I haven't verified these behaviors when using log4j 1.x yet. Whatever doesn't work for log4j 1 we can add after moving to log4j 2 (see SOLR-7887) which should be Real Soon Now. > find/fix inefficiencies in our use of logging > - > > Key: SOLR-11884 > URL: https://issues.apache.org/jira/browse/SOLR-11884 > Project: Solr > Issue Type: Improvement > Security Level: Public(Default Security Level. Issues are Public) >Reporter: Erick Erickson >Assignee: Erick Erickson >Priority: Major > > We've been looking at Solr using Flight Recorder and ran across some > interesting things I'd like to discuss. Let's discuss general logging > approaches here, then perhaps break out sub-JIRAs when we reach any kind of > agreement. > 1> Every log message generates a new Throwable, presumably to get things like > line number, file, class name and the like. On a 2 minute run blasting > updates this meant 150,000 (yes, 150K) instances of "new Throwable()". > > See the section "Asynchronous Logging with Caller Location Information" at: > [https://logging.apache.org/log4j/2.x/performance.html] > I'm not totally sure changing the layout pattern will fix this in log4j 1.x, > but apparently certainly should in log4j 2. > > The cost of course would be that lots of our log messages would lack some of > the information. Exceptions would still contain all the file/class/line > information of course. > > Proposal: > Change the layout pattern to, by default, _NOT_ include information that > requires a Throwable to be created. Also include a pattern that could be > un-commented to get this information back for troubleshooting. > > > > We generate strings when we don't need them. Any construct like > log.info("whatever " + method_that_builds_a_string + " : " + some_variable); > generates the string (some of which are quite expensive) and then throws it > away if the log level is at, say, WARN. The above link also shows that > parameterizing this doesn't suffer this problem, so anything like the above > should be re-written as: > log.info("whatever {} : {} ", method_that_builds_a_string, some_variable); > > The alternative is to do something like but let's make use of the built-in > capabilities instead. > if (log.level >= INFO) { > log.info("whatever " + method_that_builds_a_string + " : " + > some_variable); > } > etc. > This would be a pretty huge thing to fix all-at-once so I suppose we'll have > to approach it incrementally. It's also something that, if we get them all > out of the code should be added to precommit failures. In the meantime, if > anyone who has the precommit chops could create a target that checked for > this it'd be a great help in tracking all of them down, then could be > incorporated in the regular precommit checks if/when they're all removed. > Proposal: > Use JFR or whatever to identify the egregious violations of this kind of > thing (I have a couple I've found) and change them to parameterized form (and > prove it works). Then see what we can do to move forward with removing them > all through the code base. > > -- 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