Fully featured low overhead profiler for Java EE and Java SE platforms.
Ultimate profiling and monitoring solution for Gradle, Maven, Ant, JUnit and TestNG.
Easy to use performance and memory profiler for .NET framework.

CPU Time in Threads view does not match CPU Time in Summary

Moderators: Vladimir Kondratyev, Anton Katilin

CPU Time in Threads view does not match CPU Time in Summary

Postby vanyatka » Sun Mar 29, 2015 2:05 pm

Hi,

Could anyone suggest why accumulated CPU Time from Threads view does not remotely match the one from Summary page (the latter is much larger) ? E.g. I see the following numbers: sum cpu time from threads panel ~2m 20s and summary page gives me 5m 18s.

Thanks,
vanyatka
 
Posts: 6
Joined: Thu Aug 04, 2011 11:15 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby Anton Katilin » Mon Mar 30, 2015 10:01 am

Hello,

The Summary tab shows the process CPU time as measured with corresponding platform-dependent function. Threads shows CPU time of running threads.

I can offer the following explanation why the process CPU time is larger than the sum of thread CPU times seen in Threads:

1. Threads shows Java threads only, while JVM may have other threads too. For example, those implementing the garbage collector. You application may use native code too, although it's less likely the case.

2. Threads shows live threads and recent dead threads only. If it's a long running application, the oldest dead threads outside the telemetry frame (1 hour by default) will not be shown.

Best regards,
Anton
Anton Katilin
 
Posts: 5574
Joined: Wed Aug 11, 2004 8:37 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby vanyatka » Mon Mar 30, 2015 11:58 am

Anton,

Thanks for your suggestions. Please, see my comments below.

Anton Katilin wrote:The Summary tab shows the process CPU time as measured with corresponding platform-dependent function. Threads shows CPU time of running threads.

Does Threads time also include system time?

Anton Katilin wrote:1. Threads shows Java threads only, while JVM may have other threads too. For example, those implementing the garbage collector. You application may use native code too, although it's less likely the case.

Good point, thanks. However, even with 'Internal threads checkbox enabled' and adding Garbage Collector time (from Summary page) still summary cpu time is much higher. My last observation 8 min vs 3 min (threads + internal + gc time)

Could it be that System Time must also be included? If so, any ideas how it could be measured from within YJP (after all yourkit can measure system time showing the line in cpu telemetry chart)?

Anton Katilin wrote:2. Threads shows live threads and recent dead threads only. If it's a long running application, the oldest dead threads outside the telemetry frame (1 hour by default) will not be shown.

This must not be the case here, since the app I'm running is about several mins long (running from Intellij with Profile command).
vanyatka
 
Posts: 6
Joined: Thu Aug 04, 2011 11:15 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby Anton Katilin » Mon Mar 30, 2015 12:08 pm

Does Threads time also include system time?

Yes.

However, even with 'Internal threads checkbox enabled'

This adds internal, but still Java threads. There are non-Java, fully native threads too.

and adding Garbage Collector time

Thread and process times are measured by the profiler agent using corresponding low level OS functions. The GC time is measured by JVM, and, according to our observations, it is not always correct. Strictly speaking, these numbers come from different sources and cannot be directly matched.

Anyway, could you please provide a snapshot file demonstrating the problem. Could you please send a download link to support@yourkit.com if you cannot share it in the forum.

Could it be that System Time must also be included?

As I wrote, it is included.

