前回からの続きです。
今回はタイムプロファイリングの章です。
Time Profiling - Rust and WebAssembly
タイムプロファイリングする
ライフゲームのパフォーマンス向上の指針として、FPS（Frames Per Second）タイマーの導入を行います。
window.performance.nowという関数を利用して、
www/index.jsにfpsオブジェクトを実装します。
const fps = new class {
constructor() {
this.fps = document.getElementById("fps");
this.frames = [];
this.lastFrameTimeStamp = performance.now();
}
render() {
// 最後のフレームレンダリングからの差分時間を1秒あたりのフレーム数に変換する。
const now = performance.now();
const delta = now - this.lastFrameTimeStamp;
this.lastFrameTimeStamp = now;
const fps = 1 / delta * 1000;
// 最新の100個のタイミングだけを保存する。
this.frames.push(fps);
if (this.frames.length > 100) {
this.frames.shift();
}
// 最新の100個のタイムの最大値、最小値、平均値を求めます。
let min = Infinity;
let max = -Infinity;
let sum = 0;
for (let i = 0; i < this.frames.length; i++) {
sum += this.frames[i];
min = Math.min(this.frames[i], min);
max = Math.max(this.frames[i], max);
}
let mean = sum / this.frames.length;
// fpsに描画する
this.fps.textContent = `
Frames per Second:
latest = ${Math.round(fps)}
avg of last 100 = ${Math.round(mean)}
min of last 100 = ${Math.round(min)}
max of last 100 = ${Math.round(max)}
`.trim();
}
};
//...中略
const renderLoop = () => {
fps.render(); // 追記
universe.tick();
drawGrid();
drawCells();
animationId = requestAnimationFrame(renderLoop);
};
www/index.htmlにも要素を追加します。
<style>
...中略
#fps {
white-space: pre;
font-family: monospace;
}
...中略
</style>
...中略
<div id="fps"></div>
FPSタイマーが実装できました！
console.timeとconsole.timeEndの活用
デバッグを導入した際にインストールしたweb-sysクレートを使えば、console.timeとconsole.timeEndというブラウザ標準の関数の呼び出しも可能になります。
console.time() - Web API | MDN
これを使用することでもタイムプロファイリングが可能になります。
まずは依存関係を追加しましょう。
[dependencies.web-sys]
version = "0.3.64"
features = [
"console",
]
続けて、console.timeとconsole.timeEndの呼び出しを行うTimerトレイトを実装します。
console.timeとconsole.timeEndの呼び出しはセットなため、同じトレイトで完結するようにしています。
extern crate web_sys;
use web_sys::console;
pub struct Timer<'a> {
name: &'a str,
}
impl<'a> Timer<'a> {
pub fn new(name: &'a str) -> Timer<'a> {
console::time_with_label(name);
Timer { name }
}
}
impl<'a> Drop for Timer<'a> {
fn drop(&mut self) {
console::time_end_with_label(self.name);
}
}
これをUniverseのtick関数に適用してあげます。
#[wasm_bindgen]
impl Universe {
//...
pub fn tick(&mut self) {
let _timer = Timer::new("Universe::tick");
//...
}
//...
}
Dropはデストラクタであり、このような形でTimerのインスタンス生成を行うとメソッド内でのみ有効となるようになっています。
これをビルドしてブラウザで見てみましょう。
ちゃんとプロファイリングしています。
前にデバッグでロギングしたときと違ってログ出力が抑えられているおかげか、重くはなりませんでした。
cargo benchを使ってパフォーマンスを上げる
パフォーマンスをどう上げるかを考えるとき、rustのnightlyのみで提供されているbenchマクロを使用する方法があります。
これまでで実装してきた関数で、最も処理が重そうなのはやはりライフゲーム中ずっと走っているUniverse::tick関数でしょう。
この関数を対象にベンチマーク関数を実装しましょう。
その前に、benchマクロはnightlyのみで有効なので、使用している環境にrustupを使用してnightlyをインストールしてあげましょう。
rustup install nightly
インストールされたバージョンを指定するrust-toolchain.tomlを実装してあげましょう。
別に設定しなくても問題はないんですが、後から動かすときやプロジェクトでパッケージを共有する際は必要なものなので、できれば作成しておいたほうがいいでしょう。
rust-toolchain.tomlについてはこちらの記事も見てね
[toolchain]
channel = "nightly-2023-08-03"
ここまで準備できたら実際にベンチマークの実装を行います。
#![feature(test)]
extern crate test;
extern crate wasm_game_of_life;
#[bench]
fn universe_ticks(b: &mut test::Bencher) {
let mut universe = wasm_game_of_life::Universe::new();
b.iter(|| {
universe.tick();
});
}
実装はできましたが、このままベンチマークを動かすことはできません。
#[wasm_bindgen]を一度コメントアウトしてあげましょう。
// #[wasm_bindgen]
#[repr(u8)]
#[derive(Clone, Copy, Debug, PartialEq, Eq)]
pub enum Cell {
//...
}
// #[wasm_bindgen]
pub struct Universe {
//...
}
// #[wasm_bindgen]
impl Universe {
//...
}
次に、Cargo.tomlから"cdylib"もコメントアウトします。
[lib]
crate-type = [
# "cdylib",
"rlib",
]
これで準備ができたので、cargo benchを実行します。
warning: unused macro definition: `log`
--> src/lib.rs:25:14
|
25 | macro_rules! log {
| ^^^
|
= note: `#[warn(unused_macros)]` on by default
warning: `wasm-game-of-life` (lib) generated 1 warning
Finished bench [optimized] target(s) in 0.04s
Running benches/bench.rs (target/release/deps/bench-ea0d54e195fed039)
running 1 test
panicked at /home/username/.cargo/registry/src/index.crates.io-6f17d22bba15001f/web-sys-0.3.64/src/features/gen_console.rs:6:5:
cannot call wasm-bindgen imported functions on non-wasm targets
test universe_ticks ... FAILED
failures:
failures:
universe_ticks
test result: FAILED. 0 passed; 1 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
error: bench failed, to rerun pass `-p wasm-game-of-life --bench bench`
あら、エラーになってしまいました。
いろいろいじってましたが、Timerの実装がいれっぱなしなのが良くなかったみたいです。
impl Universe {
//...
pub fn tick(&mut self) {
// let _timer = Timer::new("Universe::tick");
//...
}
//...
}
ここをコメントアウトしたら動きました。
また、後ほどパフォーマンス改善前と改善後の結果を比較するためにteeコマンドで出力を保存しておきましょう。
% cargo bench | tee before.txt
Compiling wasm-game-of-life v0.1.0 (/home/username/Project/personal/wasm-game-of-life)
warning: unused macro definition: `log`
--> src/lib.rs:25:14
|
25 | macro_rules! log {
| ^^^
|
= note: `#[warn(unused_macros)]` on by default
warning: `wasm-game-of-life` (lib) generated 1 warning
Finished bench [optimized] target(s) in 0.79s
Running benches/bench.rs (target/release/deps/bench-ea0d54e195fed039)
running 1 test
test universe_ticks ... bench: 282,521 ns/iter (+/- 6,317)
test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out; finished in 0.77s
このベンチマークの結果をperfコマンドを使用して解析します。
まずperfコマンドをインストールします。
sudo apt install linux-tools-`uname -r` -y && \
sudo sh -c 'echo -1 >/proc/sys/kernel/perf_event_paranoid' && \
sudo sh -c 'echo 0 > /proc/sys/kernel/kptr_restrict'
ではcargo benchで生成されたベンチマークの実行バイナリを、perfコマンドから実行します。
% perf record -g target/release/deps/bench-ea0d54e195fed039 --bench
running 1 test
test universe_ticks ... bench: 286,389 ns/iter (+/- 8,756)
test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out; finished in 1.83s
[ perf record: Woken up 2 times to write data ]
[ perf record: Captured and wrote 0.473 MB perf.data (7327 samples) ]
実行すると、実行したディレクトリ上にperf.dataというファイルが作成されます。
このファイルが存在するディレクトリ上でperf reportを実行すると、perf.dataのバイナリを可視化してくれます。
所謂TUIってやつですね。かっこいい。
左側のパーセンテージ表示から、ほぼすべての時間がUniverse::tickに費やされていることが分かります。(99.60%)
対象の行でaを押すと、更に詳細にどこで時間を使っているのかを見ることができます。
アセンブラ感が漂ってきますね。
赤くなっている部分が特にCPU時間を使っている部分なんですが、div命令の箇所が特に時間を使ってしまっているようです。
divによる計算処理はlive_neighbor_count関数内で行っていますが、いま現時点だとこの計算方法はかなり無駄な部分が多いです。
そもそも余剰を使用した計算方法をしていたのは、左上から右下のような端から端への動きを表現するのにifを使うとかなりごちゃつくため、余剰を使用していたのでした。（ほぼコピペしてたから知らんかった）
ということで、この辺をifを使用した作りに切り替えます。
fn live_neighbor_count(&self, row: u32, column: u32) -> u8 {
let mut count = 0;
let north = if row == 0 {
self.height - 1
} else {
row - 1
};
let south = if row == self.height - 1 {
0
} else {
row + 1
};
let west = if column == 0 {
self.width - 1
} else {
column - 1
};
let east = if column == self.width - 1 {
0
} else {
column + 1
};
let nw = self.get_index(north, west);
count += self.cells[nw] as u8;
let n = self.get_index(north, column);
count += self.cells[n] as u8;
let ne = self.get_index(north, east);
count += self.cells[ne] as u8;
let w = self.get_index(row, west);
count += self.cells[w] as u8;
let e = self.get_index(row, east);
count += self.cells[e] as u8;
let sw = self.get_index(south, west);
count += self.cells[sw] as u8;
let s = self.get_index(south, column);
count += self.cells[s] as u8;
let se = self.get_index(south, east);
count += self.cells[se] as u8;
count
}
では再度cargo benchを走らせてみましょう。
% cargo bench | tee after.txt
Compiling wasm-game-of-life v0.1.0 (/home/username/Project/personal/wasm-game-of-life)
warning: unused macro definition: `log`
--> src/lib.rs:25:14
|
25 | macro_rules! log {
| ^^^
|
= note: `#[warn(unused_macros)]` on by default
warning: `wasm-game-of-life` (lib) generated 1 warning
warning: `wasm-game-of-life` (lib test) generated 1 warning (1 duplicate)
Finished bench [optimized] target(s) in 2.51s
Running unittests src/lib.rs (target/release/deps/wasm_game_of_life-8cf4cfb87fcb0354)
running 0 tests
test result: ok. 0 passed; 0 failed; 0 ignored; 0 measured; 0 filtered out; finished in 0.00s
Running benches/bench.rs (target/release/deps/bench-ea0d54e195fed039)
running 1 test
test universe_ticks ... bench: 85,930 ns/iter (+/- 18,306)
test result: ok. 0 passed; 0 failed; 0 ignored; 1 measured; 0 filtered out; finished in 3.97s
ではこの結果を比較するためのツールをインストールしておきます。
GitHub - BurntSushi/cargo-benchcmp: A small utility to compare Rust micro-benchmarks.
cargo install cargo-benchcmp
インストールできたら、ベンチマークの結果を比較してみます。
% cargo benchcmp before.txt after.txt
name bench_before.txt ns/iter bench_after.txt ns/iter diff ns/iter diff % speedup
universe_ticks 282,521 85,930 -196,591 -69.58% x 3.29
3.29倍になっていました！
まとめ
アセンブリが初めて役立ったような気がします。
パフォーマンス向上にベンチマークを使って、アセンブリ読んでパフォーマンスが上がるという体験ができたことがすごく嬉しいです。
アセンブリ勉強しようかな…。