ここ数か月、2つの技術に興味を持っていました。Zigというプログラミング言語と、Ethereumという暗号通貨です。両方をもっと学ぶために、ZigでEthereum仮想マシン（EVM）のバイトコードインタプリタを書いています。

Zigはパフォーマンス最適化に優れた言語です。メモリや制御フローを細かくコントロールできるからです。モチベーションを保つために、自分のEthereum実装を公式のGo実装とベンチマークで比較してきました。

最近、ベンチマークスクリプトをちょっとリファクタリングしたつもりだったのですが、アプリのパフォーマンスが急落しました。原因を調べると、違いは次の2つのコマンドにありました。

$ 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はバイナリをコンパイルして実行するためのショートカットコマンドにすぎません。本来は次の2つのコマンドと同等のはずです。

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

なぜビルドのステップが1つ増えただけで、プログラムが10倍近く速くなるのでしょうか？

現象を最小構成で再現する

このパフォーマンスの謎を解くために、アプリをどんどん単純化してみました。バイトコードインタプリタですらなくし、標準入力から読み込んだバイト数を数えるだけのプログラムにしたのです。

// 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のパイプラインでつないだ3つのコマンドから成り立っていました。

1. echoは10バイトの16進数列（0x00、0x01、…）を出力します。
2. xxdはechoの16進数出力をバイナリに変換します。
3. zig build runはバイトカウンタプログラムをコンパイルして実行し、xxdが出力したバイナリのバイト数を数えます。

zig build runと./zig-out/bin/count-bytesの違いは、後者がコンパイル済みのアプリを実行するだけなのに対し、前者は再コンパイルしてから実行する点だけでした。

またしても、頭を抱えることになりました。

なぜ余計なコンパイルステップでプログラムが速くなるのでしょうか？ Zigアプリは焼きたての方が速く動くのでしょうか？

Zigコミュニティに助けを求める

この時点でお手上げでした。ソースコードを何度も読み返しても、コンパイルしてから実行する方が、コンパイル済みのバイナリをそのまま実行するより速くなる理由がまったくわかりませんでした。

Zigはまだ新しい言語なので、きっと自分が何か誤解しているに違いないと思いました。経験豊富なZigプログラマーなら、私のコードを見ればすぐに間違いに気づいてくれるはずです。

そこでZigのディスカッションフォーラムであるZiggitに質問を投稿しました。最初のいくつかの返信では「入力バッファリングに問題がある」と指摘されましたが、具体的な修正方法や調査方法までは示されませんでした。

すると、Zigの創設者でありリード開発者のAndrew Kelly氏がスレッドにサプライズ登場しました。彼は私が見ていた現象自体は説明できないとしつつも、別のパフォーマンス上のミスを指摘してくれました。

最後に、友人のAndrew Ayer氏がMastodonでの私の投稿を見て、謎を解いてくれました。

Andrew Ayer氏の指摘はまさに的を射ていました。以下で詳しく解説します。

余談ですが、Andrew Ayer氏は前回のパフォーマンスの謎を解く鍵となる洞察もくれた人物です。

bashパイプラインについての私の思い込みは間違っていました

bashのパイプラインについて深く考えたことはありませんでしたが、Andrew氏のコメントで自分の思い込みが間違っていたことに気づきました。

次のようなシンプルなbashパイプラインを想像してください。

./jobA | ./jobB

実際には、bashパイプライン内のすべてのコマンドは同時に開始されます。

bashパイプラインでの並列実行を示すために、2つのシンプルなbashスクリプトで概念実証を作ってみました。

jobAは起動して3秒スリープし、標準出力に出力してから、さらに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は起動して標準入力からの入力を待ち、標準入力が閉じられるまで読み取れるものすべてを出力します。

#!/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をダウンロード

jobAとjobBをbashパイプラインで実行すると、jobB is startingとjobB 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

パイプラインではなくjobAとjobBを順番に実行するようにすると、jobBのstartingとterminatingのメッセージの間はわずか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アプリケーションが実際に動き出す頃には、前のジョブの完了を待つ必要がありません。入力はすでに標準入力で待機しているのです。

zig buildのステップを飛ばしてコンパイル済みバイナリを直接実行すると、count-bytesはすぐに起動してタイマーが動き始めます。問題は、count-bytesがechoとxxdからの入力が標準入力に届くのを約150マイクロ秒も待たなければならないことです。

ベンチマークを修正する

ベンチマークの修正は簡単でした。アプリケーションを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

Andrew Kelly氏のパフォーマンス改善を適用する

思い出してください。Andrew Kelly氏は私が1バイト読むごとに1回システムコールしていることを指摘していました。

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

つまり、ループ内でreadByteを呼ぶたびに、アプリケーションは実行を停止し、OSに入力の読み取りを要求して、OSが1バイトを届けるまで待ってから再開しなければならなかったのです。

修正は簡単でした。バッファ付きリーダーを使うのです。OSから1バイトずつ読むのではなく、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

より大きな入力でベンチマークする

私のEthereumインタプリタは現在、Ethereumのオペコードのごく一部にしか対応していません。現時点で実行できる最も複雑な計算は、数値を足し合わせることです。

例えば、こちらはスタックに1を3回プッシュしてから加算することで3まで数えるEthereumアプリケーションです。

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を足し合わせて1,000まで数えるEthereumバイトコードでした。

Andrew Kelly氏のアドバイスでシステムコールを削減した結果、「1,000まで数える」アプリケーションの実行時間は2,024マイクロ秒からわずか58マイクロ秒へと、35倍も高速化しました。これで公式のEthereum実装よりほぼ2倍速くなったのです。

チートで最高パフォーマンスを引き出す

自分のZig実装がついに公式のGo版を上回るのを見て興奮しましたが、Zigを活用してどこまでパフォーマンスを高められるか試してみたくなりました。

ソフトウェアでよくあるボトルネックの1つがメモリ確保です。プログラムはOSにメモリを要求し、OSがそれに応えるまで待たなければならないからです。

Zigには固定バッファアロケータ（fixed buffer allocator）というメモリアロケータがあります。アロケータがOSにメモリを要求する代わりに、あらかじめ固定サイズのバイトバッファを渡しておき、その範囲内だけでメモリを確保する仕組みです。

スタックから確保した2KBのメモリだけに制限したEthereumインタプリタをコンパイルすれば、ベンチマークでチートができます。

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());

これを「チート」と呼ぶのは、特定のベンチマークに合わせて最適化しているからです。もちろん2KB以上のメモリを必要とする正当なEthereumプログラムも存在しますが、この最適化でどこまで速くなるのか純粋に興味があったのです。

コンパイル時に最大メモリ要件がわかっている場合、パフォーマンスがどうなるか見てみましょう。

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

おわりに

この経験から得た教訓は、パフォーマンスのベンチマークは早く、そして頻繁に行うべきだということです。

継続的インテグレーションにベンチマークスクリプトを組み込み、結果をアーカイブしておいたことで、計測値がいつ変化したかを簡単に特定できました。もしベンチマークを手動で定期的に行うだけの作業にしていたら、計測値の差の原因を正確に突き止めるのは難しかったでしょう。

この経験は、指標を正しく理解することの重要性も浮き彫りにしました。このバグに遭遇するまで、自分のベンチマークに他のプロセスが標準入力を満たすまでの待ち時間が含まれているとは考えもしませんでした。

ソースコード

• eth-zvm: Zigで実装した趣味のEthereum仮想マシン