Why does an extraneous build step make my Zig app 10x faster?

Michael Lynch

为什么一个多余的构建步骤让我的 Zig 应用快了 10 倍?

原文由 Michael Lynch 发布,订阅该博客

过去几个月里,我一直对两项技术很感兴趣:Zig 编程语言和以太坊加密货币。为了更深入地了解它们,我一直在用 Zig 编写以太坊虚拟机的字节码解释器

Zig 是一门非常适合做性能优化的语言,因为它能让你对内存和控制流进行细粒度的控制。为了激励自己,我一直在把自己的以太坊实现与官方的 Go 实现做基准对比。

一开始,我这个业余的 Zig 版以太坊实现比官方 Go 实现慢了约 40%。

最近,我本以为只是对基准测试脚本做了一次简单的重构,结果应用性能却一落千丈。我定位到关键差异在于以下两条命令:

$ echo '60016000526001601ff3' | xxd -r -p | zig build run -Doptimize=ReleaseFast
execution time:  58.808µs
$ echo '60016000526001601ff3' | xxd -r -p | ./zig-out/bin/eth-zvm
execution time:  438.059µs

zig build run 只是编译并执行二进制文件的一条快捷命令,它应该等同于下面这两条命令:

zig build
./zig-out/bin/eth-zvm

多了一个构建步骤,怎么会让程序运行速度快了将近 10 倍?

创建一个最小复现

为了解开这个性能之谜,我尝试不断简化应用,直到它不再是一个字节码解释器,而只是一个统计从 stdin 读取字节数的程序:

// src/main.zig

const std = @import("std");

pub fn countBytes(reader: anytype) !u32 {
    var count: u32 = 0;
    while (true) {
        _ = reader.readByte() catch |err| switch (err) {
            error.EndOfStream => {
                return count;
            },
            else => {
                return err;
            },
        };
        count += 1;
    }
}

pub fn main() !void {
    var reader = std.io.getStdIn().reader();

    var timer = try std.time.Timer.start();
    const start = timer.lap();
    const count = try countBytes(&reader);
    const end = timer.read();
    const elapsed_micros = @as(f64, @floatFromInt(end - start)) / std.time.ns_per_us;

    const output = std.io.getStdOut().writer();
    try output.print("bytes:           {}\n", .{count});
    try output.print("execution time:  {d:.3}µs\n", .{elapsed_micros});
}

即使用了这个简化版应用,我依然能看到性能差异。用 zig build run 运行字节计数器时,只花了 13 微秒:

$ echo '00010203040506070809' | xxd -r -p | zig build run -Doptimize=ReleaseFast
bytes:           10
execution time:  13.549µs

而直接运行编译好的二进制文件时,耗时却要长 12 倍,达到了 162 微秒:

$ echo '00010203040506070809' | xxd -r -p | ./zig-out/bin/count-bytes
bytes:           10
execution time:  162.195µs

我的测试由 bash 管道中的三条命令组成:

  1. echo 打印 10 个十六进制编码的字节(0x000x01……)。
  2. xxdecho 输出的十六进制字节转换为二进制字节。
  3. zig build run 编译并执行我的字节计数程序,统计 xxd 输出的二进制字节数量。

zig build run./zig-out/bin/count-bytes 唯一的差别在于,后者直接运行已编译好的应用,而前者会重新编译一次。

我再次感到百思不得其解。

怎么多一次编译步骤反而让程序更快了?难道 Zig 应用刚出炉时跑得更快吗?

向 Zig 社区求助

到这一步,我完全卡住了。我把源码反复看了好几遍,还是无法理解为什么编译并运行应用会比直接运行已编译好的二进制文件更快。

Zig 毕竟还是一门新语言,肯定是我对 Zig 的某些地方理解错了。经验丰富的 Zig 程序员只要看一眼我的代码,肯定能立刻发现问题所在吧。

