⏱️

Zigで書いたコマンドラインアプリケーションにperfを使ってみた

2022/07/12に公開1件

Zig

perf

tech

はじめに

Zigで書いたコマンドラインアプリケーションのボトルネック調査にperfを使ってみたメモです。
なお、私は今回初めてperfを使ったレベルで全然詳しくないので、間違いや改善点があればぜひご指摘ください。

環境は Ubuntu 22.04 LTS です。

$ zig version
0.10.0-dev.2853+6279a1d68

perfのセットアップ

Ubuntuでperfで測定する手順メモを参考にしました。ありがとうございます。Linux perf Examples も見ました。

sudo apt install -y linux-tools-common

一般ユーザで perf を使うための設定。

sudo sh -c 'echo -1 > /proc/sys/kernel/perf_event_paranoid'
sudo sh -c 'echo 0 > /proc/sys/kernel/kptr_restrict'

恒久的に設定するなら上記の代わりに以下のようにします。

cat <<EOF | sudo tee /etc/sysctl.d/98-perf.conf
kernel.perf_event_paranoid = -1
kernel.kptr_restrict = 0
EOF
sudo sysctl --load=/etc/sysctl.d/98-perf.conf

$ perf version
perf version 5.15.35

このままだと perf report を実行したときに最下行に Cannot load tips.txt file, please install perf! というメッセージが出ます。
package management - How to get perf fully working with all features? - Ask Ubuntu を参考に tips.txt をダウンロードして保存します（一応 Ubuntu – パッケージ内容検索結果 -- /usr/share/doc/perf/tips.txt で確認しましたがヒットなしでした）。

sudo curl --create-dirs -Lo /usr/share/doc/perf/tips.txt https://raw.githubusercontent.com/torvalds/linux/master/tools/perf/Documentation/tips.txt
sudo chmod o+rx /usr/share/doc/perf-tip

調査対象のコマンドラインアプリケーション

hnakamur/log2sqlite3-zig です。
ndjson形式のアクセスログファイルをSQLiteのデータベースにインポートするコマンドラインツールです。ただし広く一般向けというより自分の用途に限定したものになっています。あとまだ開発途中です。

SQLiteのデータベースへのアクセスはvrischmann/zig-sqlite: zig-sqlite is a small wrapper around sqlite's C API, making it easier to use with Zig.を使用しています。

入力ファイル

nginxにcurlでアクセスして作成しました。

nginxのログ設定を以下のようにします。この記事で扱うアプリケーションでは数値カラムは未対応のため全ての項目を文字列としています。

    log_format json escape=json '{"time":"$time_iso8601",'
                                '"msec":"$msec",'
                                '"host":"$remote_addr",'
                                '"port":"$remote_port",'
                                '"method":"$request_method",'
                                '"uri":"$request_uri",'
                                '"status":"$status",'
                                '"body_bytes":"$body_bytes_sent",'
                                '"referer":"$http_referer",'
                                '"ua":"$http_user_agent",'
                                '"request_time":"$request_time",'
                                '"response_time":"$upstream_response_time"}';
    access_log /var/log/nginx/access.log json;

curlで1万回アクセスしてログを作成します。

for i in {0..9999}; do curl http://localhost/$i > /dev/null; done

cp /var/log/nginx/access.log .

$ wc -l access.log
10000 access.log

$ head -2 access.log
{"time":"2022-07-09T17:38:20+09:00","msec":"1657355900.715","host":"127.0.0.1","port":"46138","method":"GET","uri":"/0","status":"404","body_bytes":"153","referer":"","ua":"curl/7.81.0","request_time":"0.000","response_time":""}
{"time":"2022-07-09T17:38:20+09:00","msec":"1657355900.722","host":"127.0.0.1","port":"46140","method":"GET","uri":"/1","status":"404","body_bytes":"153","referer":"","ua":"curl/7.81.0","request_time":"0.000","response_time":""}

アプリケーションのビルド

ZigのBuild Modeはリリースモードが3種類あります。
今回は実行速度優先のReleaseFastにします。
Build Modeでは zig build-exe example.zig -O ReleaseSafe というコマンド例が書いてありますが、 zig build のオプションだと -Drelease-fast です。

$ zig build --help | grep release
  -Drelease-safe=[bool]        Optimizations on and safety on
  -Drelease-fast=[bool]        Optimizations on and safety off
  -Drelease-small=[bool]       Size optimizations on and safety off

ということで以下のコマンドでビルドします。

zig build -Drelease-fast

./zig-out/bin/log2sqlite3-zig に実行ファイルが作成されます。

$ file ./zig-out/bin/log2sqlite3-zig
./zig-out/bin/log2sqlite3-zig: ELF 64-bit LSB executable, x86-64, version 1 (SYSV), dynamically linked, interpreter /lib64/ld-linux-x86-64.so.2, for GNU/Linux 3.2.0, with debug_info, not stripped

