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.fu...@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.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
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>>
>>
>
>
