OK, I will try to give that a try over the next few days and try to see how
much overhead it incurs.
Ralph
> On May 11, 2016, at 9:43 AM, Mandy Chung <mandy.ch...@oracle.com> wrote:
>
>
>> On May 11, 2016, at 9:24 AM, Ralph Goers <ralph.go...@dslextreme.com> 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 <ralph.go...@dslextreme.com> 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 <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
>>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>>
>>>>>>>>>
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>
>>>>
>>>
>>>
>>>
>>
>>
>
>
