Own time is implemented in a bad way (Build 514)

Questions about YourKit Java Profiler
Post Reply

Do You need a list of methods ordered by Own time?

Poll ended at Fri Mar 25, 2005 6:42 pm

Yes
3
60%
No
0
No votes
I am fine, need no Own time feature
2
40%
 
Total votes: 5

falk
Posts: 6
Joined: Fri Oct 08, 2004 9:50 pm

Own time is implemented in a bad way (Build 514)

Post by falk »

As mentioned earlier by some people, a CPU profiler missing this feature is almost useless, cf. http://forums.yourkit.com/viewtopic.php?t=31. Now, with build 514, the feature is announced to be available:
Build 514 (January 24, 2005):

CPU profiling: own method times (e.g. without time spent in subcalls) are shown in 'Invocation tree'
Dear Gentlemen, thank You very much to finally having brought this much awaited feature.
However, I must now be sure, You still haven't understood how a CPU profiler is used (a question: do You at YourKit ever use CPU profiling yoursevles? -- I mean use, not test...)

To be as precise as necessary, I will now list all bugs present in the actual implementation of the feature. Every single item renders the feature useless, hence the entire profiler (cf. discussion above - read: I still cannot buy or recommend your product).

Buglist:
  • Own time appears in the invocation tree. However, Own time is not shown for collapsed items, and uncollapsing all items is an extremely slow and tedious process. An "Uncollapse All" button is missing.

    The Own time of a collapsed items is the sum of all hidden Own times and not zero.

    Once the invocation tree is uncollapsed, one cannot sort according to Own time (one would have to give up the tree structure, of course).

    A method appears multiple times in the tree if called via different chains. It must not, of course, because own time means the sum over ALL invocations.

    Any Own time must still include time spent in all FILTERED methods because THEIR own time does never show up elsewhere.

    Own times of 15ms or 0ms under Windows should be summarized as 'eps' because the Java-on-Windows clock resolution is too small. It may be usefull to have a native clock or combine several profiles into a single, more accurate, one. But this item is a feature, not a bug.
In summary, to fix most of the bugs, You probably have to remove "Own time" from the invocation tree screen and implement a proper "Own time" screen which lists all (unfiltered) methods by "Own time" (second column would be overall time) and pre-sort by "Own time" so that the bottleneck method appears right in the top of the list. The "Own time" screen DOES NOT use a tree, just a plain table. Should be easy to do.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Post by Anton Katilin »

Hello,
a question: do You at YourKit ever use CPU profiling yoursevles? -- I mean use, not test...)
Yes, we actually DO use YourKit Java Profiler for profiling YourKit Java Profiler :) And we ourselves never used to find any application of "own" times, that's why they were not included until now, and that's why you should forgive us this first non-optimal implementation :)
In summary, to fix most of the bugs, You probably have to remove "Own time" from the invocation tree screen and implement a proper "Own time" screen which lists all (unfiltered) methods by "Own time" (second column would be overall time) and pre-sort by "Own time" so that the bottleneck method appears right in the top of the list. The "Own time" screen DOES NOT use a tree, just a plain table. Should be easy to do
I like your idea of the list. We'll add Hot Spots for own times. A question: do you mean there should be the following columns: method name etc., cumulate method own time (sorted by default), cumulate method non-own time (including children)?
falk
Posts: 6
Joined: Fri Oct 08, 2004 9:50 pm

Post by falk »

I like your idea of the list. We'll add Hot Spots for own times. A question: do you mean there should be the following columns: method name etc., cumulate method own time (sorted by default), cumulate method non-own time (including children)?
I think the Hot Spots screen as it is (By time, Alt+1) would be pretty decent as well for Own time. I assume that EVERY (unfiltered and called) method does appear exactly ONCE in this screen. What there now is called "Time" actually could be more precisely called "Invocation Time" (ti). I would propose the following equation to hold true:
  • ti = to + tf + sum_c(ti)
where 'to' would be "Own time" of a method, 'tf' would be invocation time spent in all called filtered methods (which are not listed), and 'sum_c(ti)' would be invocation time spent in all called unfiltered methods (which can be expanded in the current Hot Spots screen and appear elsewhere in the list).

I would now display 'ti' and 'to+tf' as the two columns of the Hot Spots screen. I would display 'to+tf' rather than 'to' alone to make sure that the sum over all 'to+tf' values adds up to the exact overall execution time.
tf is zero if no methods are filtered. Alternatively, one could display three columns: ti, to, and tf (or: ti, 'to+tf', to). Always, the sum of ALL to and tf values in the list add up EXACTLY to the total execution time, which is the largest ti value.

Given this proposal, the only difference between "Hot Spot By [invocation] time" and "Hot Spot By [own] time" is the column by which the list is sorted by default.

I think there is no need for a forth column, 'sum_c(ti)' or 'ti - to - tf', which You may call "cumulate method non-own time". But if, it would go as fourth column only.

The tricky thing in all this is to handle filtered methods correctly.


Note: Your reply was much more friendly than my initial posting. Sorry for that. I was just disappointed...
falk
Posts: 6
Joined: Fri Oct 08, 2004 9:50 pm

Post by falk »

I now tested build 516 with the "By Own time" snapshot. BTW, this build lacks at least one class:

Code: Select all

