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

[Martin Buchholz]

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 &lt; 0 ||
      *         index &gt;= 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);
 }