I should mention - if you actually want to run the test you should checkout the source and then build it. Just run mvn clean install. Once you have done that the log4j-perf module has all the performance tests. Most of the tests have the command line you can use to run the test.
Ralph > On May 10, 2016, at 7:34 PM, Ralph Goers <ralph.go...@dslextreme.com> wrote: > > 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 > <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 >> <mailto:mandy.ch...@oracle.com>> wrote: >> >> >>> On May 10, 2016, at 5:17 PM, Ralph Goers <ralph.go...@dslextreme.com >>> <mailto: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 >>>> <mailto: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 >>>>> <mailto: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 >>>>>> <mailto: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 >>>>>>> <mailto: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 >>>>>>>> <mailto: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 >>>>>>>>> <mailto: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 >>>>>>>>>> <mailto: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 <mailto: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 >>>>>>>>>>>> <mailto:mandy.ch...@oracle.com>> wrote: >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>>> On Apr 12, 2016, at 1:34 AM, Rémi Forax <fo...@univ-mlv.fr >>>>>>>>>>>>> <mailto: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 <mailto:mandy.ch...@oracle.com>> a écrit : >>>>>>>>>>>>>> Webrev at: >>>>>>>>>>>>>> http://cr.openjdk.java.net/~mchung/jdk9/webrevs/8153912/webrev.00/index.html >>>>>>>>>>>>>> >>>>>>>>>>>>>> <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 >>>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>>> >>>>>>> >>>>>> >>>>>> >>>>> >>>> >>>> >>> >>> >> >> >
