Rustのプロファイリングをpprofで行う

この記事はHRBrainアドベントカレンダーの15日目の記事です。

qiita.com

こんにちは、バックエンドエンジニアの稲垣です。

弊社のバックエンドエンジニアにはGoが得意なエンジニアが多く、サービスのほとんどはGoで実装されています。

自分も直近5年くらいはずっとGoを使ってきました。

ところで、皆さんはGoのどんなところが好きでしょうか?

.........

......

...

うんうん、そうですよね、わかります、いいですよね。

自分はエコシステムが充実しているところがお気に入りポイントで、特に pprof のことが、和風オムライスと同じくらい好きです。

pprofを使っているときって、なんかスーパーハッカーになったみたいでいいですよね。

f:id:ingtk:20201215154852p:plain

pprofで見れるCUI画面はとても使いやすく、自分もpprofでボトルネックを発見したことがあります。

なんとなくpprofがすんなり使えるのってGoを使っている恩恵っぽいですよね?

でも、他の言語でも使いたいなーと思ったことはないでしょうか?

最近自分は、Goと同じくらいRustを書く機会があって、Rustでもpprofを使いたいなーって思ってました。

そこで探してみたところ、以下のようなツールを見つけました。

github.com

pprofはprofile.proto形式のプロファイルを読み込ませて分析しているようで、上記のツールはprofile.proto形式の出力をサポートしているようです。

なんかいけそうです!上記のリポジトリのexampleで早速試してみましょう。

exampleの中には素数判定のコードがあります。パフォーマンス・チューニングのサンプル実装あるあるですね。

コードの中にはいろいろ書かれていますが、プロファイルを出力するのに必要なコードは以下の箇所だけです。

何これ簡単。

...

fn main() {
    
    ...

    let guard = pprof::ProfilerGuard::new(100).unwrap();

    ...

    match guard.report().build() {
        Ok(report) => {
            let mut file = File::create("profile.pb").unwrap();
            let profile = report.pprof().unwrap();

            let mut content = Vec::new();
            profile.encode(&mut content).unwrap();
            file.write_all(&content).unwrap();

            println!("report: {:?}", report);
        }
        Err(_) => {}
    };
}

さて実行してみます。profile.pbが出力されていれば成功です。

(この記事書いている時ににしったのですが、example配下を直接cargo runで実行できるのですね)

$ cargo run --example=profile_proto --features="protobuf"
...

$ ls -l  profile.pb
profile.pb

いました、楽勝です。

でもpprofで使えないと意味がありません。

おそるおそるpprofコマンドを実行します。

Gopherの自分は go tool pprof が使えるので、これで実行します。

$ go tool pprof profile.pb
Type: cpu
Entering interactive mode (type "help" for commands, "o" for options)
(pprof) top30 -cum
Showing nodes accounting for 1189, 100% of 1189 total
Dropped 15 nodes (cum <= 5)
      flat  flat%   sum%        cum   cum%
      1189   100%   100%       1189   100%  backtrace::backtrace::libunwind::trace
         0     0%   100%       1189   100%  backtrace::backtrace::trace_unsynchronized
         0     0%   100%       1188 99.92%  _main
         0     0%   100%       1188 99.92%  std::panic::catch_unwind
         0     0%   100%       1188 99.92%  std::panicking::try
         0     0%   100%       1188 99.92%  std::panicking::try::do_call
         0     0%   100%       1188 99.92%  std::rt::lang_start
         0     0%   100%       1188 99.92%  std::rt::lang_start::{{closure}}
         0     0%   100%       1188 99.92%  std::rt::lang_start_internal
         0     0%   100%       1188 99.92%  std::rt::lang_start_internal::{{closure}}
         0     0%   100%       1165 97.98%  profile_proto::main
         0     0%   100%        566 47.60%  profile_proto::is_prime_number2
         0     0%   100%        555 46.68%  profile_proto::is_prime_number3
         0     0%   100%        469 39.44%  <core::slice::Iter<T> as core::iter::traits::iterator::Iterator>::next
         0     0%   100%        452 38.02%  <usize as core::ops::arith::Rem<&usize>>::rem
         0     0%   100%        420 35.32%  <usize as core::ops::arith::Rem>::rem
         0     0%   100%        167 14.05%  core::slice::Iter<T>::post_inc_start
         0     0%   100%        109  9.17%  core::ptr::non_null::NonNull<T>::as_ptr
         0     0%   100%         57  4.79%  core::ptr::mut_ptr::<impl *mut T>::offset
         0     0%   100%         56  4.71%  core::ptr::mut_ptr::<impl *mut T>::is_null
         0     0%   100%         53  4.46%  core::ptr::const_ptr::<impl *const T>::is_null
         0     0%   100%         34  2.86%  core::ptr::non_null::NonNull<T>::new_unchecked
         0     0%   100%         15  1.26%  core::mem::size_of
         0     0%   100%         11  0.93%  core::iter::range::<impl core::iter::traits::iterator::Iterator for core::
ops::range::Range<A>>::next
         0     0%   100%         11  0.93%  core::slice::<impl [T]>::iter
         0     0%   100%         10  0.84%  core::slice::<impl core::iter::traits::collect::IntoIterator for &[T]>::in
to_iter
         0     0%   100%          7  0.59%  profile_proto::is_prime_number1

きました!

自分は topX -cumlist コマンドを多用するので、listも試してみます!

│(pprof) list profile_proto::main
│Total: 1189
│ROUTINE ======================== profile_proto::main in github.com/tikv/pprof-rs/exampl
│es/profile_proto.rs
│         0       1165 (flat, cum) 97.98% of Total
│         .          .     88:        if i % 4 == 0 {
│         .          .     89:            if is_prime_number1(i, &prime_numbers) {
│         .          .     90:                v += 1;
│         .          .     91:            }
│         .          .     92:        } else if i % 4 == 1 {
│         .       1165     93:            if is_prime_number2(i, &prime_numbers) {
│         .          .     94:                v += 1;
│         .          .     95:            }
│         .          .     96:        } else {
│         .          .     97:            if is_prime_number3(i, &prime_numbers) {
│         .          .     98:                v += 1;

おお、すごい、しっかり表示されてますね。

pprofコマンドが使えるので当然graph表示もできます。

$ go tool pprof -svg profile.pb
Main binary filename not available.
Generating report in profile001.svg

出力されたsvgを開くとちゃんとグラフが作成されています。

f:id:ingtk:20201215155915p:plain

これで、Rust使っててもGoと同じようなプロファイリング体験ができ、なおかつスーパーハッカー気分を味わえそうです。

f:id:ingtk:20201215153359p:plain

ちなみにREADMEを読んでいただけるとわかりますが、Flamegraphも出力することができます。

自分はFlamegraphを凝視していると目が回って気持ち悪くなってくるので、ここでは割愛しますが、興味のある方はぜひやってみてください。