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?
Ralph
> On May 10, 2016, at 5:01 PM, Mandy Chung <mandy.ch...@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.go...@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.ch...@oracle.com> wrote:
>>>
>>> What does your benchmark call?
>>>
>>> Mandy
>>>
>>>> On May 10, 2016, at 9:49 AM, Ralph Goers <ralph.go...@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.ch...@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.go...@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.ch...@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.go...@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.ch...@oracle.com>
>>>>>>>>> wrote:
>>>>>>>>>
>>>>>>>>>
>>>>>>>>>> On Apr 12, 2016, at 1:34 AM, Rémi Forax <fo...@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.ch...@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
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>>
>>
>
>