ファイルサイズ確認。

$ ls -lh ./zig-out/bin/log2sqlite3-zig
-rwxrwxr-x 1 hnakamur hnakamur 748K  7月 10 20:58 ./zig-out/bin/log2sqlite3-zig

参照している共有ライブラリ確認。

$ ldd ./zig-out/bin/log2sqlite3-zig
        linux-vdso.so.1 (0x00007ffd2e4a5000)
        libsqlite3.so.0 => /usr/lib/x86_64-linux-gnu/libsqlite3.so.0 (0x00007f4c1a502000)
        libc.so.6 => /usr/lib/x86_64-linux-gnu/libc.so.6 (0x00007f4c1a2da000)
        /lib64/ld-linux-x86-64.so.2 (0x00007f4c1a651000)
        libm.so.6 => /lib/x86_64-linux-gnu/libm.so.6 (0x00007f4c1a1e0000)

呼び出しグラフを取得しつつperfで計測して実行

今回の計測対象のコミット: Add sql.insertRecord · hnakamur/log2sqlite3-zig@91372be

まず perf 無しで time で実行時間を計測（実際には3回ぐらい実行してばらつきを見ますが記事では省略します）。

$ rm -f mydata.db; time ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log

real    0m15.124s
user    0m0.526s
sys     0m4.743s

DBファイルを削除後、perfから対象のアプリケーションを実行して計測結果を perf.data ファイルに保存します。
perfなしの場合より約1秒遅いので、perfで計測することによるオーバーヘッドが約1秒あることがわかります。

$ rm -f mydata.db; time perf record -F 99 -g --call-graph dwarf ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log
[ perf record: Woken up 96 times to write data ]
[ perf record: Captured and wrote 25.643 MB perf.data (560 samples) ]

real    0m16.248s
user    0m0.722s
sys     0m5.615s

logテーブルのレコード件数確認（以下も変更して実行するたびに確認しますが記事では省略します）。

$ sqlite3 mydata.db "select count(*) from log"
10000

perf.data のデータを読み込んでレポートを表示します。

perf report

TUIの画面で以下のような内容が表示されます。

Samples: 507  of event 'cycles', Event count (approx.): 11589404687
  Children      Self  Command          Shared Object        Symbol
+   87.72%     0.00%  log2sqlite3-zig  [kernel.kallsyms]    [k] entry_SYSCALL_64_after_hwframe
+   86.71%     0.82%  log2sqlite3-zig  [kernel.kallsyms]    [k] do_syscall_64
+   80.83%     0.00%  log2sqlite3-zig  log2sqlite3-zig      [.] .sqlite.Db.execDynamic (inlined)
+   80.58%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3_step
+   80.58%     0.19%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3VdbeExec
+   80.58%     0.00%  log2sqlite3-zig  log2sqlite3-zig      [.] .sqlite.DynamicStatement.exec (inlined)
+   59.02%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3VdbeHalt
+   42.01%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3BtreeCommitPhaseOne
+   42.01%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3PagerCommitPhaseOne
…(略)…

Share Object が log2sqlite3-zig の列では以下の行が一番割合が高いです。

+   70.51%     0.00%  log2sqlite3-zig  log2sqlite3-zig      [.] .sqlite.Db.execDynamic (inlined)

Add sql.insertRecord · hnakamur/log2sqlite3-zig@91372be の log2sqlite3-zig/sql.zig at main · hnakamur/log2sqlite3-zig では毎回 SQL の文字列を動的に組み立てて sqlite.Db.execDynamic を読んでいるのでここがボトルネックになっています。

実は perf の練習用にわざと遅い書き方にしてました。これをまずはプリペアドステートメントを使うように変更してみます。

プリペアドステートメントを使うようにした版

Add prepareInsertLog and execInsertLog · hnakamur/log2sqlite3-zig@69870a9

perf 無しで time で実行時間を計測。所要時間はほぼ変化なしでした。

$ rm -f mydata.db; time ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log

real    0m15.007s
user    0m0.346s
sys     0m4.922s

perf 有りで time で実行時間を計測。

$ rm -f mydata.db; time perf record -F 99 -g --call-graph dwarf ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log
[ perf record: Woken up 90 times to write data ]
[ perf record: Captured and wrote 23.945 MB perf.data (464 samples) ]

real    0m16.242s
user    0m0.483s
sys     0m5.347s

perf report の結果。

Samples: 464  of event 'cycles', Event count (approx.): 10249570976
  Children      Self  Command          Shared Object        Symbol
