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