G'Day,
On Mon, Feb 04, 2008 at 11:40:04PM -0800, Matthieu Chase Heimer wrote:
> If there is a better place to report this please let me know.
This is best.
> When adding the inclusive method execution time it is required to use the
> complete method signature. The problem is likely to be present in other
> scripts but I've verified it in the Java related scripts that calculate
> inclusive and exclusive execution times. The problem is caused by tracing
> overloaded methods, a fairly common occurrence in Java.
>
>
> Given the following Java program:
>
> public class Problem {
>
> public static void main(String[] args) {
> action(42);
> try{ Thread.sleep(2000); } catch(Exception e) {}
> }
>
> public static void action(int x) {
> action("duke");
> try{ Thread.sleep(2000); } catch(Exception e) {}
> }
>
> public static void action(String s) {
> try{ Thread.sleep(6000); } catch(Exception e) {}
> }
>
> }
>
> The relevant output of j_calltime.d would be:
> Top 10 inclusive method elapsed times (us),
> PID TYPE NAME TOTAL
> 1346 method sun/misc/Launcher.<init> 1526459
> 1346 method sun/misc/Launcher.<clinit> 1527443
> 1346 method java/lang/ClassLoader.initSystemClassLoader 1530208
> 1346 method java/lang/ClassLoader.getSystemClassLoader 1530537
> 1346 method java/net/URL.<init> 1558066
> 1346 method java/lang/ClassLoader.loadClass 3195875
> 1346 method java/security/AccessController.doPrivileged 3578758
> 1346 method java/lang/Thread.sleep 9942087
> 1346 method Problem.main 9955080
> 1346 method Problem.action 14025628
>
> Notice how action is listed as having a longer execution time than it's
> caller.
Yes - it is expected to have a longer *inclusive* elapsed time. This is
one of a number of reasons why understanding inclusive times is difficult.
Note that the inclusive time reports delibrately don't include a "Total"
line - since that would add to the confusion.
Consider:
# ./j_flow.d | grep Problem
0 140987 5335249357945 -> Problem.main
0 140987 5335249357955 -> Problem.action
0 140987 5335249357965 -> Problem.action
0 140987 5335255360139 <- Problem.action
0 140987 5335257370085 <- Problem.action
1 140987 5335259380101 <- Problem.main
On line 2 Problem.action(int) begins. Inclusive time will include everything
it calls, which is the 2000 ms sleep it calls directly and the 6000 ms
sleep a child method calls. Tally 8000 ms for "Problem.action".
On line 3 Problem.action(string) begins. It's inclusive time is 6000 ms.
Add that to "Problem.action" and we reach 14000 ms, which is correct.
Using full signatures would eliminate this particular confusion, at the
expense of more cluttered output. Probably best for a seperate script.
It won't solve similar confusion for recursive functions.
I should update Notes/ALLinclusive_notes.txt and explain this in more
detail. :) It might be handy to include your example in the notes file,
if you don't mind, since it presents a good case.
cheers,
Brendan
--
Brendan
[CA, USA]
_______________________________________________
dtrace-discuss mailing list
[email protected]
