Java VisualVM 给出奇怪的 CPU 分析结果 - 有其他人遇到过这个吗?
我编写了这个小(而且效率极低)的类,并希望使用 Java VisualVM 对其进行分析。
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);
}
}
结果很奇怪。结果完全由对 ConnectionHandler.run() 的调用决定。
(98.2%) sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run()
(1.7%) java.lang.Thread.join(long)
(0%) java.lang.String.equals(Object)
等等......
可能有大约一百种方法被分析,但没有一个是 fib(int)!
令人难以置信的是,我的程序实际上将所有时间都花在了这些方法上。它们似乎是连接到我的 jvm 并执行其操作的分析器。
我做错了什么?
为清楚起见进行了编辑:如果您为 n 传递 45,则此应用程序将运行 20 秒。我最初分析的程序(不是斐波那契计算器)将我的 cpu 上的所有四个核心固定为 100%,并且我进行的分析运行持续长达 5 分钟。这些具有相同的结果,并且我的应用程序中的方法并未出现在热点方法列表中的较高位置。
它因运行而异,但 ConnectionHandler.run() 始终位于顶部,通常占配置文件时间的约 99%。
第二次编辑:我尝试使用采样器,现在得到的结果与 JProfiler 生成的结果一致。这样做的缺点是我无法获得分析附带的堆栈跟踪信息。但对于我的即时需求来说,这非常好。
我在尝试过程中发现,VisualVM 在分析方法调用时会计算方法调用的挂钟时间。
在我的具体情况下,我的应用程序有一个主线程,它启动工作线程并立即阻止等待队列上的消息。
这意味着阻塞方法似乎会占用分析器上的几乎所有时间,尽管事实上并不是该方法消耗了我的 CPU。
我希望 sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run() 方法也是如此,它很好地完成了它的工作 - 但是当它终止时,它成为我的应用程序中运行时间最长的方法之一 - 反复。
I have written this small (and brutally inefficient) class and wanted to profile it using the Java VisualVM.
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);
}
}
The results are bizarre. The results are completely dominated by calls to ConnectionHandler.run().
(98.2%) sun.rmi.transport.tcp.TCPTransport$ConnectionHandler.run()
(1.7%) java.lang.Thread.join(long)
(0%) java.lang.String.equals(Object)
etc...
There are probably around one hundred methods profiled and not one of them is fib(int)!
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.
What am I doing wrong?
Edited for clarity: 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.
It varies from run to run but ConnectionHandler.run() is always at the top and usually accounts for ~99% of the profile time.
Second Edit: 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.
Something I have discovered while playing around is that VisualVM counts wall-clock time for method calls while profiling them.
In my specific case my application has a main thread which launches worker threads and immediately blocks waiting for a message on a queue.
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.
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 - repeatedly.
如果你对这篇内容有疑问,欢迎到本站社区发帖提问 参与讨论,获取更多帮助,或者扫码二维码加入 Web 技术交流群。
绑定邮箱获取回复消息
由于您还没有绑定你的真实邮箱,如果其他用户或者作者回复了您的评论,将不能在第一时间通知您!
发布评论
评论(4)
我认为这根本不是不可想象的。您有一个应用程序,其中“有效负载”相当小(尽管这当然取决于
n
的值),并且您必须接受所需的额外工作(连接探查器并转移所有传递给它的信息)将淹没该有效负载。这不是我首先要分析的应用程序类型,因为很明显,无论如何都会在
fib
上花费大量时间(对于n< 的非平凡值) /code>),将其标记为明显的优化目标。
我更倾向于将探查器用于更重要的应用程序,其中:
如果您确实想测试该代码,您可能需要通过(例如)将:替换
为:
我会告诉您一个需要注意的事情来 提高其效果不过。我不知道任何特定 JVM 的内部结构,但使用参数减少速度较慢的递归方法通常是一个坏主意,这会导致堆栈空间很快耗尽。
我的意思是,二分搜索是一个很好的候选者,因为它会删除每个递归级别的剩余搜索空间的一半(因此 10 亿个项目的搜索空间只有 30 个级别)。
另一方面,对数字 1,000,000,000 使用斐波那契数列的递归将需要大约十亿级,并且大多数堆栈都很难包含它。
尾端递归优化可以避免该问题,但您需要小心,以防优化未完成。
I don't think that's inconceivable at all. You have an application where the "payload" is fairly minuscule (though that of course depends on the value of
n
), and you have to accept that the extra effort required (to connect the profiler and shift all the information across to it) will swamp that payload.This is not the sort of application I would be profiling in the first place since it's pretty obvious that the vast amount of time would be spent in
fib
anyway (for non-trivial values ofn
), marking that as an obvious target for optimisation.I would be more inclined to use the profiler for more substantial applications where:
If you really want to test that code, you probably need to bump up its effect by (for example) replacing:
with:
I'll tell you one thing to watch out for though. I don't know the internals of any particular JVM but using a recursive method where the reduction of the argument is slow is usually a bad idea, one that leads to stack space being exhausted pretty quickly.
By that, I mean a binary search is a good candidate since it removes half the remaining search space with each recursion level (so that a search space of a billion items is only 30 levels).
On the other hand, using recursion for a Fibonacci sequence on the number 1,000,000,000 would take about a billion levels and most stacks would have a hard time containing that.
Tail end recursion optimisation may avoid that problem but you need to be careful in case that optimisation isn't done.
jvisualvm 分析可能会在加载字节码时将其编织到类中。由于您的程序只有一个类,并且在 jvisualvm 到达现场时它已经初始化,我认为它无法被检测。
将您的 fib 方法移至另一个类并再次尝试分析。您可以添加一个 jvm 选项“-verbose:class”,以在 jvisualvm 中启用 cpu 分析之前仔细检查该类是否未加载。
编辑:感谢 JB 的评论。忘记我的类加载废话吧。我的直觉是 fib 方法与 main 方法耦合得太紧密,因此它实际上是当前正在执行的字节码。
jvisualvm profiling probably weaves bytecode into classes as they are loaded. Since your program has just one class and it is already initialized by the time jvisualvm arrives on the scene, I would suppose it cannot be instrumented.
Move your fib method into another class and try profiling again. You might add a jvm option "-verbose:class" to double check that the class isn't loaded before you enable cpu profiling in jvisualvm.
Edit: Thanks JB for the comment. Forget my classloading hogwash. My intuition is that the fib method is too tightly coupled to the main method, so it is effectively bytecode currently being executed.
根据 Ron 的回答,可以通过在启动后立即停止 JVM,然后激活分析器,最后继续执行(按 Enter 键)来改善结果。这很粗糙。
Based on Ron's answer was able to improve the result by stopping the JVM right after the start, then activated the profiler, and finally after that continue the excetion (by pressing enter). It's crude.
我的猜测是,您向 fib 传递的值太小,并且程序运行的时间不够长,无法注册。为了在分析(或基准测试)时获得几乎所有内容的有意义的数据,通常需要至少几秒钟的时间。
My guess is that you are passing too small a value to fib, and the program just doesn't run long enough to register. To get meaningful data for nearly anything when profiling (or bench-marking) you generally need an elapsed time of at least a few seconds.