Review request 8153912: StackFrame::getFileName and StackFrame::getLineNumber not needed

Ralph Goers ralph.goers at dslextreme.com
Wed May 11 16:14:50 UTC 2016 

Yes, we need the StakWalker API for other parts of our code where we need the Class so we can determine what ClassLoader to use.  For creating a LogEvent with location information we primarily need the class name, method name and line number. However, the “extended” Throwable also returns the name of the jar the class came from and the location of the jar, so in that case we would want to use the StackWalker API - so it probably makes more sense to always use it.

You are correct that most of the time it would be faster to start from frame 0. However, the problem we have with walking the stack from frame 0 is that it is possible to have a situation like  

Foo::method1—>Logger.log—>BarAppender.append—>Foo::method2 (or even method1 again)—>Logger.log 

If we start from the top we will believe Foo::method 1 is where we were called from, which would be incorrect. If in the Logger.log method we were able to capture the current stack frame index from StackWalker we could then pass that on through and then when we actually need the StackElement we could just ask for index-1, but I don’t see any methods like that, which is unfortunate.

Ralph

> On May 11, 2016, at 7:22 AM, Daniel Fuchs <daniel.fuchs at oracle.com> wrote:
> 
> Hi Ralph,
> 
> On 10/05/16 19:40, Ralph Goers wrote:
>> The benchmark logs events using Log4j 2’s asynchronous loggers. In the process of doing that it captures the location information using the code below:
>> 
>> 
>> // LOG4J2-1029 new Throwable().getStackTrace is faster than Thread.currentThread().getStackTrace().
>> final StackTraceElement[] stackTrace = new Throwable().getStackTrace();
>> StackTraceElement last = null;
>> for (int i = stackTrace.length - 1; i > 0; i--) {
>>    final String className = stackTrace[i].getClassName();
>>    if (fqcnOfLogger.equals(className)) {
>>        return last;
>>    }
>>    last = stackTrace[i];
>> }
>> return null;
> 
> Your benchmark walks the stack backwards.
> 
> To take the full benefits of only walking part of the stack
> you should consider changing your algorithm to walk from
> frame 0 instead.
> 
> With the StackWalker API you get a chance to get the
> Class that declares the method on the frame - which
> makes it possible to use things like Class.isAssignableFrom
> etc..., which could make it now possible to implement
> different strategies.
> 
> Hope this helps,
> 
> -- daniel
> 
>> 
>> Ralph
>> 
>> 
>>> On May 10, 2016, at 9:57 AM, Mandy Chung <mandy.chung at oracle.com> wrote:
>>> 
>>> What does your benchmark call?
>>> 
>>> Mandy
>>> 
>>>> On May 10, 2016, at 9:49 AM, Ralph Goers <ralph.goers at dslextreme.com> wrote:
>>>> 
>>>> I just ran one of the Log4j performance tests that specifically captures location information.  To run the test I do
>>>> 
>>>> java -jar log4j-perf/target/benchmarks.jar ".*AsyncAppenderLog4j2LocationBenchmark.*" -f 1 -wi 10 -i 20 -t 4 -si true
>>>> 
>>>> And the results are:
>>>> 
>>>> java version "1.7.0_80
>>>> 
>>>> Benchmark                                                             Mode  Samples       Score      Error  Units
>>>> o.a.l.l.p.j.AsyncAppenderLog4j2LocationBenchmark.throughputSimple    thrpt       20  124819.285 ± 3003.918  ops/s
>>>> 
>>>> java version "1.8.0_65"
>>>> 
>>>> Benchmark                                                             Mode  Samples       Score      Error  Units
>>>> o.a.l.l.p.j.AsyncAppenderLog4j2LocationBenchmark.throughputSimple    thrpt       20  123209.746 ± 3064.672  ops/s
>>>> 
>>>> 
>>>> java version "9-ea"
>>>> Java(TM) SE Runtime Environment (build 9-ea+116)
>>>> 
>>>> Benchmark                                                             Mode  Samples      Score      Error  Units
>>>> o.a.l.l.p.j.AsyncAppenderLog4j2LocationBenchmark.throughputSimple    thrpt       20  96090.261 ± 4565.763  ops/s
>>>> 
>>>> 
>>>> This tells me that Java 9 is about 23% slower than previous versions in walking the stack trace elements.
>>>> 
>>>> Ralph
>>>> 
>>>>> On Apr 13, 2016, at 12:03 PM, Mandy Chung <mandy.chung at oracle.com> wrote:
>>>>> 
>>>>> If you record all stack frames, I can believe Throwable is faster because of a recent optimization JDK-8150778 that has been made in jdk9 to improve the Throwable::getStackTraceElements method.
>>>>> 
>>>>> Mandy
>>>>> 
>>>>>> On Apr 13, 2016, at 11:49 AM, Ralph Goers <ralph.goers at dslextreme.com> wrote:
>>>>>> 
>>>>>> I did a raw test of StackWalker by itself and the performance was much better than using a Throwable to get the location information.  However, I haven’t tested how it will be implemented in Log4j.  We still support Java 7 (and will for some time) so we have to find a way to support using StackWalker when running on Java 9 even though we build with Java 7.
>>>>>> 
>>>>>> Ralph
>>>>>> 
>>>>>>> On Apr 13, 2016, at 10:27 AM, Mandy Chung <mandy.chung at oracle.com> wrote:
>>>>>>> 
>>>>>>> It is good to know Log4J is planning to use StackWalker.
>>>>>>> 
>>>>>>> Thanks for the feedback.  I will reconsider.
>>>>>>> 
>>>>>>> One thing to mention is the patch went in jdk9/hs-rt that will show up in jdk9/dev some time that changes the implementation to create StackTraceElement to get filename and line number.  The object allocation should be cheap that does create short-lived objects.  The main motivation of JDK-8153123 was to simplify the hotspot implementation that the runtime team had concern about. There is an open issue to follow up the performance (JDK-8153683).  It’d be helpful to get your feedback on using StackWalker API and the performance data.
>>>>>>> 
>>>>>>> Mandy
>>>>>>> 
>>>>>>>> On Apr 13, 2016, at 6:51 AM, Ralph Goers <ralph.goers at dslextreme.com> wrote:
>>>>>>>> 
>>>>>>>> I had planned on using StackWalker to generate the location information for every logging event. It seems that this change would thus cause the creation of a new StackTraceElement for every logger event. That seems wasteful. Log4j is currently in the process of trying to reduce the number of objects that are created while logging as it has a significant impact on garbage collection. So I am also in favor of getting the filename and line number directly from the StackFrame.
>>>>>>>> 
>>>>>>>> Ralph
>>>>>>>> 
>>>>>>>>> On Apr 12, 2016, at 5:15 PM, Mandy Chung <mandy.chung at oracle.com> wrote:
>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>>> On Apr 12, 2016, at 1:34 AM, Rémi Forax <forax at univ-mlv.fr> wrote:
>>>>>>>>>> 
>>>>>>>>>> Hi Mandy,
>>>>>>>>>> I really don't like this patch.
>>>>>>>>>> 
>>>>>>>>>> Being forced to call toStackElement to get the line number is counter intuitive.
>>>>>>>>>> I would prefer the two methods to not return Optional but an int and a String with the same convention as StackElement if the point of this patch is to remove the dependency to Optional.
>>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>> I was expecting the common usage of StackWalker API does not need file name and line number.  I think it'd be useful to include StackFrame::getBci (in the future it might include live information like locals etc) and keep the optional stuff and uncommon usage to StackTraceElement.
>>>>>>>>> 
>>>>>>>>> Mandy
>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>>> Rémi
>>>>>>>>>> 
>>>>>>>>>> 
>>>>>>>>>> Le 11 avril 2016 23:22:39 CEST, Mandy Chung <mandy.chung at oracle.com> a écrit :
>>>>>>>>>>> Webrev at:
>>>>>>>>>>> http://cr.openjdk.java.net/~mchung/jdk9/webrevs/8153912/webrev.00/index.html
>>>>>>>>>>> 
>>>>>>>>>>> StackFrame::getFileName and StackFrame::getLineNumber are originally
>>>>>>>>>>> proposed with the view of any stack walking code can migrate to the
>>>>>>>>>>> StackWalker API without the use of StackTraceElement.
>>>>>>>>>>> 
>>>>>>>>>>> File name and line number are useful for debugging and troubleshooting
>>>>>>>>>>> purpose. It has additional overhead to map from a method and BCI to
>>>>>>>>>>> look up the file name and line number.
>>>>>>>>>>> 
>>>>>>>>>>> StackFrame::toStackTraceElement method returns StackTraceElement that
>>>>>>>>>>> includes the file name and line number. There is no particular benefit
>>>>>>>>>>> to duplicate getFileName and getLineNumber methods in StackFrame. It is
>>>>>>>>>>> equivalently convenient to call
>>>>>>>>>>> StackFrame.toStackTraceElement().getFileName() (or getLineNumber).
>>>>>>>>>>> 
>>>>>>>>>>> This patch proposes to remove StackFrame::getFileName and
>>>>>>>>>>> StackFrame::getLineNumber methods since such information can be
>>>>>>>>>>> obtained from StackFrame.toStackTraceElement().
>>>>>>>>>>> 
>>>>>>>>>>> Mandy
>>>>>>>>>> 
>>>>>>>>> 
>>>>>>>>> 
>>>>>>>> 
>>>>>>>> 
>>>>>>> 
>>>>>>> 
>>>>>> 
>>>>>> 
>>>>> 
>>>>> 
>>>> 
>>> 
>>> 
>> 
> 
>

More information about the core-libs-dev mailing list