> 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.
I get the math but a caller should never have a shorter inclusive time than a callee. The problem example has 2 inclusive times for (lacking the full signature) the same method. Since we have to consider this as a nested method call of the same method then the shorter time should be discarded to get the accurate inclusive time. Right now the second action method is getting counted twice in the aggregation. > Using full signatures would eliminate this particular > confusion, at the > expense of more cluttered output. Probably best for > a separate script. If the method signature is moved to the last column it's not so bad but I know what you mean. I wish there was a maximum width option for a printf format string. > It won't solve similar confusion for recursive > functions. Not just recursive, anything reentrant at all. The fix is to count method reentrance using an associative array with the full method sig as the key and only add to the inclusive aggregation when we return to a depth of zero. The only problem is I can't get this working without getting drops, even if I could get it working the overhead probably wouldn't be worth it. When you compare the frequency of method overloading to reentrance in the Java APIs I think it's worth dealing with the overloading but just give a warning for the rest. > 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. It's all yours, do whatever you want with it (any license). -- This message posted from opensolaris.org _______________________________________________ dtrace-discuss mailing list [email protected]
