webrev Re: REVIEW 6511515: poor performance of LogRecord.inferCaller depending on java.lang.Throwable.getStackTraceElement

[Tim Bell]

David wrote:

> Aside: we really must get webrev or something like it available. These 
> simple diffs are really hard to evaluate in isolation.

The webrev script we are using for OpenJDK is available to anyone here:

   http://blogs.sun.com/jcc/resource/webrev

I understand that it is easy to send a diff or a patch, and of course 
doing that will preserve it in the email record.

On the other hand, the webrev script will create a patch file for you, 
and also create web pages showing the proposed changes in ways that many 
folks prefer to read.

HTH-
Tim

> Cheers,
> David
> 
> Martin Buchholz said the following on 04/21/09 09:25:
>> Hi java.util.logging maintainers,
>>
>> Here is a patch to improve the performance of
>> LogRecord.inferCaller.  This improves the performance
>> of the microbenchmark in 6511515 by 5x.
>> Swamy, please review.
>> Contributed by Jeremy Manson.
>> http://cr.openjdk.java.net/~martin/inferCaller
>>
>> As a followon, it makes sense to allow full random
>> access to elements of a stack trace.  If that is done,
>> this change would be simplified by not requiring
>> SharedSecrets.
>>
>> # HG changeset patch
>> # User martin
>> # Date 1240268799 25200
>> # Node ID ba9c54ffcac48493a46ee902dae6809cf4678e8d
>> # Parent  8b326aebb981265a99ed96355efe28f8c1b0a0c0
>> 6511515: poor performance of LogRecord.inferCaller depending on
>> java.lang.Throwable.getStackTraceElement
>> Reviewed-by: swamyv
>> Contributed-by: jeremymanson
>> Summary: Allow random access to stack trace elements; retrieve only 
>> needed ones
>>
>> diff --git a/src/share/classes/java/lang/System.java
>> b/src/share/classes/java/lang/System.java
>> --- a/src/share/classes/java/lang/System.java
>> +++ b/src/share/classes/java/lang/System.java
>> @@ -1174,6 +1174,12 @@
>>              public void registerShutdownHook(int slot, Runnable r) {
>>                  Shutdown.add(slot, r);
>>              }
>> +            public int getStackTraceDepth(Throwable t) {
>> +                return t.getStackTraceDepth();
>> +            }
>> +            public StackTraceElement getStackTraceElement(Throwable 
>> t, int i) {
>> +                return t.getStackTraceElement(i);
>> +            }
>>          });
>>      }
>>
>> diff --git a/src/share/classes/java/lang/Throwable.java
>> b/src/share/classes/java/lang/Throwable.java
>> --- a/src/share/classes/java/lang/Throwable.java
>> +++ b/src/share/classes/java/lang/Throwable.java
>> @@ -645,17 +645,21 @@
>>      /**
>>       * Returns the number of elements in the stack trace (or 0 if the 
>> stack
>>       * trace is unavailable).
>> +     *
>> +     * package-protection for use by SharedSecrets.
>>       */
>> -    private native int getStackTraceDepth();
>> +    native int getStackTraceDepth();
>>
>>      /**
>>       * Returns the specified element of the stack trace.
>> +     *
>> +     * package-protection for use by SharedSecrets.
>>       *
>>       * @param index index of the element to return.
>>       * @throws IndexOutOfBoundsException if <tt>index < 0 ||
>>       *         index >= getStackTraceDepth() </tt>
>>       */
>> -    private native StackTraceElement getStackTraceElement(int index);
>> +    native StackTraceElement getStackTraceElement(int index);
>>
>>      private synchronized void writeObject(java.io.ObjectOutputStream s)
>>          throws IOException
>> diff --git a/src/share/classes/java/util/logging/LogRecord.java
>> b/src/share/classes/java/util/logging/LogRecord.java
>> --- a/src/share/classes/java/util/logging/LogRecord.java
>> +++ b/src/share/classes/java/util/logging/LogRecord.java
>> @@ -28,6 +28,9 @@
>>  import java.util.concurrent.atomic.AtomicInteger;
>>  import java.util.concurrent.atomic.AtomicLong;
>>  import java.io.*;
>> +
>> +import sun.misc.JavaLangAccess;
>> +import sun.misc.SharedSecrets;
>>
>>  /**
>>   * LogRecord objects are used to pass logging requests between
>> @@ -522,29 +525,31 @@
>>      // Private method to infer the caller's class and method names
>>      private void inferCaller() {
>>          needToInferCaller = false;
>> -        // Get the stack trace.
>> -        StackTraceElement stack[] = (new Throwable()).getStackTrace();
>> -        // First, search back to a method in the Logger class.
>> -        int ix = 0;
>> -        while (ix < stack.length) {
>> -            StackTraceElement frame = stack[ix];
>> +        JavaLangAccess access = SharedSecrets.getJavaLangAccess();
>> +        Throwable throwable = new Throwable();
>> +        int depth = access.getStackTraceDepth(throwable);
>> +
>> +        String logClassName = "java.util.logging.Logger";
>> +        boolean lookingForLogger = true;
>> +        for (int ix = 0; ix < depth; ix++) {
>> +            // Calling getStackTraceElement directly prevents the VM
>> +            // from paying the cost of building the entire stack frame.
>> +            StackTraceElement frame =
>> +                access.getStackTraceElement(throwable, ix);
>>              String cname = frame.getClassName();
>> -            if (cname.equals("java.util.logging.Logger")) {
>> -                break;
>> +            if (lookingForLogger) {
>> +                // Skip all frames until we have found the first 
>> logger frame.
>> +                if (cname.equals(logClassName)) {
>> +                    lookingForLogger = false;
>> +                }
>> +            } else {
>> +                if (!cname.equals(logClassName)) {
>> +                    // We've found the relevant frame.
>> +                    setSourceClassName(cname);
>> +                    setSourceMethodName(frame.getMethodName());
>> +                    return;
>> +                }
>>              }
>> -            ix++;
>> -        }
>> -        // Now search for the first frame before the "Logger" class.
>> -        while (ix < stack.length) {
>> -            StackTraceElement frame = stack[ix];
>> -            String cname = frame.getClassName();
>> -            if (!cname.equals("java.util.logging.Logger")) {
>> -                // We've found the relevant frame.
>> -                setSourceClassName(cname);
>> -                setSourceMethodName(frame.getMethodName());
>> -                return;
>> -            }
>> -            ix++;
>>          }
>>          // We haven't found a suitable frame, so just punt.  This is
>>          // OK as we are only committed to making a "best effort" here.
>> diff --git a/src/share/classes/sun/misc/JavaLangAccess.java
>> b/src/share/classes/sun/misc/JavaLangAccess.java
>> --- a/src/share/classes/sun/misc/JavaLangAccess.java
>> +++ b/src/share/classes/sun/misc/JavaLangAccess.java
>> @@ -57,4 +57,14 @@
>>
>>      /** register shutdown hook */
>>      void registerShutdownHook(int slot, Runnable r);
>> +
>> +    /**
>> +     * Returns the number of stack frames represented by the given 
>> throwable.
>> +     */
>> +    int getStackTraceDepth(Throwable t);
>> +
>> +    /**
>> +     * Returns the ith StackTraceElement for the given throwable.
>> +     */
>> +    StackTraceElement getStackTraceElement(Throwable t, int i);
>>  }