CreateDirectories()有什么问题? - CPU性能分析指南

阅读其他语言: English Español 한국어 Português

有时你的应用程序能正常运行，但你希望通过提高吞吐量或减少延迟来提升性能。 或者，你可能只是想了解代码在运行时的行为，确定热点位置， 或者弄清楚框架底层是如何运作的。

这就是剖析器大显身手的地方。它们提供了对任意大型执行片段的鸟瞰视角， 帮助你从宏观上发现问题。

许多人认为，只要他们不编写高负载应用程序，就没有必要学习如何进行剖析。 在下面的例子中，我们将看到即使处理非常简单的应用，我们也能从剖析中获益。

示例应用

假设我们有以下 程序：

import java.io.IOException;
import java.nio.file.Files;
import java.nio.file.Path;
import java.nio.file.Paths;
import java.util.*;
import java.util.concurrent.TimeUnit;

public class CountEvents {

    public static int update(Deque<Long> events, long nanos, long interval) {
        events.add(nanos);
        events.removeIf(aTime -> aTime < nanos - interval);
        return events.size();
    }

    public static void main(String[] args) throws IOException {
        long start = System.nanoTime();
        int total = 100_000;
        long interval = TimeUnit.MILLISECONDS.toNanos(100);
        int[] count = new int[total];

        Deque<Long> collection = new ArrayDeque<>();
        for (int counter = 0; counter < count.length; counter++) {
            count[counter] = update(collection, System.nanoTime(), interval);
            Path p = Paths.get("./a/b");
            Files.createDirectories(p);
        }
        long spent = System.nanoTime() - start;

        //noinspection OptionalGetWithoutIsPresent
        System.out.println("Average count: " + (int) (Arrays.stream(count).average().getAsDouble()) + " op");
        System.out.println("Spent time: " + TimeUnit.NANOSECONDS.toMillis(spent) + " ms");
    }
}

该程序反复尝试使用NIO2的 createDirectories() 方法在文件系统中创建路径。然后我们使用一个简陋的基准测试来衡量吞吐量。

每次任务运行时，基准逻辑都会将当前时间戳存储到一个集合中，并移除所有指向时间早于当前时间减去某个间隔的时间戳。 这样，只需查询集合就可以知道这个时间间隔内发生了多少事件。这个基准测试旨在帮助我们评估 createDirectories() 方法的性能。

当我们运行程序时，发现数字低得可疑：

Average count: 6623 op
Spent time: 1462 ms

让我们对其进行剖析，看看哪里出了问题。

获取快照

Info icon

我使用的是IntelliJ Profiler，因为它与IDE紧密集成，省去了设置的所有麻烦。 如果你没有IntelliJ IDEA Ultimate，你可以使用另一个剖析器。在这种情况下，步骤可能会略有不同。

首先，我们需要收集剖析数据，也称为“快照”。 在这个阶段，剖析器会与程序一起运行，收集其活动信息。 剖析器使用不同的技术来实现这一点，比如在方法入口和出口处插入检测代码。 IntelliJ Profiler则是通过定期从应用程序的所有线程中收集堆栈信息来实现的。

要在IntelliJ IDEA中附加剖析器，请选择你通常用来运行应用程序的运行配置，然后从菜单中选择分析 (Profile)。

运行小部件中的菜单显示了剖析选项 运行小部件中的菜单显示了剖析选项

当应用程序运行完毕后，会出现一个弹出窗口，提示我们打开快照。 如果我们不小心关闭了弹出窗口，快照仍然可以在分析器 (Profiler) 工具窗口中找到。

让我们打开报告，看看里面有什么。

分析快照

打开报告后，我们首先看到的是火焰图。 这基本上是对所有采样堆栈的总结。 剖析器收集到具有相同堆栈的样本越多，这个堆栈在火焰图上的宽度就越大。 因此，帧的宽度大致相当于在此状态下所花费时间的比例。

打开快照后显示的火焰图 打开快照后显示的火焰图

令我们惊讶的是， createDirectory() 方法并没有占用大部分执行时间。 我们自制的基准测试大约消耗了相同的时间！

此外，如果观察上面的帧，我们会发现这主要是因为 removeIf() 方法， 它几乎占用了调用者 update() 方法的所有时间。

在火焰图上指向removeIf()帧 在火焰图上指向removeIf()帧

显然，这需要进一步探究。

Tip icon

除了传统的工具如火焰图， IntelliJ Profiler还在编辑器中直接提供性能提示，非常适合快速参考和简单场景：

编辑器行号边距中的剖析器提示 编辑器行号边距中的剖析器提示

