StackOverflow2013

Note that there are some explanatory texts on larger screens.

plurals

POJava VisualVM giving bizarre results for CPU profiling - Has anyone else run into this?
text
Body
copied!<p>I have written this small (and brutally inefficient) class and wanted to profile it using the Java VisualVM.</p> <pre><code>public class Test { public static void main(String[] args) throws IOException { BufferedReader br = new BufferedReader(new InputStreamReader(System.in)); br.readLine(); int n = Integer.parseInt(args[0]); int fib = fib(n); System.out.println(fib); } private static int fib(int n) { if (n < 2) { return n; } return fib(n-1)+fib(n-2); } } </code></pre> <p>The results are bizarre. The results are completely dominated by calls to ConnectionHandler.run().</p> <p>(98.2%) sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run()<br> (1.7%) java.lang.Thread.join(long) <br> (0%) java.lang.String.equals(Object) <br> etc...</p> <p>There are probably around one hundred methods profiled and not one of them is fib(int)!</p> <p>It is inconceivable that my program is actually spending all of its time in these methods. They appear to be the profiler connecting to my jvm and doing its thing.</p> <p>What am I doing wrong?</p> <p><strong>Edited for clarity:</strong> If you pass in 45 for the n this application runs for 20 well profiled seconds. The program I was profiling originally (not a fibonacci calculator) pegs all four cores on my cpu at 100% and I was doing profiling runs lasting up to 5 minutes. These had the same results and methods from my application did not appear high up on the hot spot method list.</p> <p>It varies from run to run but ConnectionHandler.run() is always at the top and usually accounts for ~99% of the profile time.</p> <p><strong>Second Edit:</strong> I have tried using the sampler and I am now getting results that are consistent with what JProfiler is producing. The downside to this is that I don't get the stack trace information that comes with profiling. But for my immediate needs this is excellent.</p> <p>Something I have discovered while playing around is that VisualVM counts wall-clock time for method calls while profiling them. </p> <p>In my specific case my application has a main thread which launches worker threads and immediately blocks waiting for a message on a queue.</p> <p>This means that the blocking method will appear to take up almost all of the time on the profiler despite the fact that it is not this method that is eating up my CPU.</p> <p>I would expect that the same is true of the sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run() method which does its job nicely - but when it terminates it becomes one of the longest running methods in my application - <em>repeatedly</em>.</p>

Querying!

Guidance

An individual column

Larger individual text columns get their own page to allow for proper reading.

SQuiL has stopped working due to an internal error.

If you are curious you may find further information in the browser console, which is accessible through the devtools (F12).

Reload