REVIEW 6511515: poor performance of LogRecord.inferCaller depending on java.lang.Throwable.getStackTraceElement
David Holmes - Sun Microsystems
David.Holmes at Sun.COM
Wed Apr 22 04:00:58 UTC 2009
Hi Jeremy,
In the case where the exception is thrown this would be definitely slower :)
But I would have expected some improvement otherwise as this is a native
call with all the ensuing checks and transitions.
C'est la vie. It was just a thought. :)
Cheers,
David
Jeremy Manson said the following on 04/22/09 13:55:
> 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);
>>> }
More information about the core-libs-dev
mailing list