Here is the link to the source - https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;a=blob;f=log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/AsyncAppenderLog4j2LocationBenchmark.java;h=c306ac1a0f475d772b6ccb8afa527dc037d7c646;hb=HEAD <https://git-wip-us.apache.org/repos/asf?p=logging-log4j2.git;a=blob;f=log4j-perf/src/main/java/org/apache/logging/log4j/perf/jmh/AsyncAppenderLog4j2LocationBenchmark.java;h=c306ac1a0f475d772b6ccb8afa527dc037d7c646;hb=HEAD>. You can check out all of Log4j 2 by doing
git clone http://git-wip-us.apache.org/repos/asf/logging-log4j2.git Ralph > On May 10, 2016, at 7:26 PM, Mandy Chung <mandy.ch...@oracle.com> wrote: > > >> On May 10, 2016, at 5:17 PM, Ralph Goers <ralph.go...@dslextreme.com> wrote: >> >> OK - I try that. My earlier comparison had shown that StackWalker was much >> faster but since walking the Throwable is so much slower I’m now wondering >> how much better than Java 7 & 8 it will be. >> >> Any idea why walking the Throwable is so much slower? >> > > No idea yet. Can you share your benchmark so that we can understand what you > measure? > > Mandy > >> Ralph >> >>> On May 10, 2016, at 5:01 PM, Mandy Chung <mandy.ch...@oracle.com> wrote: >>> >>> 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 >>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>>> >>>>>>> >>>>>>> >>>>>> >>>>> >>>>> >>>> >>> >>> >> >> > >