Build: 516
JDK: 1.4.2_05
VM: Java HotSpot(TM) Client VM
Vendor: Sun Microsystems Inc.
OS: Windows 2000
java.lang.NoClassDefFoundError: com/yourkit/runtime/RequestServer
	at com.yourkit.ui.i.b$2.a(a:64)
	at com.yourkit.ui.d$b.run(a:17)
I still managed to connect locally via the attach to remote app option, and test the Own time feature.

To make it short: Still disappointing.

Feature-wise, please read my other post word-by-word. Then, my point is evident. Currently, no handling of filtered methods. And overall Own times do not add properly to overall invocation time. Also, my suggestion to have all times in a single screen (using 4 Columns incl. Invocation count) was not followed. Sorting does it all.

Implementation-wise, there must be a bug in the current implementation.

In my test, all six methods listed in Own time add up to 18 s, ranging from 2 to 4.5 s. There should be at least a hundred methods, though. The overall invocation time was (all threads together view) 200 s (Meaning, 91% of Own Time is missing...). The by Time Hotspot lists 100's of methods and I did not filter out JDK methods which consume most of the time.

I would acknowledge to receive screen-shots of partial Own-time implementations in the future by private e-mail (falk{at}living-pages.de). To test snapshot by snapshot is a slow procedure. I seem to have difficulties to make my point clear.

As a side remark: Haven't your table columns be resizable? They are not now.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Post by Anton Katilin »

Hello,

Sorry for delayed answer.
I now tested build 516 with the "By Own time" snapshot. BTW, this build lacks at least one class:
This bug is fixed in 518
Feature-wise, please read my other post word-by-word. Then, my point is evident. Currently, no handling of filtered methods. And overall Own times do not add properly to overall invocation time. Also, my suggestion to have all times in a single screen (using 4 Columns incl. Invocation count) was not followed. Sorting does it all.
You want a plain list with all non filtered ever called methods with columns ti, to, tf and if available invocation counts, right?

The thing that is unclear for me, is what is the meaning of tf, i.e. time spent in directly called filtered methods? The question is why and how this information can be helpful? I'm not trying to say it is not helpful, instead I want to understand myself. Maybe you could give some example that demonstrate this metrics. (Or, equivalently, to + tf).
Implementation-wise, there must be a bug in the current implementation.

In my test, all six methods listed in Own time add up to 18 s, ranging from 2 to 4.5 s. There should be at least a hundred methods, though. The overall invocation time was (all threads together view) 200 s (Meaning, 91% of Own Time is missing...). The by Time Hotspot lists 100's of methods and I did not filter out JDK methods which consume most of the time.
If I understand the situation correctly, this happens because currently not all methods are shown, but only those that have 1% or more impact. So the sum of shown own times may be less that 100%
I would acknowledge to receive screen-shots of partial Own-time implementations in the future by private e-mail (falk{at}living-pages.de). To test snapshot by snapshot is a slow procedure. I seem to have difficulties to make my point clear.
Thank you
As a side remark: Haven't your table columns be resizable? They are not now.
They never were resizeable. But we have corresponding request.


Best regards,
Anton
falk
Posts: 6
Joined: Fri Oct 08, 2004 9:50 pm

Post by falk »

You want a plain list with all non filtered ever called methods with columns ti, to, tf and if available invocation counts, right?
Ok, this may be the first source of misunderstanding. What I like to see is a list with every unfiltered method (and a few filtered methods, cf. below) shown exactly once. The (sortable) columns would be:

Code: Select all

1. Tree handle
2. Methods signature
3. ti
4. tf + to (NEW)
5. to (NEW)
6. Invocation count
It would still be possible to open a method to see callees. I would miss this nifty YourKit feature otherwise.
What is the meaning of tf, i.e. time spent in directly called filtered methods? The question is why and how this information can be helpful?
Ok, assume a text-heavy application (like a XML parser). Then, with JDK filtering off, something like 'java.lang.String.<init>()' would show up top in the list (you may actually test your profiler to verify it does indeed deliver this result...).

This is a useful info: Look up the callers which are top in calling this method. Replace 'java.lang.String.<init>()' by 'java.lang.String.substring(int,int)' which is known to be much faster and which can be used instead in many cases. The application may now perform twice as fast. An optimization currently not possible in YourKit (if I do not know the Own Time hot spot).

Now, assume, JDK filtering is on. Then, top callers of 'java.lang.String.<init>()' must appear top of the list when sorting according to column 'to + tf'. Still, I can do the same optimization if I somehow guess that the String constructor is critical. This is so because 'tf' did change due to JDK filtering. A column 'to' alone with JDK filtering on would not be useful in this situation. Hence column 'to+tf'.

It is important to understand the following equation eq.1:

Code: Select all

max ('ti') = sum ('to + tf')      (eq.1)
where max and sum gows aver all (collapsed) rows of the table view, and 'ti' and 'to+tf' are two different table columns. Build an assertion of this equation into your code because, if it fails, profile data will be corrupt...

Equation eq.1. has a number of corrolars: One is that if a calling stack starts with a filtered method (like EventQueue.run() or so), this filtered method must be treated everywhere exactly as if it were unfiltered.
If I understand the situation correctly, this happens because currently not all methods are shown, but only those that have 1% or more impact. So the sum of shown own times may be less that 100%.
I do not think this is it. We know the true own time hot spots of the test we did and YourKit did not show one of them. It just failed and showed only 9% of overall own times. We switched all filters off to get rid off this source of complication. Certainly a bug in YourKit. Assert eq.1 and you will be on the safe side :wink:
Post Reply