meteredクレートの紹介

そもそもの問題

Rustで処理を書いていて、なんかちょっと遅いな?どこの処理で時間がかかってるんだろう? ということがありませんか?ありますよね?

というのを調べるために、最初に思いつくのは自分で計測する方法です。流石にそれはなぁ、と思ったのでググって出てきた方法を最初は使っていました。

Rustで実行時間計測

3年前の記事ですが、とりあえず計測する分には問題なかったのでこちらの方が書いていたマクロを拝借していました。が、ちょっと面倒なのが戻り値がある処理などのときに、このマクロを挟むのが結構めんどくさいなと。また、処理の時間を測りたいのは基本的にはメソッドや関数単位であることが多いです。

で、さらにググっていて見つけたのが、meteredでした。

どんなもの?

計測したい部分に#[metric]のようなアノテーションを追加することで計測対象としてくれます。あとは、計測したものを保存するレジストリという場所を指定するだけです。処理が終わったタイミングなどで、そのレジストリの内容を出力することで、次の情報を計測することができます。

HitCount : 実行された回数
ErrorCount : エラーを返した数(Resultを戻り値にしているメソッドが対象)
InFlight : 処理中の回数かな?
ResponseTime : レスポンスタイム(処理に何秒かかったか)
Throughput : スループット(1秒あたり何回呼ばれたか)

とりあえず試してみたのは、ResponseTimeとThroughputです。他のメトリクスはまた後日(機会があれば)。また、metered::metric::Metricトレイトというものが用意されているようで、これを実装した独自のメトリクスも扱うことができるようです。

使い方

使い方としては次のようになります。

計測対象となるメソッドがある構造体に、メトリクスを保持するためのレジストリを用意
計測対象にしたい構造体のメソッドに#[measure]を追加(このとき、計測したいものも指定する。)

あとは、実行したあとに構造体をダンプするとメトリクスが出力されます。

レジストリの用意

#[derive(Default, Debug, Serialize)]
pub struct NekoParser {
    metric_reg: NekoParserMetricRegistry,
}

NekoParserMetricRegistryという型はこのあとのimplのアノテーションで指定する名前になります。実際にはこの型の構造体を自分で定義する必要はありません。構造体のderiveでDefaultを指定します。構造体のインスタンス化のときにdefault()メソッドを呼び出して初期化したいためです(おそらくレジストリの初期化をやってくれるのだと思う(要確認))。レジストリの用意はこれだけです。

レジストリの指定と計測対象の指定

計測対象側です。少し長いですが、NekoParserのメソッドすべてを掲載しました。まずは、1行目でレジストリの名前の指定(registry = NekoParserMetricRegistry)、レジストリのフィールド名(registry_expr = self.metric_reg)、レジストリの可視性(visibility = pub(self))を定義します。 2行目では、implブロック全体で計測したいメトリクスを指定しています。今回は、スループットとレスポンスタイムを計測したかったので #measure([ResponseTime, Throughput])]と2種類を指定しています。メトリクスが2種類のため配列で指定していますが、1種類だけの場合は[]の記号は必要ありません。

あとは、計測したい各メソッドに#[measure]をつけるだけです。なお、メソッドごとに#[measure(ErrorCount)]といったかたちで個別にメトリクスを指定することも可能です。今回はお試しということもあり、すべて#[measure]だけになっています。アノテーションを付けただけで、メソッド自体を変更はしていません。

#[metered(registry = NekoParserMetricRegistry, registry_expr = self.metric_reg, visibility = pub(self))]
#[measure([ResponseTime, Throughput])]
impl NekoParser {
    #[measure]
    pub fn load_and_parse_neko(&self) {
        let file_path = "./data/chap04/neko.txt";
        let file = File::open(file_path).unwrap();
        let buf = BufReader::new(file);
        let mut out = File::create("./data/chap04/neko.txt.lindera.json").unwrap();
        buf.lines().filter_map(|item| item.ok()).for_each(|line| {
            let tokens = self.tokenize(line.as_str());
            self.output_tokens(&tokens, &mut out);
        });
    }

    #[measure]
    pub fn output_tokens(&self, tokens: &Vec<Token>, buf: &mut File) {
        writeln!(buf, "{}", serde_json::to_string(tokens).unwrap())
            .expect("Error during output json");
    }

    #[measure]
    pub fn tokenize(&self, line: &str) -> Vec<Token> {
        let mut tokenizer = lindera::tokenizer::Tokenizer::new("normal", "");
        let lindera_tokens = tokenizer.tokenize(line);
        let tokens = lindera_tokens
            .iter()
            .map(|lindera_token| {
                let surface = lindera_token.text.to_string();
                let pos = lindera_token.detail[0].to_string();
                let pos1 = if pos != "UNK" {
                    lindera_token.detail[1].to_string()
                } else {
                    String::new()
                };
                let base = if pos != "UNK" {
                    lindera_token.detail[6].to_string()
                } else {
                    String::new()
                };
                Token {
                    surface,
                    base,
                    pos,
                    pos1,
                }
            })
            .collect();
        return tokens;
    }
}

計測結果の出力

最後は計測結果の出力です。今回はテストメソッドで実行して結果を出力する処理を書きました。

