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

[David Holmes - Sun Microsystems]

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);
>  }