지난 몇 달 동안 저는 두 가지 기술에 관심을 가져왔습니다. 바로 Zig 프로그래밍 언어와 이더리움 암호화폐입니다. 두 기술을 더 깊이 배우기 위해 저는 Zig로 이더리움 가상 머신용 바이트코드 인터프리터를 작성해 왔습니다.

Zig는 메모리와 제어 흐름을 세밀하게 다룰 수 있어 성능 최적화에 아주 좋은 언어입니다. 스스로 동기를 부여하기 위해 저는 제 이더리움 구현을 공식 Go 구현과 비교해 벤치마크해 왔습니다.

최근에 저는 벤치마크 스크립트를 단순히 리팩터링했다고 생각했는데, 앱 성능이 급격히 떨어졌습니다. 원인을 추적해 보니 두 명령어의 차이 때문이었습니다.

$ 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는 16진수로 인코딩된 10바이트 시퀀스(0x00, 0x01, …)를 출력합니다.
2. xxd는 echo의 16진수 바이트를 바이너리 바이트로 변환합니다.
3. zig build run은 제 바이트 카운터 프로그램을 컴파일하고 실행해 xxd가 출력한 바이너리 바이트 수를 셉니다.

zig build run과 ./zig-out/bin/count-bytes의 유일한 차이는 두 번째 명령어는 이미 컴파일된 앱을 실행하는 반면, 첫 번째 명령어는 앱을 다시 컴파일한다는 점이었습니다.

또다시 저는 완전히 어리둥절해졌습니다.

어떻게 컴파일 단계가 하나 더 추가됐다고 프로그램이 더 빨라질 수 있을까요? Zig 앱이 갓 구워져 나왔을 때 더 빨리 실행되는 걸까요?

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 파이프라인의 병렬 실행을 보여주기 위해 저는 간단한 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가 제가 바이트를 읽을 때마다 시스템 콜을 한 번씩 하고 있다고 지적한 것을 기억하시나요.

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

즉, 애플리케이션이 루프에서 readByte를 호출할 때마다 실행을 중단하고 OS에 입력 읽기를 요청한 뒤, OS가 한 바이트를 전달하면 다시 재개해야 했습니다.

수정 방법은 간단했습니다. 버퍼드 리더를 사용하면 됩니다. OS에서 한 번에 한 바이트씩 읽는 대신, Zig에 내장된 std.io.bufferedReader를 사용해 OS에서 큰 덩어리로 데이터를 읽도록 했습니다. 이렇게 하면 시스템 콜 횟수를 대폭 줄일 수 있습니다.

전체 변경 내용은 다음과 같습니다.

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

더 큰 입력으로 벤치마크하기

현재 제 이더리움 인터프리터는 이더리움 오프코드 중 일부만 지원합니다. 지금 제 인터프리터가 할 수 있는 가장 복잡한 연산은 숫자를 더하는 것입니다.

예를 들어 다음은 1을 스택에 세 번 푸시한 뒤 값을 더해 3까지 세는 이더리움 애플리케이션입니다.

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까지 세는 이더리움 바이트코드였습니다.

Andrew Kelly의 팁 덕분에 시스템 콜을 줄인 뒤, “1,000까지 세기” 애플리케이션의 실행 시간은 2,024마이크로초에서 단 58마이크로초로 떨어져 35배나 빨라졌습니다. 이제 공식 이더리움 구현보다 거의 2배 빠른 셈이었습니다.

꼼수를 써서 최대 성능 끌어내기

제 Zig 구현이 마침내 공식 Go 버전을 앞지르는 것을 보고 신이 났지만, Zig를 활용해 성능을 얼마나 더 끌어올릴 수 있을지 보고 싶었습니다.

소프트웨어에서 흔한 병목 중 하나는 메모리 할당입니다. 프로그램이 운영체제에 메모리를 요청하고 OS가 이를 처리할 때까지 기다려야 하기 때문입니다.

Zig에는 고정 버퍼 할당자(fixed buffer allocator)라는 메모리 할당자가 있습니다. 메모리 할당자가 OS에 메모리를 요청하는 대신, 할당자에 고정된 바이트 버퍼를 제공하면 그 바이트만으로 메모리를 할당합니다.

스택에서 할당된 2KB 메모리로 제한된 버전의 이더리움 인터프리터를 컴파일해 벤치마크에서 꼼수를 쓸 수 있습니다.

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 이상의 메모리를 요구하는 유효한 이더리움 프로그램도 있겠지만, 이 최적화로 얼마나 빨라질 수 있는지 궁금했을 뿐입니다.

컴파일 시점에 최대 메모리 요구량을 안다면 성능이 어떻게 달라지는지 보겠습니다.

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

멋지네요! 고정 메모리 버퍼를 사용하자 제 이더리움 구현은 “1,000까지 세기” 바이트코드를 34마이크로초 만에 실행해 공식 Go 구현보다 거의 3배 빨라졌습니다.

결론

이번 경험에서 얻은 교훈은 성능 벤치마크를 일찍, 자주 해야 한다는 것입니다.

지속적 통합에 벤치마크 스크립트를 추가하고 결과를 보관했기 때문에 측정값이 언제 달라졌는지 쉽게 파악할 수 있었습니다. 만약 벤치마크를 수동으로 주기적으로 수행하는 작업으로 미뤄뒀다면, 측정값 차이의 원인을 정확히 파악하기 어려웠을 것입니다.

이번 경험은 지표를 제대로 이해하는 것의 중요성도 보여줍니다. 이 버그를 만나기 전까지는 제 벤치마크에 다른 프로세스가 stdin을 채울 때까지 기다리는 시간이 포함되어 있다는 사실을 생각하지 못했습니다.

소스 코드

• eth-zvm: Zig로 구현한 취미용 이더리움 가상 머신