Java 性能分析工具箱

Java性能分析工具箱

作者/Scott Oaks

Oracle资深架构师,专注研究Oracle中间件软件的性能。加入Oracle之前,他曾于Sun Microsystem公司任职多年,在多个技术领域都有建树,包括SunOS的内核、网络程序设计、Windows系统的远程方法调用(RPC)以及OPEN LOOK虚拟窗口管理器。1996年,Scott成为Sun公司的Java布道师,并于2001年加入Sun公司的Java性能小组——从那时起他就一直专注于Java的性能提升。此外,Scott也在O'Reilly出版社出版了多部书籍,包括Java SecurityJava ThreadsJXTA in a NutshellJini in a Nutshell

性能分析器是性能分析师工具箱中最重要的工具。Java 有许多性能分析器,各有优缺点。

性能分析经常需要使用各种工具——特别是那些采样分析器。即便是相同的应用,不同的分析器也能发现其他分析器所发现不了的问题。

几乎所有的 Java 性能分析工具都是用 Java 写的,并以“关联”(attaching)应用的方式进行性能分析——意思是性能分析器开启与目标应用之间的 socket(或其他通信通道)。随后目标应用和性能分析工具交换应用的行为信息。

这意味着,就像调优任何其他 Java 应用一样,你必须注意性能分析工具自身性能的调优。尤其是如果应用很大,需要传递给分析工具的数据非常多,那么分析工具就必须得有足够大的堆内存来处理这些数据。性能分析工具采用并发 GC 算法运行,通常是个不错的主意。在性能分析过程中,不合时宜的 Full GC 停顿会导致性能分析工具缓冲区中的数据溢出。

采样分析器

性能分析有两种模式:数据采样或数据探查。数据采样是性能分析的基本模式,带来的开销最小,这点很重要。性能分析为人诟病的一点就是,对应用进行的测量会改变它的性能。(然而,你必须进行性能分析:还有什么方法能让你知道程序中的猫是否存活?)限制性使用性能分析可以使得测试结果更接近现实模型,即通常情况下应用的表现行为。

不幸的是,采样分析器可能会遇到各种错误。计时器定期触发采样分析器,然后采样分析器检查每个线程并判断正在执行的方法。

下图是采样中最常见的错误。线程交替执行 methodA(见图中的阴影块)和 methodB(见图中的白色块)。如果计时器只在线程执行 methodB 时触发,采样分析器就会报告成,在所有这段时间内线程都在执行 methodB,而实际上更多时间在执行 methodA

{%}

图 交替方法执行

常见的采样错误还不止这一个。减少这类错误的方法是,拉长分析的时间段,同时减少采样间隔。但是减少采样间隔和尽量减小性能分析影响应用的目的相违背,这里需要有平衡。不同的性能分析工具考虑的平衡点也不同,这就是为什么不同的性能分析工具所报告的数据有很大差别的原因。

下面的这个图是 GlassFish 应用服务器启动一个域时所测量出的基本采样分析。图中显示,大块时间(19%)都用在了defineClass1()上,接着是getPackageSourcesInternal()等方法。程序的启动性能是受 JVM 定义类过程的控制的,这并不奇怪。为了加快代码运行速度,必须改进类加载的性能。

{%}

图 基于一个样例的测试

请仔细留意上面的最后一句话:必须改善类加载的性能,而不是改善 defineClass1() 的性能。改善性能的通常设想是,应该先优化性能分析结果中排在最上面的方法。然而,这种做法常常受限。这个案例中的 defineClass1() 是 JDK 的一部分,而且是本地方法(native method),除非改写 JVM,否则不可能改善它的性能。而且,即便能改写 JVM 使得这个方法少花 60% 的时间,但换算成整体性能的改善,也不过 10%——这无异于杯水车薪。

而更常见的情况是,排在性能分析结果顶上的方法只占了整体时间的 2% 或 3%。即便将它所用的时间砍掉一半(通常极为困难),也只会使应用的性能提高 1%。只盯着性能分析结果中最上头的方法,通常并不会让性能提高很多。

相反,你应该在最顶上那些方法所指引的区域中搜寻可优化的地方。GlassFish 性能工程师不会试图让类定义更快,但通常他们会找出如何加速类加载——装载更少的类、并行加载类等。

快速小结

  1. 采样分析器是最常用的分析器。

  2. 因为采样分析器的采样频率相对较低,所以引入的测量失真也较小。

  3. 不同的采样分析器各有千秋,针对不同应用各有所长。

