Why does park/unpark have 60% CPU usage?

Question

Recently we started stress testing our application (an XMPP based chat server) using YJP 11.0.9. During our test we noticed following strange behavior.

1. Sampling shows sun.misc.Unsafe.unpark(Object) took 60% of CPU.
2. For the same app Tracing shows that LockSupport.park(Object) took 52% of CPU.

I did multiple tests to confirm results and every time I got similar results.

I am unable to understand why unpark should take 60% time and why tracing shows exactly opposite results.

Can someone help me understand these results. Am I missing something here?

Environment:

java -version
java version "1.6.0_31"
Java(TM) SE Runtime Environment (build 1.6.0_31-b04)
Java HotSpot(TM) 64-Bit Server VM (build 20.6-b01, mixed mode)

Usage

It could take that much if calling unpark is pretty much the only thing the thread ever does. What do you mean that "tracing shows exactly opposite results"? Does tracing perhaps measure time spent within a method? park is a blocking method, so no wonder time is spent within it. – Yoshieyoshiko

@MarkoTopolnik thread does other things as well. Basically Its producer / consumer problem. Produce produce tasks and submit it in the Queue and notify waiting consumers. Consumer acts on task and if no tasks available than park itself. – Usage

The thread that calls unpark is not the thread being unparked. That thread, in turn, may really only be doing little work besides unparking the appropriate consumer threads. As for the CPU time of park, it is a) tough to measure due to blocking and b) irrelevant since it will be an insignificant fraction of the actual time spent in the parked state. – Yoshieyoshiko

@MarkoTopolnik in Sampling test 60% of CPU spent on doing unpark consumer. While in Tracing test 52% of CPU spent on doing park from consumer thread. – Usage

@MarkoTopolnik As I said producer does CPU activity like xml parsing which should be significantly higher than doing unpark. – Usage

You are stacking the parking time done by one thread against the unparking time done by other thread. Those two numbers are in principle meaningless to compare, even ignoring the probable fact that sampling correctly doesn't measure time spent blocking, while "tracing" does. – Yoshieyoshiko

@MarkoTopolnik My main confusion is given there is lots of other CPU activity going on why should unpark comes in hot spots during sampling while at the same time during tracing unpark is no were in the list but now park tops the hot spots list. – Usage

I'd focus my attention on unpark only. park cannot be a problem. Also, I don't know what exactly you mean by "during sampling" and "during tracing". JVisualVM, for example, has a sampling profiler, it shows hot spots while running. They are largely irrelevant. The really relevant stuff is shown after taking a snapshot and analyzing each thread's call stacks. – Yoshieyoshiko

@MarkoTopolnik In YJP there are two ways for CPU profiling - Sampling & Tracing. More details are at yourkit.com/docs/80/help/cpu_intro.jsp – Usage

Tracing would be the same as just "Profiling" in VisualVM. Note that "tracing" just compares method entry timestamp with method exit timestamp. It doesn't know how much of that time was spent actually executing on the CPU, and how much was just blocking. – Yoshieyoshiko

Answer 1

High CPU time of Unsafe.unpark is a sign of excessive Context Switching. Here is an article to get the idea of how expensive is a context switch:

How long does it take to make a context switch?

The easiest option to find out CS count on Linux is run vmstat <seconds>.

Once high CS is confirmed (e.g. more 10K switches per core/per second) you take the offending thread (you can sort threads in YJP by their CPU time) and run strace -p <pid> -c to find out the cause of switching, e.g. thread is reading from socket in small pieces and get's switched off, in which case increasing socket buffer might help.

Libbey

Answer 2

With certain low level blocking commands like read/write/park/lock the "CPU" time is over estimated as it assumes it is consuming CPU when actually the operation is blocking. The fact unpark/park are both high does suggest you have a problem, but I suspect you should take the lower of the two percentages as an estimate.

Sorbose

Answer 3

I learned the hard way that you can also have high CPU usage % on LockSupport.parkNanos() if you call multiple times the method and your sleep argument is in the order of nanoseconds:

while(true){
  // code logic
  LockSupport.parkNanos(100);
}

Simply changing to microseconds helped me resolve my issue. I also tried it on my local machine and was able to reproduce the high CPU usage %, and saw it drastically improve after going for microseconds.

Clamshell