[SOLR-11901] Improve how logging collects class name information

• Type: Improvement
• Status: Resolved
• Priority: Minor
• Resolution: Done
• Fix Version/s: 7.4
• Assignee: Varun Thacker
• Reporter: Varun Thacker
• Created: 24/Jan/18 23:35
• Updated: 10/Apr/20 13:17
• Resolved: 10/Apr/20 13:17

Description

The log4j.properties that we ship with Solr has this Pattern

%d{yyyy-MM-dd HH:mm:ss.SSS} %-5p (%t) [%X{collection} %X{shard} %X{replica} %X{core}] %c{1.} %m%n

The %c collects class name information ( more on this http://logging.apache.org/log4j/2.x/manual/async.html#Location ) which creates a throwable ( https://github.com/apache/log4j/blob/trunk/src/main/java/org/apache/log4j/spi/LoggingEvent.java#L253 ) and it can be expensive

Here is the stack trace excerpt from the JFR capture which lead to this issue

org.apache.log4j.spi.LoggingEvent.getLocationInformation()
org.apache.log4j.helpers.PatternParser$ClassNamePatternConverter.getFullyQualifiedName(LoggingEvent)
org.apache.log4j.helpers.PatternParser$NamedPatternConverter.convert(LoggingEvent)
org.apache.log4j.helpers.PatternConverter.format(StringBuffer, LoggingEvent)
org.apache.log4j.PatternLayout.format(LoggingEvent)
org.apache.log4j.WriterAppender.subAppend(LoggingEvent)
org.apache.log4j.RollingFileAppender.subAppend(LoggingEvent)
...
org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.finish()	214,658	32.42	0

We could remove capturing the class name information from the default config but ideally capturing the classname is useful. So if we can find a way that doesn't need to create a throwable then it's ideal.

Here is an interesting read : https://shipilev.net/blog/2014/exceptional-performance/

Issue Links

• is fixed by: SOLR-7887 Upgrade Solr to use log4j2 -- log4j 1 now officially end of life
• relates to: SOLR-11934 Visit Solr logging, it's too noisy.