探查分析器

探查分析器相比于采样分析器,侵入性更强,但它们可以给出关于程序内部所发生的更有价值的信息。下图探查的是与采样分析器部分介绍的相同的 GlassFish 域,采用的也是同一个性能分析工具,但这次使用的是探查模式。

{%}

图 一个探查分析器

我们立即就能从这份性能分析结果中看出些问题。首先,现在最“热”的方法成了 getPackageSourcesInternal(),因为占用时间达到了 13%(而不是前个例子中的 4%)。性能分析结果中还有其他几个占用很多时间的方法,也都排到了前头,而 defineClass1() 已经完全消失了。这次工具还报告了每个方法被调用的次数,并且基于这个次数计算出了每次调用的平均时间。

难道这个性能分析结果比采样的好?这取决于能否有办法知道在给定的情况下哪种分析结果更精确。探查分析结果中的调用次数毫无疑问是精确的,而其他信息在判断哪段代码实际花费了更多时间,哪些有更多的优化空间时通常很有帮助。在这个例子中,虽然 ImmutableMap.get() 消耗了 12% 的整体时间,但它被调用了约 470 万次。减少这个方法的总调用次数比加快它的运行速度可以更显著地提升性能。

不过话说回来,探查分析器会在类加载时更改类的字节码(即插入统计调用次数的代码等)。相比采样分析器,探查分析器更可能会将性能偏差引入应用。比如,JVM 会内联小方法使得执行时不会产生方法调用。编译器的这种判断是基于代码的大小,所以有可能使得这段代码不再被内联,这取决于如何探查代码。这会导致探查分析器高估某些方法对整体性能的影响。方法内联只是一个例子,说明编译器会基于代码在内存中的布局而做出决策。一般来讲,加入(更改)的探查代码越多,运行的性能分析结果就越有可能发生变更。

为何 ImmutableMap.get() 只在这里出现,而没在前面的采样分析结果中出现,还有一个很重要的技术原因。Java 的采样分析器只能在线程位于安全点时采集线程样本——基本上只有在 JVM 分配内存的时候。get() 方法可能永远都不会进入安全点,所以可能永远都不会被采样。

在这个例子中,探查分析器和采样分析器给出的结果都指向同样的代码区域:类装载和类解析。实际上,不同分析器的结果可能指向的是完全不同的代码区域。性能分析器可以用来很好地估计,但也仅仅是估计而已:某时某刻它们也会犯错。

快速小结

  1. 探查分析器可以给出更多的应用信息,但相对采样分析器,它对应用的影响更大。

  2. 探查分析器应该仅在小代码区域——一些类和包——中设置使用,以限制对应用性能的影响。

阻塞方法和线程时间线

接下来,我们用另一种探查分析工具(NetBeans 性能分析器)来分析GlassFish 启动。可以看出,此时的执行时间主要被 park()parkNanos() 占用了(相对于占用更少的 read() 方法)。

{%}

图 一个带有阻塞方法的分析器

这些方法(以及类似的阻塞方法)并不消耗 CPU 时间,所以对应用的整体 CPU 使用率没有贡献。没有必要优化它们的执行。应用线程花费 623 秒不是在执行 parkNanos() 方法,而是等待别的事情发生(例如,等待其他线程调用 notify() 方法)。park()read() 方法同样如此。

因为这个原因,大多数分析器不会报告被阻塞的方法,相应的线程也被显示为空闲(这个例子,NetBeans 被设置为显式包括这些方法和其他 Java 级别的方法)。在这个例子中,这是件好事:停止运行的是 Java 线程池中的线程,这些线程用来执行服务器所收到的 servlet(和其他)请求。启动时没有请求发生,所以这些线程被阻塞,等待任务执行。这是正常状态。

在其他情况下,你总是希望能看到那些阻塞调用所花费的时间。线程在 wait()——等待其他线程唤醒——中的用时决定了许多应用的整体执行时间。大多数基于 Java 的性能分析器可以通过设置过滤器和调整其他选项来显示或隐藏这些阻塞方法。

另一方面,审视线程的执行模式而不是分析器给阻塞方法所标记的用时,常常更有价值。下图是 Oracle Solaris Studio 性能分析工具中所显示的线程。

{%}

图 一个线程时间线分析器

