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
>>>>>>>>>
>>>>>>>>
>>>>>>>>
>>>>>>>
>>>>>>>
>>>>>>
>>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>
>>
>>
>