+   90.45%     0.36%  log2sqlite3-zig  [kernel.kallsyms]    [k] entry_SYSCALL_64_after_hwframe
+   89.71%     0.00%  log2sqlite3-zig  [kernel.kallsyms]    [k] do_syscall_64
+   78.41%     0.00%  log2sqlite3-zig  log2sqlite3-zig      [.] sql.execInsertLog
+   78.41%     0.00%  log2sqlite3-zig  log2sqlite3-zig      [.] .sqlite.DynamicStatement.exec (inlined)
+   78.41%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3_step
+   78.41%     0.24%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3VdbeExec
+   56.29%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3VdbeHalt
+   45.78%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3BtreeCommitPhaseOne
+   45.78%     0.00%  log2sqlite3-zig  libsqlite3.so.0.8.6  [.] sqlite3PagerCommitPhaseOne
+   31.53%     0.00%  log2sqlite3-zig  libc.so.6            [.] __GI_fdatasync (inlined)
…(略)…

トランザクションを使って1000レコードごとにコミットした版

Use savepoint (transaction) · hnakamur/log2sqlite3-zig@e322bb6

perf 無しで time で実行時間を計測。一気に短くなりました。

$ rm -f mydata.db; time ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log

real    0m0.499s
user    0m0.053s
sys     0m0.430s

perf 有りで time で実行時間を計測。

$ rm -f mydata.db; time perf record -F 99 -g --call-graph dwarf ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log
[ perf record: Woken up 83 times to write data ]
[ perf record: Captured and wrote 20.584 MB perf.data (51 samples) ]

real    0m1.207s
user    0m0.226s
sys     0m0.957s

perf report の実行結果（json.parseStringPos で展開した状態）。

Samples: 51  of event 'cycles', Event count (approx.): 2128458945
  Children      Self  Command          Shared Object      Symbol
+   73.49%     0.00%  log2sqlite3-zig  [kernel.kallsyms]  [k] entry_SYSCALL_64_after_hwframe                                    ◆
+   73.49%     0.00%  log2sqlite3-zig  [kernel.kallsyms]  [k] do_syscall_64                                                     ▒
-   63.04%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] json.parseStringPos                                               ▒
     json.parseStringPos                                                                                                        ▒
     json.parseString (inlined)                                                                                                 ▒
   + std.mem.Allocator.dupe (inlined)                                                                                           ▒
+   63.04%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] json.parseString (inlined)                                        ▒
+   63.04%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.mem.Allocator.dupe (inlined)                                  ▒
+   41.03%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.mem.Allocator.alloc (inlined)                                 ▒
+   41.03%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.mem.Allocator.allocAdvancedWithRetAddr (inlined)              ▒
+   41.03%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.mem.Allocator.rawAlloc (inlined)                              ▒
+   41.03%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.heap.PageAllocator.alloc (inlined)                            ▒
+   41.03%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.os.mmap (inlined)                                             ▒
+   41.03%     0.00%  log2sqlite3-zig  libc.so.6          [.] __GI___mmap64 (inlined)                                           ▒
+   36.96%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] std.start.main (inlined)                                          ▒
…(略)…

メモリ割り当て回数削減版

Rename json.ParseResult to ndjson.Parser · hnakamur/log2sqlite3-zig@2446d99

perf 無しで time で実行時間を計測。

$ rm -f mydata.db; time ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log

real    0m0.055s
user    0m0.023s
sys     0m0.019s

perf 有りで time で実行時間を計測。

$ rm -f mydata.db; time perf record -F 99 -g --call-graph dwarf ./zig-out/bin/log2sqlite3-zig --db mydata.db --table log access.log
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.072 MB perf.data (6 samples) ]

real    0m1.214s
user    0m0.123s
sys     0m0.369s

perf report の結果。メモリ割り当てはボトルネックではなくなりました。

Samples: 6  of event 'cycles', Event count (approx.): 7744147
  Children      Self  Command          Shared Object      Symbol
-   99.66%    99.66%  log2sqlite3-zig  log2sqlite3-zig    [.] ndjson.parseStringPos                                             ▒
     ndjson.parseStringPos                                                                                                      ▒
     ndjson.expectPrefixPos (inlined)                                                                                           ▒
     ndjson.startsWithPos (inlined)                                                                                             ▒
-   99.66%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] ndjson.expectPrefixPos (inlined)                                  ▒
     ndjson.expectPrefixPos (inlined)                                                                                           ▒
     ndjson.startsWithPos (inlined)                                                                                             ▒
-   99.66%     0.00%  log2sqlite3-zig  log2sqlite3-zig    [.] ndjson.startsWithPos (inlined)                                    ▒
     ndjson.startsWithPos (inlined)                                                                                             ▒
     0.34%     0.34%  log2sqlite3-zig  [kernel.kallsyms]  [k] may_expand_vm                                                     ◆
…(略)…

今回はこれで十分短縮できたということで以上とします。

Discussion

Hiroaki Nakamura

hnakamur/log2sqlite3-zig を public にするの忘れてたので今しました。