let parser = NekoParser::default();で構造体をインスタンス化します。あとは、処理をそのまま実行します。

最後に出力結果をJSON形式の文字列にしてから出力しました。 let serialized ... println!("{}", serialized);という形です。簡単ですね!

#[cfg(test)]
mod tests {
    use crate::chapter04::answer::NekoParser;
    use std::path::Path;
    #[test]
    fn success_output_tokenlists() {
        let parser = NekoParser::default();
        parser.load_and_parse_neko();
        let serialized = serde_json::to_string(&parser).unwrap();
        println!("{}", serialized);
        assert!(Path::new("./data/chap04/neko.txt.lindera.json").exists());
    }
}

出力結果

ここまで紹介したものの実行結果は次のような形でした。レスポンスタイム、スループットともに、最小、最大、99パーセンタイルなどを出力してくれます。出力はメソッド名ごとにくくられているのでとても便利です。

{
    "metric_reg": {
        "load_and_parse_neko": {
            "response_time": {
                "samples": 1,
                "min": 176128,
                "max": 177151,
                "mean": 176640.0,
                "stdev": 0.0,
                "90%ile": 177151,
                "95%ile": 177151,
                "99%ile": 177151,
                "99.9%ile": 177151,
                "99.99%ile": 177151
            },
            "throughput": {
                "samples": 0,
                "min": 0,
                "max": 0,
                "mean": 0.0,
                "stdev": 0.0,
                "90%ile": 0,
                "95%ile": 0,
                "99%ile": 0,
                "99.9%ile": 0,
                "99.99%ile": 0
            }
        },
        "output_tokens": {
            "response_time": {
                "samples": 9964,
                "min": 0,
                "max": 143,
                "mean": 0.03592934564431955,
                "stdev": 1.5152489085107463,
                "90%ile": 0,
                "95%ile": 0,
                "99%ile": 0,
                "99.9%ile": 6,
                "99.99%ile": 143
            },
            "throughput": {
                "samples": 174,
                "min": 39,
                "max": 71,
                "mean": 57.103448275862064,
                "stdev": 3.8417981983375835,
                "90%ile": 60,
                "95%ile": 61,
                "99%ile": 64,
                "99.9%ile": 71,
                "99.99%ile": 71
            }
        },
        "tokenize": {
            "response_time": {
                "samples": 9964,
                "min": 12,
                "max": 79,
                "mean": 16.897230028101177,
                "stdev": 2.331145559054724,
                "90%ile": 19,
                "95%ile": 20,
                "99%ile": 24,
                "99.9%ile": 46,
                "99.99%ile": 79
            },
            "throughput": {
                "samples": 174,
                "min": 39,
                "max": 71,
                "mean": 57.103448275862064,
                "stdev": 3.819293076427424,
                "90%ile": 60,
                "95%ile": 61,
                "99%ile": 64,
                "99.9%ile": 71,
                "99.99%ile": 71
            }
        }
    }
}

出力内容で気になったのはoutput_tokensとtokenizeのthroughputが全く同じ結果が出ていることです。なにかバグを踏んでいる気がします。。。(時間を見つけてソースコード読んでみるか。)

気をつけること

meteredの導入時にわかりにくいコンパイルエラーが出たので備忘録として残しておきます。 (下からコンパイルエラーを読んでしまうくせがあったのが問題なのですが。。。) エラーメッセージは次のとおりです。

error[E0412]: cannot find type `ResponseTime` in this scope
  --> src/chapter04/answer.rs:13:12
   |
13 | #[measure([ResponseTime, Throughput])]
   |            ^^^^^^^^^^^^ not found in this scope
   |
help: consider importing one of these items
   |
1  | use metered::ResponseTime;
   |
1  | use metered::common::ResponseTime;
   |

error[E0283]: type annotations needed
  --> src/chapter04/answer.rs:12:1
   |
12 | #[metered(registry = NekoParserMetricRegistry, /* default = self.metrics */ registry_expr = self.metric_reg)]
   | ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ cannot infer type
   |
   = note: cannot satisfy `_: std::default::Default`
   = note: required by `std::default::Default::default`
   = note: this error originates in a derive macro (in Nightly builds, run with -Z macro-backtrace for more info)

最初のメッセージにはわかりやすく出ていますが、ResponseTimeをuseせずに利用しようとした場合に以下のようなエラーが出ていました。ターミナル画面が狭かったのでE0283のエラーが目に入り、何を言ってるんだろう?という状態になってしまいました。スクロールアップしたら、答えが載っているのに。。。

コード全体

元ネタはNLP100本ノックの第4章です。コードの全体はGitHubのソースをご覧ください。

まとめ

meteredを簡単ですが紹介してみました。導入自体も簡単で、想像していたような使い方ができたので満足しています。ほかにもプロファイラなどはあるのかもしれませんが、まずはこれを使っていこうかと思っています。

バグらしきものがありそうだったりするので、そのへんは今後調査してみようかと。まだ、ちょっと試してみただけなので、metered自体のオーバーヘッドや、独自のメトリクスの実装方法、メソッドではなく関数に対して利用する場合にはどうするのか?などいくつか疑問点があるので、今後試してみてまたブログに残しておこうと思います。