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

[Jeremy Manson]

Hi David.

The change to eliminate the call to getStackTraceDepth and catch the
potential exception instead either makes no difference or makes the
benchmark slightly slower (I can't quite tell which without a lot more
testing).  The getStackTraceDepth call doesn't really do much - it
just iterates over the array - so I don't think it adds much to the
runtime.

In the interests of not writing code that looks like that (i.e.,
"yuck!"), I recommend leaving it as-is.

Jeremy

On Mon, Apr 20, 2009 at 6:39 PM, David Holmes - Sun Microsystems
<David.Holmes at sun.com> wrote:
> Hi Martin, Jeremy,
>
> I'm assuming inferCaller always expects to find a caller, or at least that
> would be the common case - yes? If so then this might be a case where it is
> quicker to forego the getStackTraceDepth() call and simply catch the
> potential exception if we reach the end.
>
> Aside: we really must get webrev or something like it available. These
> simple diffs are really hard to evaluate in isolation.
>
> 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);
>>  }
>