κeenのHappy Hacκing Blog | Lispエイリアンの狂想曲
☰

cargo-profilerを試す

κeenです。先日Rustのニュースに流れてきたcargo profilerを試してみます。 元の紹介記事はこちらIntroducing Cargo Profiler · suchin。

GitHubレポジトリはこちらpegasos1/cargo-profiler: cargo subcommand to profile binaries。

Profilerとはいっても自身でプロファイラを持っている訳ではなくて外部のプロファイラ（現状valgrind）を呼び出して整形してくれるツールのようです。 Rust向けに関数をモジュールパス付きで表示してくれたりするのでRustから使うにはvalgrind生より便利そうです。

インストール

READMEに従って

$ sudo apt install valgrind
$ cargo install cargo-profiler

とします。

プロジェクトの準備

適当なものがないので手元のκLispでフィボナッチ数列を動かしてみます。(と思ったらκLispに比較演算子がなかったのでそれを作るところから始まりましたがそれはまた別の話)。

main.rsはこんな感じ。

extern crate kappa_lisp;
use kappa_lisp::kappa_lisp::{run, init};
use kappa_lisp::env::Env;

fn main() {
    let mut env = Env::new();
    init(&mut env).unwrap();
    run(&mut env, r"
(defun fib (n)
  (if (< n 2)
      1
      (+ (fib (- n 1)) (fib (- n 2)))))
").unwrap();
    let expr = run(&mut env, r" (fib 20) ").unwrap();
    println!("{}", expr);
}

割と遅いので20くらいで限界でした。

さて、これを

cargo build --release

としてビルドします。

プロファイル

今のところcallgrindとcachegrindが実装されているようです。1つづづ試してみます。

callgrind

よく分かってないのですが多分実行時間に占める関数毎の割合を出してくれるんですかね。-nで上位何件を表示するか指定出来ます。

とりあえず上位10件出してみましょう。

$ cargo profiler callgrind --bin ./target/release/kappa_lisp -n 10
Profiling kappa_lisp with callgrind...

Total Instructions...571,437,255

142,527,726 (24.9%) ???:collections::hash::table::make_hash
-----------------------------------------------------------------------
107,551,309 (18.8%) ???:hash::sip::SipHasher.Hasher::write
-----------------------------------------------------------------------
39,749,571 (7.0%) ???:collections::hash::map::HashMap..K$C$..V$C$..S..::get
-----------------------------------------------------------------------
38,693,006 (6.8%) ???:sdallocx
-----------------------------------------------------------------------
37,670,732 (6.6%) ???:mallocx
-----------------------------------------------------------------------
34,608,049 (6.1%) ???:expr..Expr::drop.9629
-----------------------------------------------------------------------
26,539,906 (4.6%) ???:eval::eval
-----------------------------------------------------------------------
19,887,024 (3.5%) ???:util::f_foldr
-----------------------------------------------------------------------
16,634,175 (2.9%) ???:eval::feval
-----------------------------------------------------------------------
14,353,992 (2.5%) ???:util::kcons
-----------------------------------------------------------------------

はい、こんな感じです。ハッシュテーブル関連が時間喰ってますね。これは関数呼び出しの度に行われてます。 ちょっと実装が雑すぎるので直さなきゃ…。

cachegrind

キャッシュミスを表示してくれます。本気出してチューニングする時に必要ですね。

同じく -nで件数を絞り込めます。

cargo profiler cachegrind --bin ./target/release/kappa_lisp -n 10  


Profiling kappa_lisp with cachegrind...

Total Memory Accesses...800,070,388	

Total L1 I-Cache Misses...100,068 (0%)	
Total LL I-Cache Misses...422 (0%)	
Total L1 D-Cache Misses...4,346,335 (0%)	
Total LL D-Cache Misses...7,724 (0%)	

 Ir  I1mr ILmr  Dr  D1mr DLmr  Dw  D1mw DLmw
0.25 0.00 0.02 0.09 0.00 0.01 0.11 0.05 0.06 ???:collections::hash::table::make_hash
-----------------------------------------------------------------------
0.19 0.00 0.03 0.13 0.00 0.00 0.11 0.01 0.01 ???:hash::sip::SipHasher.Hasher::write
-----------------------------------------------------------------------
0.07 0.00 0.01 0.13 0.06 0.01 0.07 0.00 0.00 ???:expr..Expr::drop.9629
-----------------------------------------------------------------------
0.07 0.00 0.01 0.10 0.08 0.00 0.12 0.03 0.04 ???:collections::hash::map::HashMapK$C$V$C$S::get
-----------------------------------------------------------------------
0.07 0.00 0.03 0.09 0.01 0.00 0.03 0.00 0.00 ???:sdallocx
-----------------------------------------------------------------------
0.07 0.02 0.03 0.11 0.02 0.01 0.04 0.01 0.01 ???:mallocx
-----------------------------------------------------------------------
0.05 0.06 0.20 0.06 0.29 0.21 0.09 0.25 0.16 ???:eval::eval
-----------------------------------------------------------------------
0.03 0.00 0.03 0.04 0.14 0.15 0.09 0.13 0.09 ???:util::f_foldr
-----------------------------------------------------------------------
0.03 0.02 0.05 0.04 0.05 0.00 0.02 0.06 0.05 ???:eval::feval
-----------------------------------------------------------------------
0.03 0.00 0.02 0.03 0.00 0.01 0.08 0.05 0.09 ???:util::kcons
-----------------------------------------------------------------------

やはりハッシュテーブルが酷いですが同じコードを繰り返し実行するタイプのマイクロベンチマークなのでキャッシュミスは少ないです。

因みにそれぞれの列はこういう意味だそうです。

  • Ir -> Total Instructions
  • I1mr -> Level 1 I-Cache misses
  • ILmr -> Last Level I-Cache misses
  • Dr -> Total Memory Reads
  • D1mr -> Level 1 D-Cache read misses
  • DLmr -> Last Level D-cache read misses
  • Dw -> Total Memory Writes
  • D1mw -> Level 1 D-Cache write misses
  • DLmw -> Last Level D-cache write misses

--sort オプションでどの列をみるのか指定出来るようです。全メモリアクセスのミスレートを見てみましょうか。

$ cargo profiler cachegrind --bin ./target/release/kappa_lisp -n 10 --sort dr


Profiling kappa_lisp with cachegrind...

Total Memory Accesses...800,082,686	

Total L1 I-Cache Misses...100,083 (0%)	
Total LL I-Cache Misses...420 (0%)	
Total L1 D-Cache Misses...4,321,895 (0%)	
Total LL D-Cache Misses...7,721 (0%)	

 Ir  I1mr ILmr  Dr  D1mr DLmr  Dw  D1mw DLmw
0.19 0.00 0.03 0.13 0.00 0.00 0.11 0.01 0.01 ???:hash::sip::SipHasher.Hasher::write
-----------------------------------------------------------------------
0.07 0.00 0.01 0.13 0.06 0.01 0.07 0.00 0.00 ???:expr..Expr::drop.9629
-----------------------------------------------------------------------
0.07 0.02 0.03 0.11 0.02 0.01 0.04 0.01 0.01 ???:mallocx
-----------------------------------------------------------------------
0.07 0.00 0.01 0.10 0.08 0.00 0.12 0.03 0.04 ???:collections::hash::map::HashMapK$C$V$C$S::get
-----------------------------------------------------------------------
0.25 0.00 0.02 0.09 0.00 0.01 0.11 0.05 0.06 ???:collections::hash::table::make_hash
-----------------------------------------------------------------------
0.07 0.00 0.03 0.09 0.01 0.00 0.03 0.00 0.00 ???:sdallocx
-----------------------------------------------------------------------
0.05 0.06 0.20 0.06 0.29 0.21 0.09 0.25 0.16 ???:eval::eval
-----------------------------------------------------------------------
0.03 0.00 0.03 0.04 0.14 0.15 0.09 0.13 0.09 ???:util::f_foldr
-----------------------------------------------------------------------
0.03 0.02 0.05 0.04 0.04 0.00 0.02 0.06 0.05 ???:eval::feval
-----------------------------------------------------------------------
0.03 0.00 0.02 0.03 0.00 0.01 0.08 0.05 0.09 ???:util::kcons
-----------------------------------------------------------------------

やっぱりハッシュテーブル関連が重い…。

まとめ

私にとっては薮蛇にκLispの実装の筋が悪いことが分かったりしてショックでしたがまあ、簡単にプロファイルをとれるツールを紹介しました。

Rustで高速なアプリケーションを作りたい方、利用してみては如何でしょうか。

Written by κeen
Later article
DOT/dottyについて調べてみた
Older article
高速な継続ライブラリに向けて