优化基准测试

看来负责从队列中移除事件的代码正在做额外的工作。

由于我们使用的是有序集合，并且事件按时间顺序添加， 我们可以确定所有待移除的元素总是位于队列的头部。 如果我们用一个循环替换 removeIf() ，该循环一旦开始迭代它不会移除的事件就会中断，那么我们有可能提高性能：

// events.removeIf(aTime -> aTime < nanos - interval);
while (events.peekFirst() < nanos - interval) {
    events.removeFirst();
}

让我们修改代码，再次对应用程序进行剖析并查看结果：

指向新快照中的createDirectories()，显示为'所有中的96.49%' 指向新快照中的createDirectories()，显示为'所有中的96.49%'

现在基准逻辑的开销已经降到最低，应该如此， 而 createDirectories() 帧现在占据了整个执行时间的大约95%。

改进也在控制台输出中可见：

Average count: 14788 op
Spent time: 639 ms

本地剖析

解决了基准测试的问题后，我们本可以就此打住，自我表扬一番。 但是我们的 createDirectories() 方法呢？它太慢了吗？

看起来这里几乎没有优化的空间，因为这是一个库方法，我们无法控制它的实现。 不过，剖析器还是可以给我们一些线索。

通过展开折叠的库帧，我们可以检查内部发生了什么。

展开火焰图中的节点显示更多被折叠的库节点 展开火焰图中的节点显示更多被折叠的库节点

火焰图的这一部分显示， createDirectories() 方法执行时间的主要贡献者是 sun.nio.fs.UnixNativeDispatcher.mkdir0 。这个帧的很大一部分上面没有任何内容。 这被称为方法的“自执行时间”，表明没有Java代码超出这一点。 然而，可能有本地代码。

因为我们试图创建一个目录，这需要调用操作系统的API， 所以我们可能会期望 mkdir 的自执行时间主要由本地调用占据。 类名中的 UnixNativeDispatcher 似乎证实了这一点。

让我们启用本地剖析 设置 (Settings) | 构建、执行、部署 (Build, Execution, Deployment) | Java 分析器 (Java Profiler) | 收集原生调用 (Collect native calls)：

IntelliJ IDEA的Java分析器设置对话框 IntelliJ IDEA的Java分析器设置对话框

重新运行启用了本地剖析的应用程序，向我们展示了全貌：

现在一些Java帧之上有蓝色的本地帧 现在一些Java帧之上有蓝色的本地帧

原来的问题在这里。 createDirectories() 方法的文档说明如下:

通过首先创建所有不存在的父目录来创建目录。 与 createDirectory 方法不同， 如果目录无法创建是因为它已经存在，则不会抛出异常。

该描述从Java的角度来看是正确的， 因为它没有抛出任何Java异常。 然而，当尝试创建一个已经存在的目录时，操作系统级别会抛出异常。 这在我们的场景中导致了资源的大量浪费。

让我们尝试避免这种情况，并用 Files.exists() 检查 来包裹对 createDirectories() 的调用：

Path p = Paths.get("./a/b");
if (!Files.exists(p)) {
    Files.createDirectories(p);
}

程序变得极快!

Average count: 50000 op
Spent time: 87 ms

现在它的速度大约是最初速度的16倍。 这种异常处理真的很昂贵！结果可能会根据硬件和环境而有所不同，但无论如何都应该令人印象深刻。

快照差异

如果您正在使用IntelliJ Profiler，有一个方便的工具可以让您直观地比较 两个快照。有关详细说明和步骤，我建议参考 文档。 以下是差异显示结果的简要概述：

快照之间的差异以不同颜色反映 快照之间的差异以不同颜色反映

新快照中缺失的帧以绿色高亮显示，而新增的帧则以红色着色。 如果一个帧有多种颜色，这意味着该帧存在于两个快照中，但其总运行时间发生了变化。

如上图所示，我们程序最初执行的绝大多数操作都是不必要的，我们已经成功消除了它们。 CountEvents.update() 完全为绿色，这意味着 我们的第一次更改使该方法的运行时间接近完全改善。添加 Files.exists() 并非100%的改进，但它有效地从快照中移除了 createDirectories() ， 仅给程序运行时间增加了60毫秒。

结论

在这个场景中，我们使用了一个分析器来检测并修复了一个性能问题。我们还见证了 即使是众所周知的API也可能具有严重影响Java程序执行时间的后果。 这向我们展示了为什么即使你不是为了每秒百万次交易进行优化，性能分析也是一项有用的技能。

在接下来的文章中，我们将考虑更多的性能分析用例和技术。 敬请期待！

all posts ->