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