Strange profiling results: definitely non-bottleneck method pops up

Question

I'm profiling a program using sampling profiling in YourKit and JProfiler, and also "manually" (I launch it and press Ctrl-Break several times to get thread dumps).

All three methods give me extremely strange results: some tens of percents of time spent in a 3-line method that does not even do any allocation or synchronization and doesn't have loops etc. Moreover, after I made this method into a NOP and even removed its invocation completely, the observable program performance didn't change at all (although it got a negligible memory leak, since it was a method for freeing a cheap resource).

I'm thinking that this might be because of the constraints that JVM puts on the moments at which a thread's stacktrace may be taken, and it somehow turns out that in my program it is exactly the moments where this method is invoked, although there is absolutely nothing special about it or the context in which it is invoked.

What can be the explanation for this phenomenon? What are the aforementioned constraints? What further measurements can I take to clarify the situation?

Answer 1

To my minds, these results only show that this method gets called a huge number of times. Since its code is quite small, and it may be called as an invocation tree leaf, its impact on your profiling results seems neglectable. However, I had many time that kind of weird results.

Answer 2

When you did the Ctrl-Break several times and got thread dumps, I'm curious what you saw. The call stacks are, to my mind, the most useful information. If your 3-liner is on the stack a large % of time, then you can see why by looking at where it is called from, and where that is called from, etc. Those call sites are just as responsible for the time being spent as the 3-liner is.

If the stack traces seem to make no sense, it may be because they are being delayed until after something completes. If that is so, look up the stack to see what has just completed, because the break could have occurred within that.

Answer 3

Some 3rd party libraries cause the heap dumps to go completely haywire due to unexpected usage patterns, for example if cglib is used, it will mask away the actual cause of the issues and instead show a lot of Proxy objects (if I remember correctly) filling up the VM instead.

So in short, code generation and reflection may cause the stats to go wrong.

Answer 4

You are probably using the wrong tools, techniques and measurements. Reasons for this.

1. Profiler overhead for fine grain methods with high frequency.
2. Resource contention other than monitors (cpu?, io?, memory?)
3. Garbage collection which is not discounted by the above tools and techniques.

You should check out the following articles:

http://williamlouth.wordpress.com/2009/12/24/too-cheap-to-meter-too-fast-to-profile/

http://williamlouth.wordpress.com/2009/11/30/self-optimizing-java-hotspot-detection/