> On May 11, 2016, at 9:24 AM, Ralph Goers <[email protected]> wrote:
>
> Currently StackWalker has a getCallerClass method, but not a
> getCallerStackFrame. Having that method could also solve the problem, but
> only if it is efficient enough that it could be called for every log event,
> since when we would be calling it we wouldn’t even know if the user required
> it. In looking at getCallerClass it isn’t clear to me how fast it actually is.
>
You can implement getCallerStackFrame using StackWalker as follows:
walker.walk(s -> s.skip(2).findFirst());
StackWalker::getCallerClass is implemented using StackWalker while it uses a
smaller batch size as it knows it only interests in the top few frames. It’s
smaller footprint since it only gets the Class object.
Mandy
> Ralph
>
>> On May 11, 2016, at 9:14 AM, Ralph Goers <[email protected]> wrote:
>>
>> 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 <[email protected]> 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 <[email protected]> wrote:
>>>>>
>>>>> What does your benchmark call?
>>>>>
>>>>> Mandy
>>>>>
>>>>>> On May 10, 2016, at 9:49 AM, Ralph Goers <[email protected]>
>>>>>> 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 <[email protected]>
>>>>>>> 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 <[email protected]>
>>>>>>>> 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 <[email protected]>
>>>>>>>>> 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
>>>>>>>>>> <[email protected]> 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 <[email protected]>
>>>>>>>>>>> wrote:
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>> On Apr 12, 2016, at 1:34 AM, Rémi Forax <[email protected]> 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
>>>>>>>>>>>> <[email protected]> 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
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>
>>>
>>
>>
>>
>
>