If so, any ideas how it could be measured from within YJP (after all yourkit can measure system time showing the line in cpu telemetry chart)?
I'm afraid I don't understand your question.
The kernel time is shown in the CPU usage graph, and is included to the thread times shown in Threads (and if you measure CPU time instead of wall time during CPU profiling: https://www.yourkit.com/docs/java/help/times.jsp ).

This must not be the case here, since the app I'm running is about several mins long (running from Intellij with Profile command).
OK.

Best regards,
Anton
Anton Katilin
 
Posts: 5574
Joined: Wed Aug 11, 2004 8:37 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby vanyatka » Mon Mar 30, 2015 12:39 pm

Anton Katilin wrote:Anyway, could you please provide a snapshot file demonstrating the problem.


Here is Performance Snapshot.
http://goo.gl/yd9Q2p

Thread view + gc gives about 110s while summary cpu time is 184s.

I'm afraid I don't understand your question.
The kernel time is shown in the CPU usage graph, and is included to the thread times shown in Threads (and if you measure CPU time instead of wall time during CPU profiling: https://www.yourkit.com/docs/java/help/times.jsp )


The question was if we can see kernel time of the thread (or all threads) separately from its user time as a number (not a line in chart). I thought it would help to explain the discrepancy, but as you pointed system time is included this becomes not actual for this discussion.

Anyway, if you could have a look at the snapshot and suggest if there is still hope to find "missing" 184 - 109 = 75 sec, I would appreciate.
vanyatka
 
Posts: 6
Joined: Thu Aug 04, 2011 11:15 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby Anton Katilin » Mon Mar 30, 2015 2:46 pm

Thank you for providing the snapshot.

You're profiling on Mac OS X.

Process CPU time on this platform is obtained by summing kernel and user times returned from
Code: Select all
getrusage(RUSAGE_SELF, &usage)


Thread CPU times are obtained by summing kernel and user times returned from
Code: Select all
thread_info(mach_thread, THREAD_BASIC_INFO, (thread_info_t)&tinfo, &tcount)


In both cases the used functions match the functions used in the current JVM implementation for its built-in methods. (The agent explicitly calls OS functions instead of using the Java-provided methods to ensure correct results disregarding the Java version, because historical Java versions had been using incorrect implementations on some platforms.)

So it looks like we're doing it right.

Your snapshot shows there was a significant GC activity. As I earlier wrote, the GC times measured by JVM are not always correct, they are usually smaller than we expect. But we can see the collection counts.

I can suggest to perform the following experiments:
- try running the same on another machine running a different OS, for example, Linux or Windows, and compare the results;
and/or
- try another Java version, e.g. Java 8.
Anton Katilin
 
Posts: 5574
Joined: Wed Aug 11, 2004 8:37 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby vanyatka » Tue Mar 31, 2015 2:58 pm

Anton Katilin wrote:Your snapshot shows there was a significant GC activity. As I earlier wrote, the GC times measured by JVM are not always correct, they are usually smaller than we expect. But we can see the collection counts.

I can suggest to perform the following experiments:
- try running the same on another machine running a different OS, for example, Linux or Windows, and compare the results;
and/or
- try another Java version, e.g. Java 8.


Anton,

Here is another snapshot of the variation of the same program ran on Linux with reduced GC activity.
http://goo.gl/Htuik6
Thread view + GC give ~120s, whereas Summary pages gives 162s.

The app was started with agent loaded during startup time, with 'sampling' mode.

Do I understand correctly that Sum(Own time) < Thread View CPU Time since short methods are not caught by profiler and thread view is asked directly via system call ?
vanyatka
 
Posts: 6
Joined: Thu Aug 04, 2011 11:15 am

Re: CPU Time in Threads view does not match CPU Time in Summ

Postby Anton Katilin » Tue Mar 31, 2015 4:42 pm

Thread view + GC give ~120s, whereas Summary pages gives 162s.

I would still attribute this difference (or at least its major part) to the uncounted CPU activity of the garbage collector and other JVM's non-Java threads.

And there can be some inaccuracy in the results of the system calls for thread and process CPU time measurement. Even if it's true, we have to use the functions the OS provides, since we don't have other/better ones.

The app was started with agent loaded during startup time, with 'sampling' mode.

Do I understand correctly that Sum(Own time) < Thread View CPU Time since short methods are not caught by profiler and thread view is asked directly via system call ?

Interesting question. I bet you're the first one who tries to perform such comparison.

Each sample adds the thread's CPU time difference to the top method in the stack and its parents.

So, if you sum the own times please first turn off the filters to ensure all methods are included:
https://www.yourkit.com/docs/java/help/filters.jsp

I guess that a rounding error may also affect the result.
Anton Katilin
 
Posts: 5574
Joined: Wed Aug 11, 2004 8:37 am


Return to Java Profiler

Who is online

Users browsing this forum: No registered users and 7 guests

cron