Slowness in LocationInfo construction

[Marc Prud'hommeaux <ma...@solarmetric.com>]

I am using log4j-1.2.6.jar, and I am seeing that
org.apache.log4j.spi.LoggingEvent.getLocationInformation is taking up
73% of my CPU time. This is very distressing, since the CategoryLogger
is the default logger for the Apache Commons Logging project to use, so
just calling org.apache.commons.logging.LogFactory.getLog ("foo").log ("bar")
is going to show this performance hit. This is especially bad, since the
logging output does not even wind up using information from the
LocationInformation that takes so much time to create!

The CPU usage from OptimizeIt is as follows, after which I suggest a
few performance improvements:

 Description of CPU usage for thread group main
     73.58% - 427461.0 ms - java.lang.Throwable.printStackTrace()
         73.58% - 427461.0 ms -
org.apache.log4j.spi.LocationInfo.<init>()
             73.58% - 427461.0 ms -
org.apache.log4j.spi.LoggingEvent.getLocationInformation()
                 73.58% - 427461.0 ms -
org.apache.log4j.helpers.PatternParser$LocationPatternConverter.convert()
                     73.58% - 427461.0 ms -
org.apache.log4j.helpers.PatternConverter.format()
                         73.58% - 427461.0 ms -
org.apache.log4j.PatternLayout.format()
                             73.58% - 427461.0 ms -
org.apache.log4j.WriterAppender.subAppend()
                                 73.58% - 427461.0 ms -
org.apache.log4j.WriterAppender.append()
                                     73.58% - 427461.0 ms -
org.apache.log4j.AppenderSkeleton.doAppend()
                                         73.58% - 427461.0 ms -
org.apache.log4j.helpers.AppenderAttachableImpl.appendLoopOnAppenders()
                                             73.58% - 427461.0 ms -
org.apache.log4j.Category.callAppenders()
                                                 73.58% - 427461.0 ms -
org.apache.log4j.Category.forcedLog()
                                                     73.58% - 427461.0
ms - org.apache.log4j.Category.log()
                                                         73.58% -
427461.0 ms - org.apache.commons.logging.impl.Log4JCategoryLog.info()
                                                             73.58% -
427461.0 ms - com.solarmetric.datasource.DataSourceImpl.log()


First off, in PatternParser$LocationPatternConverter, since the default
switch statement falls through, it is a waste to be invoking
getLocationInformation(), since it may not be used. E.g., the following
code:

    public
    String convert(LoggingEvent event) {
      LocationInfo locationInfo = event.getLocationInformation();
      switch(type) {
      case FULL_LOCATION_CONVERTER:
    return locationInfo.fullInfo;
      case METHOD_LOCATION_CONVERTER:
    return locationInfo.getMethodName();
      case LINE_LOCATION_CONVERTER:
    return locationInfo.getLineNumber();
      case FILE_LOCATION_CONVERTER:
    return locationInfo.getFileName();
      default: return null;
      }
    }
  }

... could be changed to:

    public
    String convert(LoggingEvent event) {
      switch(type) {
      case FULL_LOCATION_CONVERTER:
    return event.getLocationInformation().fullInfo;
      case METHOD_LOCATION_CONVERTER:
    return event.getLocationInformation().getMethodName();
      case LINE_LOCATION_CONVERTER:
    return event.getLocationInformation().getLineNumber();
      case FILE_LOCATION_CONVERTER:
    return event.getLocationInformation().getFileName();
      default: return null;
      }
    }
  }



Secondly, LocationInfo should not dump the stack trace and do the
initial parsing until it actually knows that the information will be
needed. For some reason, the parsing is done in the constructor:


    public LocationInfo(Throwable t, String fqnOfCallingClass) {
      if(t == null)
    return;

      String s;
      // Protect against multiple access to sw.
      synchronized(sw) {
    t.printStackTrace(pw);
    s = sw.toString();
    sw.getBuffer().setLength(0);
      }

     ... more parsing follows ...


Thirdly, I don't understand why the StringWriter sw is static in this
class: the overhead involed in synchronizing access to it outweights the
memory hit that would be taken by just using a member variable.


Finally, since it is often the case that many log messages will be
coming from the same line of code, it may make sense to keep a parse
cache (perhaps in a SoftHashMap) of [stack trace string : parsed
information], so that rapid multiple invocations of a logging message
will not require the stack trace to be reparsed over and over.


-- 
Marc Prud'hommeaux      marc@solarmetric.com
SolarMetric Inc.        http://www.solarmetric.com
Kodo Java Data Objects  Full featured JDO: eliminate the SQL from your code


--
To unsubscribe, e-mail:   <ma...@jakarta.apache.org>
For additional commands, e-mail: <ma...@jakarta.apache.org>