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
