> On May 11, 2016, at 9:24 AM, Ralph Goers <ralph.go...@dslextreme.com> wrote: > > Currently StackWalker has a getCallerClass method, but not a > getCallerStackFrame. Having that method could also solve the problem, but > only if it is efficient enough that it could be called for every log event, > since when we would be calling it we wouldn’t even know if the user required > it. In looking at getCallerClass it isn’t clear to me how fast it actually is. >
You can implement getCallerStackFrame using StackWalker as follows: walker.walk(s -> s.skip(2).findFirst()); StackWalker::getCallerClass is implemented using StackWalker while it uses a smaller batch size as it knows it only interests in the top few frames. It’s smaller footprint since it only gets the Class object. Mandy > Ralph > >> On May 11, 2016, at 9:14 AM, Ralph Goers <ralph.go...@dslextreme.com> wrote: >> >> Yes, we need the StakWalker API for other parts of our code where we need >> the Class so we can determine what ClassLoader to use. For creating a >> LogEvent with location information we primarily need the class name, method >> name and line number. However, the “extended” Throwable also returns the >> name of the jar the class came from and the location of the jar, so in that >> case we would want to use the StackWalker API - so it probably makes more >> sense to always use it. >> >> You are correct that most of the time it would be faster to start from frame >> 0. However, the problem we have with walking the stack from frame 0 is that >> it is possible to have a situation like >> >> Foo::method1—>Logger.log—>BarAppender.append—>Foo::method2 (or even method1 >> again)—>Logger.log >> >> If we start from the top we will believe Foo::method 1 is where we were >> called from, which would be incorrect. If in the Logger.log method we were >> able to capture the current stack frame index from StackWalker we could then >> pass that on through and then when we actually need the StackElement we >> could just ask for index-1, but I don’t see any methods like that, which is >> unfortunate. >> >> Ralph >> >>> On May 11, 2016, at 7:22 AM, Daniel Fuchs <daniel.fu...@oracle.com> wrote: >>> >>> 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 >>>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>>> >>>>>>>>>> >>>>>>>>>> >>>>>>>>> >>>>>>>>> >>>>>>>> >>>>>>>> >>>>>>> >>>>>>> >>>>>> >>>>> >>>>> >>>> >>> >>> >> >> >> > >