每个横向区域都是一个线程(图中有两个线程:线程 1.3 和线程 1.2)。颜色(或不同的灰色)条表示不同方法的执行过程,空白区域表示线程没有在执行。从更高角度来观察,线程 1.2 先是执行了大量代码,然后等待线程 1.3,线程 1.3 之后稍稍等待线程 1.2 执行其他事情,等等。用工具进一步深入这些区域,可以让我们了解线程之间是如何相互影响的。

还可以注意到,有些空白区域没有任何线程在执行。这张图只显示了应用许多线程中的两个,所以这两个线程可能一起在等待其他线程,或者想成正在执行阻塞调用 read()(或类似的)。

快速小结

1.线程被阻塞可能是性能问题,也可能不是,有必要进一步调查它们为何被阻塞。

2.通过正被阻塞的方法调用,或者分析线程的时间线,可以辨认出被阻塞的线程。

本地分析器

本地性能分析工具是指分析 JVM 自身性能的工具。这类工具可以看到 JVM 内部的工作原理,如果应用自身含有本地库,这类工具也能看到本地库代码的内部。所有本地分析工具都可以用来分析 JVM 的 C 代码(以及任何本地库),而有些本地工具则可以用来分析任何 Java 和 C/C++ 应用。

下面的图是不是有点眼熟,它是 Oracle Solaris Studio 分析器分析 GlassFish 启动的结果。这是本地分析器,可以接受 Java 和 C/C++ 代码。(虽然名字中有 Solaris,但它也可以在 Linux 系统上运行。实际上,这些图片都是 Linux OS 上截取的分析结果。不过,如果在 Solaris 的内核结构上运行,这个工具可以展示更多的应用信息。)

{%}

图 一个本地分析器

请注意,第一处与前面不同的是,记录下的应用总 CPU 时间为 25.1 秒,其中 20 秒是 JVM-System 所用。这是 JVM 自身代码的特性:JVM 编译器线程和 GC 线程(加上其他一些辅助线程)。我们可以进一步了解到,实际上,这个例子的所有时间都花费在了编译器上(启动过程确实如此,期间有许多代码需要编译)。这个例子中,GC 线程只花了很少量的时间。

除非是为了深入研究 JVM 自身,否则这些本地信息就足够了。如果我们愿意,可以进一步检查实际的 JVM 功能并优化它们。不过,这个工具所透露出来的关键信息是——基于 Java 的性能分析工具所不能提供的——应用花在 GC 上的时间。在基于 Java 的性能分析工具中,GC 线程的影响几乎看不到。(除非测试所运行的机器是 CPU 受限,否则编译器线程占用大量时间并无大碍:虽然编译线程会消耗大量的 CPU 时间,但只要机器上有更多可用的 CPU,应用自身就不受影响,因为编译是在后台发生。)

一旦检测出本地代码的影响,就可以过滤出来,以便重点考虑实际的启动过程。

{%}

图 一个过滤的本地分析器

采样分析器再次把 defineClass1() 指为了最热的方法,虽然这个方法及其子调用的实际用时——5.041 秒中的 0.67 秒——占了约 11%(不像前面采样分析器报告的那么显著)。分析结果还指出了其他一些需要调查的信息:读取和解压 JAR 文件。由于和类装载有关,这说明我们追踪的方向是正确——但在这个例子中,重要的是看到了实际读取(通过 inflateBytes() 方法)JAR 文件 I/O 只占了极少的百分点。其他工具则不会告诉我们这些信息——部分是因为 Java ZIP 库中的本地代码被当作阻塞调用而被过滤掉了。

无论你用上述哪种性能分析工具,或更好的工具,至关重要的一点就是熟悉它们的特性。性能分析器是查找性能瓶颈最重要的工具,但你必须学会如何使用它们,然后找到需要优化的代码区域,而不是仅仅关注最上头的方法。

快速小结

  1. 本地性能分析器可以提供 JVM 和应用代码内部的信息。

  2. 如果本地性能分析器显示 GC 占用了主要的 CPU 使用时间,优化垃圾收集器就是正确的做法。然而,如果显示编译线程占用了明显的时间,则说明通常对应用性能没什么影响。

 

{%}

《Java性能权威指南》对Java 7和Java 8中影响性能的因素展开了全面深入的介绍,讲解传统上影响应用性能的JVM特征,包括即时编译器、垃圾收集、语言特征等。内容包括:用G1垃圾收集器最大化应用的吞吐量;使用Java飞行记录器查看性能细节,而不必借助专业的分析工具;堆内存与原生内存最佳实践;线程与同步的性能,以及数据库性能最佳实践等。