[jira] [Commented] (SOLR-11884) find/fix inefficiencies in our use of logging

2018-05-04 Thread Erick Erickson (JIRA)

[ 
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

2018-05-04 Thread Varun Thacker (JIRA)

[ 
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

2018-03-04 Thread Erick Erickson (JIRA)

[ 
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

2018-01-23 Thread Erick Erickson (JIRA)

[ 
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

2018-01-23 Thread Varun Thacker (JIRA)

[ 
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

2018-01-22 Thread Erick Erickson (JIRA)

[ 
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

2018-01-22 Thread Michael Braun (JIRA)

[ 
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

2018-01-22 Thread Erick Erickson (JIRA)

[ 
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