在 Ziggit 上发帖提问,这是一个 Zig 的讨论论坛。最初的几条回复说我存在“输入缓冲”的问题,但没有给出具体的修复或进一步排查的建议。

Zig 的创始人兼首席开发者 Andrew Kelly 意外现身在了帖子里。他也无法解释我遇到的现象,但他指出我犯了另一个性能错误:

看起来你每次读取一个字节就要做一次系统调用?这样性能会非常差。我猜使用构建系统时多出来的步骤无意中引入了某种缓冲。但我也不确定原因。构建系统是让子进程直接继承文件描述符的。

最后,我的朋友 Andrew Ayer 在 Mastodon 上看到了我发的帖子,并解开了谜团

如果输入显著变大(比如大于 1MB)时,你还能看到 10 倍的差距吗?如果把 stdin 从文件重定向而不是通过管道,还会有差距吗?我的猜测是,当你直接执行程序时,xxd 和 count-bytes 同时启动,所以 count-bytes 第一次尝试从 stdin 读取时管道缓冲区还是空的,它必须等到 xxd 填充后才能继续。但当你使用 zig build run 时,xxd 在程序编译期间就抢先运行了一段时间,所以等到 count-bytes 去读取 stdin 时,管道缓冲区已经被填满了。

Andrew Ayer 完全说对了,下面我来详细拆解一下。

题外话:Andrew Ayer 之前也曾给出关键洞见,帮我解开了上一次的性能谜团

我对 bash 管道的理解是错的

我以前从未仔细思考过 bash 管道,而 Andrew 的评论让我意识到自己的理解是错的。

设想一个简单的 bash 管道,如下所示:

./jobA | ./jobB

我原本以为 jobA 会先启动并运行到结束,然后 jobB 才会启动,并以 jobA 的输出作为输入。

jobB 在 jobA 结束后才启动的甘特图

我对 bash 管道中任务执行方式的错误理解

实际上,bash 管道中的所有命令是同时启动的。

jobA 和 jobB 同时启动的甘特图,但 jobB 耗时更长,因为它必须等待 jobA 的结果

bash 管道中任务实际的执行方式

为了演示 bash 管道中的并行执行,我用两个简单的 bash 脚本写了一个概念验证。

jobA 启动后休眠 3 秒,向 stdout 打印内容,再休眠 2 秒,然后退出:

#!/usr/bin/env bash

function print_status() {
    local message="$1"
    local timestamp=$(date +"%T.%3N")
    echo "$timestamp $message" >&2
}

print_status 'jobA is starting'

sleep 3

echo 'result of jobA is...'

sleep 2

echo '42'

print_status 'jobA is terminating'

下载 jobA

jobB 启动后等待 stdin 上的输入,然后把从 stdin 读取到的所有内容打印出来,直到 stdin 关闭:

#!/usr/bin/env bash

function print_status() {
    local message="$1"
    local timestamp=$(date +"%T.%3N")
    echo "$timestamp $message" >&2
}

print_status 'jobB is starting'

print_status 'jobB is waiting on input'
while read line; do
  print_status "jobB read '${line}' from input"
done < /dev/stdin
print_status 'jobB is done reading input'

print_status 'jobB is terminating'

下载 jobB

如果我在 bash 管道中运行 jobAjobB,在 jobB is startingjobB is terminating 这两条消息之间恰好经过了 5.009 秒:

$ ./jobA | ./jobB
09:11:53.326 jobA is starting
09:11:53.326 jobB is starting
09:11:53.328 jobB is waiting on input
09:11:56.330 jobB read 'result of jobA is...' from input
09:11:58.331 jobA is terminating
09:11:58.331 jobB read '42' from input
09:11:58.333 jobB is done reading input
09:11:58.335 jobB is terminating

如果我调整执行方式,让 jobAjobB 串行执行而不是走管道,那么在 jobBstartingterminating 消息之间只经过了 0.008 秒:

$ ./jobA > /tmp/output && ./jobB < /tmp/output
16:52:10.406 jobA is starting
16:52:15.410 jobA is terminating
16:52:15.415 jobB is starting
16:52:15.417 jobB is waiting on input
16:52:15.418 jobB read 'result of jobA is...' from input
16:52:15.420 jobB read '42' from input
16:52:15.421 jobB is done reading input
16:52:15.423 jobB is terminating

回到我的字节计数器

一旦明白 bash 管道中的所有命令都是并行运行的,我在字节计数器上看到的现象就说得通了:

$ echo '00010203040506070809' | xxd -r -p | zig build run -Doptimize=ReleaseFast
bytes:           10
execution time:  13.549µs

$ echo '00010203040506070809' | xxd -r -p | ./zig-out/bin/count-bytes
bytes:           10
execution time:  162.195µs

看起来,管道中 echo '00010203040506070809' | xxd -r -p 这部分就要花大约 150 微秒。而 zig build run 这一步至少也要花 150 微秒。

等到 zig build 版本中的 count-bytes 应用真正开始执行时,它不需要再等待前面的任务完成。输入已经在 stdin 上等着了。

echo、xxd 和 zig build run 同时启动的甘特图,但 zig build run 的执行阶段在 echo 和 xxd 完成后才开始

使用 zig build run 时,应用执行前有一段延迟,所以等到 count-bytes 启动时,管道中前面的任务已经完成了。

而当我跳过 zig build 步骤直接运行编译好的二进制文件时,count-bytes 会立即启动并开始计时。问题在于,count-bytes 必须空等约 150 微秒,直到 echoxxd 把输入送到 stdin。

echo、xxd 和 count-bytes 同时启动的甘特图,但 count-bytes 在启动后 150 微秒内无法开始处理输入,因为它在等待 xxd 的结果

当我直接运行 count-bytes 时,它必须空等约 150 微秒,直到 echoxxd 把输入喂给 stdin。

修复基准测试

修复基准测试很简单。我不再把应用放在 bash 管道中运行,而是把准备阶段和执行阶段拆成了两条独立的命令:

# Convert the hex-encoded input to binary encoding.
$ INPUT_FILE_BINARY="$(mktemp)"
$ echo '60016000526001601ff3' | xxd -r -p > "${INPUT_FILE_BINARY}"

# Read the binary-encoded input into the virtual machine.
$ ./zig-out/bin/eth-zvm < "${INPUT_FILE_BINARY}"
execution time:  67.378µs

我的基准测试结果从之前的 438 微秒降到了只有 67 微秒。

修复基准测试脚本后,我的 Zig 应用在测量性能上的差异

应用 Andrew Kelly 的性能修复

还记得 Andrew Kelly 指出我每读取一个字节就要做一次系统调用吗。

var reader = std.io.getStdIn().reader();
...
while (true) {
      _ = reader.readByte() { // Slow! One syscall per byte
          ...
      };
      ...
  }

所以,每次应用在循环中调用 readByte 时,都必须暂停执行,向操作系统请求读取输入,然后等操作系统返回单个字节后才能继续。

修复方法很简单。我需要使用带缓冲的读取器。不再每次只从操作系统读一个字节,而是使用 Zig 内置的 std.io.bufferedReader,让应用一次性从操作系统读取一大块数据。这样一来,系统调用的次数就大幅减少了。

完整的改动如下:

