What is the meaning of 'Unknown: thread_state' when using -Xprof?
I'm trying to find a performance bottleneck in my java application.
Between 30% and 60% of the execution time are always in "Unknown: thread_state":
E.g. (excerpt):
Thread-local ticks:
0.2%35 Blocked (of total)
0.0%2 Class loader
0.0%3 Compilation
38.6% 5521 Unknown: thread_state
Flat profile of 179.25 secs (14367 total ticks): DestroyJavaVM
The summary for all Threads looks even worse, but I guess that's just a bug (I mean the 329.5%):
Global summary of 180.77 seconds:
100.0% 14550 Received ticks
0.3%50 Received GC ticks
6.4%927 Compilation
0.0%6 Class loader
329.5% 47942 Unknown code
I guess "Unknown: thread_state" means the Thread/process is idle, is that true?
It would be equally helpful if someone could point me to detailed documentation; I searched the web and SUN's website, but I couldn't find any hint. Thanks.
Message was edited by:
tzaeschke
Fixed title, clarified text.
The "Unknown: thread_state" happens because the flat profiler in JDK-1.4.2 doesn't stop the threads at each profiling point, but instead just probes each thread in turn and tries to figure out where it is. There's a big switch statement to distinguish a lot of different thread states (in share/vm/runtime/fprofiler.cpp, ThreadProfiler::record_tick, if you have the source code), but if we can't quite figure out where the thread is, then you get an Unknown: thread_state tick recorded for that thread. That said, 39% unknown thread states ticks is higher than we'd expect. Do you know if that thread is doing something that might confuse the flat profiler?
The "Unknown code" ticks can add up to more than 100% because at each profiling point we account one tick to each running thread, so if you have more than one running thread, each one will get a tick recorded for it. The "Global Summary" is a sum across all the threads, so it's relatively easy to get more than ticks accounted to threads than the number of "Received ticks".
I was using java 5:
Java HotSpot(TM) Server VM (build 1.5.0_06-b05, mixed mode)
but I guess that doesn't make a difference.
I think I found the culprit, it seems to be Thread.sleep().
The following code resulted in the printout below:
public class SleepTest {
public static void main(String[] args) throws InterruptedException {
Thread.sleep(10000);
}
}
And here's the output of 'java -Xprof SleepTest':
Flat profile of 10.02 secs (865 total ticks): main
Interpreted + nativeMethod
0.1%1 +0sun.misc.URLClassPath$JarLoader.getJarFile
0.1%1 +0Total interpreted
Thread-local ticks:
99.9%864 Unknown: thread_state
Flat profile of 0.00 secs (1 total ticks): DestroyJavaVM
Thread-local ticks:
100.0%1 Blocked (of total)
Global summary of 10.03 seconds:
100.0%866 Received ticks
99.8%864 Unknown code
Would you say this is a bug? Shall I raise it?
