> On May 10, 2016, at 5:17 PM, Ralph Goers <ralph.go...@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.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
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>>>
>>>
>>
>>
>
>
