#2348 PERF: Bottleneck in LogAndTraceBroker.java - getCaller()

Performance
closed-fixed
Dave Blaschke
5
2012-03-15
2012-02-20
Dennis Jurgensen
No

OK, so here is the problem:
In LogAndTraceBroker.java, the getCaller() method has this line:

StackTraceElement[] stack = (new Throwable()).getStackTrace();

and this code runs EVERY TIME this method is called.

There are two problems with this:
1)(new Throwable()).getStackTrace() is expensive
2)(new Throwable()).getStackTrace() carries a heavy synchronization cost (It BLOCKS)

In high scale environments, the above is causing heavy delays across
the many functions on all CIM traffic. It affects inventory collection and other
critical functions.

THE FIX:
Here's a recommended fix:
1) make a STATIC class variable like this:
static Level levelConfigured = WBEMConfiguration.getGlobalConfiguration().getLogConsoleLevel();

2) In BOTH trace() methods change the code to check the level before calling getCaller() as follows:

public void trace\(Level pLevel, String pMessage\) \{
    try \{

if (pLevel.intValue() >= levelConfigured.intValue() ) { // CHECK LEVEL FIRST
final List<TraceListener> traceListeners = getTraceListeners();
StackTraceElement caller = null;
for (int i = 0; i < traceListeners.size(); ++i) {
caller = caller == null ? getCaller() : caller;
traceListeners.get(i).trace(pLevel, caller, pMessage);
}
}
} catch (Exception e) {
// don't crash for logging
}
}

Discussion

1 2 > >> (Page 1 of 2)
  • Dave Blaschke
    Dave Blaschke
    2012-02-20

    • assigned_to: nobody --> blaschke-oss
    • status: open --> open-accepted
     
  • Dave Blaschke
    Dave Blaschke
    2012-02-20

    The recommended fix is not quite complete as step 1 overlooks a few logging caveats that need to be addressed:

    1) if there are no listeners, nothing will be traced regardless of the log/trace levels

    2) if there is an external listener, they must be called regardless of log/trace levels because there is no way to know what level they are using

    As luck would have it, bug 3484014 added two new methods - isLoggableTrace() and isLoggableMessage() - that handles all of these cases.

    Patch will be provided for feedback from performance folks.

     
  • Dave Blaschke
    Dave Blaschke
    2012-02-20

    Proposed patch

     
    Attachments
  • Dave Blaschke
    Dave Blaschke
    2012-02-20

    The proposed patch is attached, isLoggableTrace() is used to bracket the getCaller() invocations; also, getCaller() is moved outside the loop since the caller will be needed if isLoggableTrace() returns true

     
  • Dave Blaschke
    Dave Blaschke
    2012-02-20

    Patch sent, awaiting feedback from performance test

     
  • Dave Blaschke
    Dave Blaschke
    2012-02-29

    Patch sent for community review. During a 2 week period any
    exploiter may comment on the patch, request changes or turn it
    down completely (with good reason). For the time being the patch is part of the "Experimental" branch in CVS.

     
  • Dave Blaschke
    Dave Blaschke
    2012-02-29

    • status: open-accepted --> open-fixed
     
  • Dave Blaschke
    Dave Blaschke
    2012-03-14

    Patch against HEAD

     
    Attachments
  • Dave Blaschke
    Dave Blaschke
    2012-03-14

    The community review has completed and we received no substantial criticism. Therefore the patch has been approved and merged into the "HEAD" branch. The next release will pick it up.

     
  • Dave Blaschke
    Dave Blaschke
    2012-03-14

    • status: open-fixed --> pending-fixed
     
1 2 > >> (Page 1 of 2)