Mac OS 10.10 JDK8: Lots of problems on CPU tab

Questions about YourKit Java Profiler
Post Reply
nwong
Posts: 4
Joined: Tue Nov 18, 2014 7:49 pm

Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by nwong »

I'm debugging a tomcat web application and I'm looking for execution times for specific paths depending on the race condition winner. So it's very important for me to see the walltime differences between two threads based on who won mutex contention.

Often, it seems like clicking "Show Selected Thread Only" does absolutely nothing. It works maybe 1 out of a 100 times. I have to actually type the name of the thread in the upper left to get it to filter down to just the one thread.

Often, it seems like filtering by my classes does not work at all. Threads will not show any detail at all, or just some detail of the tomcat server. This is sometimes improved by turning off all filtering, but my classpaths are not in the filters. Sometimes it gets better after turning filtering off and on again.

Walltime seems completely broken if I understand correctly how it works. I did a simple thread that just sleeps for 2000 milliseconds, but walltime is showing the thread took only 80 seconds.

Environment:
Application being debugged: Spring webapp on Tomcat 7 on JDK 1.7.0_u71
Mac OS X 10.10.1, YourKit Java Profiler 2014 build 14112 on JDK 1.8.0_u25

I'm trying this all now on Ubuntu to see if it is any better or if I'm just using the tool improperly.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by Anton Katilin »

Hi,
Often, it seems like clicking "Show Selected Thread Only" does absolutely nothing. It works maybe 1 out of a 100 times. I have to actually type the name of the thread in the upper left to get it to filter down to just the one thread.
Please ensure you click a time point at which that thread has a status. Otherwise it will legally show you empty thread list with words "The selected thread was not running at this point".
If this does not help could you please provide a screenshot demonstrating the problem.
Often, it seems like filtering by my classes does not work at all. Threads will not show any detail at all, or just some detail of the tomcat server. This is sometimes improved by turning off all filtering, but my classpaths are not in the filters. Sometimes it gets better after turning filtering off and on again.
Could you please provide more detail on the context. Do you mean the "Stack traces" tab in "Threads"? If yes please note it has "Details" control in the right upper corner which may may switch to show full stacks even when the filters are applied.
Walltime seems completely broken if I understand correctly how it works. I did a simple thread that just sleeps for 2000 milliseconds, but walltime is showing the thread took only 80 seconds.
Where do you see these results? Do you use CPU usage estimation, or CPU sampling, or CPU tracing? If the first, please note it works with CPU times, not wall times. Also, it is less accurate than real CPU profiling due to rare telemetry samples it is based on.

Best regards,
Anton
nwong
Posts: 4
Joined: Tue Nov 18, 2014 7:49 pm

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by nwong »

I threw together a test application to show the Time and Samples problems.

http://i.imgur.com/aa0OEEb.png

Tracing Mode with the following configuration:

walltime=*

adaptive=true
adaptive_min_method_invocation_count=20000
adaptive_max_average_method_time_ns=1000
adaptive_min_method_time_percent=0.1

Code:
public String sayHelloWorld(final String name) {
try {
Thread.sleep(2000);
} catch (InterruptedException e) {
e.printStackTrace();
}
return "Hello World, " + name + "!";
}

JMeter was setup to do 20 threads once, results are:

Results from JMeter:
Number of Samples: 20
Average response time: 2014ms

Screen shot shows 35ms, not 2000ms+.
Screen shot shows 18 samples, not 20.

This code is significantly less complex than the application we were debugging, which I can't post a screenshot of. In this case, the "Selected Thread Only" seems to be working properly.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by Anton Katilin »

Hello,
I threw together a test application to show the Time and Samples problems.
As I suspected, you are using the CPU usage estimation feature:
http://www.yourkit.com/docs/java/help/c ... mation.jsp

It has nothing to do with sampling or tracing settings. They are for sampling and tracing respectively:
http://www.yourkit.com/docs/java/help/cpu_intro.jsp

These are different features.

As I wrote, CPU usage estimation works with CPU times - hence the word "CPU" in the feature name.

To measure wall time you need to perform CPU sampling or CPU tracing:
http://www.yourkit.com/docs/java/help/cpu_intro.jsp

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

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by Anton Katilin »

P.S.

Please pay attention that on your screenshot the Sleeping status for those threads is indicated (see the color legend in the right upper corner).
nwong
Posts: 4
Joined: Tue Nov 18, 2014 7:49 pm

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by nwong »

Ahh ok, that makes more sense. I figured I was just using it incorrectly. However, why is the invocation count 18 when I clearly sent 20 requests? Does that mean only 18 invocations used a measurable amount of CPU time?

As far as all the other problems are concerned, I'll try to reproduce the "show this thread only" issues with a non-sensitive application, but the application that caused this behavior is seriously complex with quite a few bits of AOP code and multi-threaded code.
nwong
Posts: 4
Joined: Tue Nov 18, 2014 7:49 pm

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by nwong »

I was able to get the information I needed by saving the recording and using the CPU tab, Call Tree by Thread with a focus on my code.

http://imgur.com/fyXjRHM

The invocation counts and telemetry seem to be all spot on in this view. I'm going to try with the more complicated application today to see what results I can get with a real app.
Anton Katilin
Posts: 6172
Joined: Wed Aug 11, 2004 8:37 am

Re: Mac OS 10.10 JDK8: Lots of problems on CPU tab

Post by Anton Katilin »

Hello nwong,
However, why is the invocation count 18 when I clearly sent 20 requests? Does that mean only 18 invocations used a measurable amount of CPU time?
Yes, it's possible. sleep() by itself does not consume much CPU, so the measured CPU times must come from other methods. Also, operating system measures CPU time with some granularity.

Also please note that CPU usage estimation is based on telemetry samples. Sampling is a stochastic approach by its nature. The telemetry samples are obtained approximately each second by default. There is a probability that a sample is taken at a moment the method you are looking for is not running. You can play with the startup option "telemetryperiod" to specify a smaller interval between samples:
http://www.yourkit.com/docs/java/help/s ... ptions.jsp

Anyway, CPU profiling, either tracing or sampling, provide much more accurate results. By the way, CPU sampling is similar to CPU usage estimation because both use sampling approach. The difference is that CPU sampling's period is much higher (20 ms vs 1000 ms of telemetry) thus providing better accuracy, and that it CPU sampling allows wall time measurement which CPU usage estimation always counts CPU times.

Best regards,
Anton
Post Reply