Why VisualVM Sampler does not provide full information about CPU load (method time execution)?

Question

The problem is: VisualVM sampler shows call tree by time. For some method sampler shows only "Self time" so I can't see what makes this method slow. Here is an example.
How can I increase the depth of profiling?

Answer 1

Unfortunately sampling profilers are rather limited when it comes down to in-depth profiling due to a number of reasons:

• Samplers are limited by the sampling period: For example, VisualVM currently has a minimum sampling period of 20ms. Modern processors can execute several million instructions in that time - certainly more than enough to call several short methods and return from them.

  While an obvious solution would be to decrease the sampling period, this would also increase the impact of the profiler on your application, presenting a nice example of the uncertainty principle.

• Samplers are easily confused by inline code: Both the JVM and any decent compiler will inline trivial and/or frequently-called methods, thus incorporating their code in the code of their caller. Sampling profilers have no way to tell which parts of each method actually belong to it and which belong to inline calls.

  In the case of VisualVM Self time actually includes the execution time of both the method and any inlined code.

• Samplers can get confused by an advanced VM: For example, in modern JVM implementations methods do not have a stable representation. Imagine for example the following method:

  void A() {
      ...
      B();
      ...
  }
  

  When the JVM starts B() is interpreted straight from the bytecode, thus taking quite a bit of time which makes it visible to the sampler. Then, after a while the JVM decides that B() is a good candidate for optimization and compiles it to native code, thus making it much faster. And after yet another while, the JVM might decide to inline the call to B(), incorporating its code in A().

  At best, a sampling profiler will show the cost of those first runs and then the cost of any subsequent runs will be included in the time spent by the caller. This, unfortunately, can confuse an inexperienced developer into underestimating the cost of the method that was inlined.

  At worst, that cost may be assigned to a sibling call, rather than the caller. For example, I am currently profiling an application using VisualVM, where a hotspot seems to be the ArrayList.size() method. In my Java implementation that method is a simple field getter that any JVM should quickly inline. Yet the profiler shows it as a major time consumer, completely ignoring a bunch of nearby HashMap calls that are obviously far more expensive.

The only way to avoid these weaknesses is to use an instrumenting profiler, rather than a sampling one. Instrumenting profilers, such as the one provided by the Profiler tab in VisualVM essentially record each and every method entry and exit in the selected code. Unfortunately, instrumenting profilers have a rather heavy impact on the profiled code:

• They insert their monitoring code around each method, which completely changes the way a method is treated by the JVM. Even simple field getter/setter methods may not be inlined any more due to the extra code, thus skewing any results. The profiler usually tries to account for these changes, but it is not always successful.

• They cause massive slow-downs to the profiled code, which makes them completely unsuitable for monitoring complete applications.

For these reasons instrumenting profilers are mostly suitable for analyzing hotspots that have already been detected using another method such as a sampling profiler. By instrumenting only a selected set of classes and/or methods it is possible to restrict the profiling side-effects to specific parts of an application.