diff --git a/src/main.zig b/src/main.zig
index d6e50b2..a46f8fa 100644
--- a/src/main.zig
+++ b/src/main.zig
@@ -7,7 +7,9 @@ pub fn main() !void {
     const allocator = gpa.allocator();
     defer _ = gpa.deinit();

-    var reader = std.io.getStdIn().reader();
+    const in = std.io.getStdIn();
+    var buf = std.io.bufferedReader(in.reader());
+    var reader = buf.reader();

     var evm = vm.VM{};
     evm.init(allocator);

我重新运行了示例,性能又提升了 11 微秒,带来了约 16% 的小幅加速。

$ zig build -Doptimize=ReleaseFast && ./zig-out/bin/eth-zvm < "${INPUT_FILE_BINARY}"
execution time:  56.602µs

对输入读取加缓冲又带来了 16% 的性能提升。

用更大输入做基准测试

我的以太坊解释器目前只支持以太坊操作码的一小部分。就目前而言,它能做的最复杂的计算就是把数字相加。

例如,下面这个以太坊应用通过三次将 1 压入栈,再把它们相加来数到三:

PUSH1 1    # Stack now contains [1]
PUSH1 1    # Stack now contains [1, 1]
PUSH1 1    # Stack now contains [1, 1, 1]
ADD        # Stack now contains [2, 1]
ADD        # Stack now contains [3]

我在基准测试中用到的最大的应用,是通过不断将 1 相加来数到 1000 的以太坊字节码。

在 Andrew Kelly 的建议帮我减少了系统调用之后,我的“数到 1000”应用的运行时间从 2024 微秒降到了只有 58 微秒,速度提升了 35 倍。现在我的实现已经比官方以太坊实现快了将近两倍。

对输入读取加缓冲后,我的 Zig 实现在测试集中最大的以太坊应用上比官方以太坊实现快了约 2 倍。

取巧实现极致性能

看到自己的 Zig 实现终于超过了官方 Go 版本,我很兴奋,但我还想看看能多大程度上利用 Zig 来进一步提升性能。

软件中一个常见的瓶颈是内存分配,因为程序必须向操作系统请求内存,并等待操作系统满足请求。

Zig 有一种名为固定缓冲区分配器的内存分配器。它不再让分配器向操作系统请求内存,而是由你提供一个固定大小的字节缓冲区,分配器只用这块缓冲区来分配内存。

我可以通过编译一个仅限于从栈上分配 2 KB 内存的以太坊解释器版本,来为基准测试取巧:

diff --git a/src/main.zig b/src/main.zig
index a46f8fa..9e462fe 100644
--- a/src/main.zig
+++ b/src/main.zig
@@ -3,9 +3,9 @@ const stack = @import("stack.zig");
 const vm = @import("vm.zig");

 pub fn main() !void {
-    var gpa = std.heap.GeneralPurposeAllocator(.{}){};
-    const allocator = gpa.allocator();
-    defer _ = gpa.deinit();
+    var buffer: [2000]u8 = undefined;
+    var fba = std.heap.FixedBufferAllocator.init(&buffer);
+    const allocator = fba.allocator();

     const in = std.io.getStdIn();
     var buf = std.io.bufferedReader(in.reader());

我之所以称之为“取巧”,是因为我是在针对自己的特定基准测试做优化。肯定有需要超过 2 KB 内存的合法以太坊程序,但我只是好奇用这种优化能跑多快。

来看看如果我在编译时就知道最大内存需求,性能会是什么样:

$ ./zig-out/bin/eth-zvm < "${COUNT_TO_1000_INPUT_BYTECODE_FILE}"
execution time:  34.4578µs

太棒了!使用固定内存缓冲区后,我的以太坊实现运行“数到 1000”的字节码只需 34 微秒,比官方 Go 实现快了将近 3 倍。

如果我在编译时就知道以太坊解释器的最大内存需求,就能比官方实现快 3 倍。

结论

我从这次经历中得到的启示是,要尽早、频繁地做性能基准测试。

通过把基准测试脚本加入持续集成并归档结果,我很容易就能发现测量结果何时发生了变化。如果我只是把基准测试当作一项手动、周期性的任务,就很难准确找出导致测量差异的原因。

这次经历也凸显了理解自己指标的重要性。在遇到这个 bug 之前,我从未想过我的基准测试竟然包含了等待其他进程填充 stdin 的时间。

源代码

  • eth-zvm:我用 Zig 实现的业余以太坊虚拟机

本文章由 muse-spark-1.2-contributor 进行翻译

评论