ここ数ヶ月、2つの技術に興味を持っていました。Zigというプログラミング言語と、Ethereumという暗号資産です。両方についてもっと学ぶために、Zigを使ってEthereum Virtual Machine用のバイトコードインタプリタを書いています。

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

なぜ、余計なビルドステップがプログラムをほぼ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のパイプラインでつないだ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

私の思い込みでは、jobAが開始して完了まで実行され、その後jobBがjobAの出力を入力として開始するものだと思っていました。

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

bashパイプラインでの並列実行を示すため、2つの単純な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が閉じられるまで読み取れるものすべてを出力します。

#!/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アプリケーションが実際に開始する頃には、前のジョブが完了するのを待つ必要はありません。入力はすでにstdinで待機しているのです。

zig buildのステップをスキップしてコンパイル済みバイナリを直接実行すると、count-bytesはすぐに開始してタイマーが動き始めます。問題は、count-bytesがechoとxxdのコマンドがstdinに入力を届けるまで、約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

私のベンチマークは、それまでの438マイクロ秒からわずか67マイクロ秒へと低下しました。

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

先ほど、Andrew Kelly氏が指摘していたことを思い出してください。私は1バイト読むごとに1回のsyscallを行っていました。

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を使うことで、アプリケーションはOSから大きな塊でデータを読み込むようになります。そうすれば、syscallの回数はほんの一部で済みます。

変更点はこれだけです。

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のopcodeのごく一部しかサポートしていません。現時点でインタプリタができる最も複雑な計算は、数値を足し合わせることです。

例えば、こちらは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氏のアドバイスでsyscallを削減した後、「1,000まで数える」アプリケーションの実行時間は2,024マイクロ秒からわずか58マイクロ秒へと短縮され、35倍の高速化となりました。これで公式のEthereum実装よりほぼ2倍速くなりました。

ズルをして最大パフォーマンスを引き出す

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

ソフトウェアでよくあるボトルネックの一つはメモリ確保です。プログラムは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

すごい！ 固定メモリバッファを使うことで、私のEthereum実装は「1,000まで数える」バイトコードを34マイクロ秒で実行でき、公式のGo実装よりほぼ3倍速くなりました。

まとめ

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

ベンチマークスクリプトを継続的インテグレーションに追加し、結果を保存しておいたことで、計測値が変化したタイミングを容易に特定できました。もしベンチマークを手動の定期的な作業にしていたら、計測値の差の原因を正確に突き止めることは困難だったでしょう。

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

ソースコード

• eth-zvm: Zigで実装した趣味のEthereum Virtual Machine