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

Mandy Chung mandy.chung at oracle.com
Wed May 11 02:26:03 UTC 2016 

> On May 10, 2016, at 5:17 PM, Ralph Goers <ralph.goers at dslextreme.com> wrote:
> 
> OK - I try that. My  earlier comparison had shown that StackWalker was much faster but since walking the Throwable is so much slower I’m now wondering how much better than Java 7 & 8 it will be.
> 
> Any idea why walking the Throwable is so much slower?
> 

No idea yet.  Can you share your benchmark so that we can understand what you measure?  

Mandy

> Ralph
> 
>> On May 10, 2016, at 5:01 PM, Mandy Chung <mandy.chung at oracle.com> wrote:
>> 
>> This walks the stack to find a frame with a matching class.  Throwable::getStackTrace is taking the entire stack trace.  I suggest to try StackWalker and avoids the overhead of dumping the entire stack trace.
>> 
>> Mandy
>> 
>>> On May 10, 2016, at 10:40 AM, Ralph Goers <ralph.goers at dslextreme.com> 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;
>>> 
>>> 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