C++のラムダ式とマクロで経過時間を手軽に測定

C++11では、標準ライブラリ [std::chrono](http://www.cplusplus.com/reference/chrono/) が入ったおかげで、**精密な時間測定**（Elapsed Time）を、**OS非依存**で書けるようになりましたね。

さらに **ラムダ式とマクロを組み合わせる** と、とても簡単に、時間測定できるようになります。

# 1. 例題

最初に、円周率πを求めるコードを例に、どのように時間測定コードを挿入できるか示します。
★が時間測定用コードの埋め込み部分です。

```cpp:例題｜円周率πを求めるコード
#include <iostream>
#include <cmath>

//#define NO_TIME_ELAPSED_MEASUREMENT ★
#include "TimeElapsed.hpp" ★

#define	EPSILON 0.000000001

int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

★TIME_ELAPSED(
    do {
        d += 2; qpi -= 1.0 / d;
        d += 2; qpi += 1.0 / d;
    } while (qpi-target > EPSILON);
★);

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

実行すると、標準出力に「ファイル名・行番号・経過時間」が出力されます。

```text
3.14159265358979
ElapsedTime: pi4.cpp at L.25   2060.002 msec
3.14159265758979
```

例題中でコメントアウトされた `NO_TIME_ELAPSED_MEASUREMENT` を有効化すると、即、性能測定を無効化できます。

```text
3.14159265358979
3.14159265758979
```

コードからわかるように、**元のプログラムへの改変が少ない**ので、テストなどに便利です。[^1]
なお、`TIME_ELAPSED()` はヘッダーファイル `TimeElapsed.hpp` で定義しています。


# 2. 既存の関数ポインタやマクロとは、何が違う？

ここまでシンプルな性能測定コードのインジェクションは、**C++11のラムダ式により初めて可能** になりました。

単なる関数（関数ポインタ）や関数オブジェクト、マクロでは、上記の例のように簡単に書くことはできません。
実際にそれらを試して、比較してみます。


## 2.1. 直接埋め込んでみる

最初に、素直に時間測定コードを元プログラムに埋め込んでみます。
複雑さを見るためのベースとします。

```cpp:時間測定コードを直接埋め込む（★部分）
int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

★auto t0 = std::chrono::high_resolution_clock::now();

    do {
        d += 2; qpi -= 1.0 / d;
        d += 2; qpi += 1.0 / d;
    } while (qpi-target > EPSILON);

★auto t1 = std::chrono::high_resolution_clock::now();
★auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count();
★std::cout << elapsed << " msec" << std::endl;

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

このように沢山コードを書かなければいけないし、テンポラリ変数 `t0` や `t1` が周辺に影響しないか注意が必要です。
沢山の箇所に測定が必要だと、測定用コードがノイズとなり、プログラムの可読性が低下するのも問題です。


## 2.2. 関数ポインタを利用してみる

もし、関数の処理時間を測定するだけで事足りるのなら、その関数を時間測定コードから呼び出すのが素直です。時間測定コードに、測定対象の関数のポインタを渡します。

しかし、関数ポインタは、引数や戻り値の型といったシグニチャ情報を持つので、昔ならシグニチャ毎に時間測定コードを書かなければなりませんでした。

C++11なら、可変長テンプレート（Variadic Templates）を駆使して、シグニチャの問題を回避できます。

```cpp:関数ポインタを利用
// 性能測定用の関数： Variadic Templateバージョン
template<typename inner_loop, typename ... FuncArgs>
void measure_elapsed_fptr(inner_loop &body, FuncArgs & ... args)
{
    auto t0 = std::chrono::high_resolution_clock::now();
    body(args...);
    auto t1 = std::chrono::high_resolution_clock::now();

    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count();
    std::cout << elapsed << " msec" << std::endl;
}

// 測りたいコードブロックを関数化したもの
void inner_loop(long long int &d, double &qpi, double &target)
{
    do {
        d += 2; qpi -= 1.0 / d;
        d += 2; qpi += 1.0 / d;
    } while (qpi - target > EPSILON);
}

int main(void)
{
    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

    // 関数ポインタを利用した性能測定
    // inner_loop(d,qpi,target) を代替
    measure_elapsed_fptr(inner_loop,d,qpi,target);

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

プログラムのメインパスから、時間測定用のコードを追い出すことができました。

しかし、関数内のコードブロックの一区間だけを時間測定したい場合には、手軽な方法ではありません。

第一に関数化しなければならないし（コーディング規約等でドキュメントも必要？）、測定区間の前後と干渉する変数は、参照タイプの引数として渡さなければならない。なにより、機能性やアーキテクチャといった「あるべき設計仕様」とは異なる理由で、関数が増えてしまうのは、余計な保守コストにつながります。

さらに、既存プログラムに性能測定コードをインジェクションする場合、元プログラムに大幅な変更が必要となり、リグレッション・リスクなど、現実的でないでしょう。



## 2.3. 関数オブジェクトを利用してみる

関数オブジェクトは “その場” で定義できることが、メリットです。
関数ポインタのように、測定したいコードブロックを外部に持ちださなくて済みます。


```cpp:関数オブジェクトを利用
// 性能測定用関数
template<typename inner_loop>
void measure_elapsed_fobj(inner_loop &body)
{
    auto t0 = std::chrono::high_resolution_clock::now();
    body();
    auto t1 = std::chrono::high_resolution_clock::now();

    auto elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count();
    std::cout << elapsed << " msec" << std::endl;
}

int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

    struct inner_loop {
        void operator()(void) {

            do {
                d += 2; qpi -= 1.0 / d;
                d += 2; qpi += 1.0 / d;
            } while (qpi - target > EPSILON);

        }
        inner_loop(long long int &d_, double &qpi_, double &target_)
            : d(d_), qpi(qpi_), target(target_) {};
        long long int & d;
        double & qpi, & target;
    };

    // 関数オブジェクトを生成し性能測定
    measure_elapsed_fobj(inner_loop(d,qpi,target));

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

実際やってみると、見た目の侵食率は「直接埋め込んだほうがマシ」のようです。

マクロを組み合わせると見た目は少し改善できますが、外側と干渉する変数 `d`、`qpi`、`target` の変数名と型情報を抽出して、マクロ引数としなければならないのは、回避できそうにありません（autoで頑張っても）。



## 2.4. マクロで書いてみる

素直にマクロで書くと、見た目の侵食率は低く抑えることができます
変数名の衝突を避けるため、トークン連結演算子`##`を使います。


```
#define TIME_ELAPSED_START(x)   auto x##0 = std::chrono::high_resolution_clock::now()
#define TIME_ELAPSED_END(x)     auto x##1 = std::chrono::high_resolution_clock::now();\
                                auto x##elapsed = std::chrono::duration_cast<std::chrono::milliseconds>(x##1 - x##0).count();\
                                std::cout << x##elapsed << " msec" << std::endl

int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

    TIME_ELAPSED_START(POINT0);

    do {
        d += 2; qpi -= 1.0 / d;
        d += 2; qpi += 1.0 / d;
    } while (qpi-target > EPSILON);

    TIME_ELAPSED_END(POINT0);

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

ローテクですが、意外に見やすく、実用的です。

しかし、問題もあります。

 1. ラベルのように見せている`POINT0`は苦肉の策（本当は一時変数の衝突を避けるためのPrefix）
 2. `TIME_ELAPSED_END` を忘れても、エラーをキャッチできない
 3. IDEがついてこられない（上記コードは VisualStudio 2013ではIntelliSenseエラーとなりました）
 4. もっと高度なことをすると `TIME_ELAPSED_END` が際限なく複雑になり、保守困難になる

特に４番目が深刻で、極々限られたケースでのダーティー・ハック向けでしょう。
長生きするプロダクション・コードで使ってしまうと、数年後に後悔しそう。


# 3. ラムダ式で解決

ラムダ式とは、任意のコードブロックを **「実行環境まるごと切り出し」**[^2]、別の場所やタイミングで実行できる仕組み。
他言語には昔からあるクロージャの一種です。

 - [Wikipedia: クロージャ](http://ja.wikipedia.org/wiki/%E3%82%AF%E3%83%AD%E3%83%BC%E3%82%B8%E3%83%A3)

この **「実行環境まるごと切り出す」** 能力のお陰で、ラムダ式内のコードが参照する変数を、元スコープの変数に自動的にバインドできます。わざわざ引数にしなくてもアクセスでき、関数オブジェクトの大きな弱点[^3]を解消できます。


## 3.1. ラムダ式で切り出す

例題プログラムの性能測定区間を、ラムダ式使って、切り出してみます。

```cpp:測定したい部分をラムダ式を使ってみる
int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

    auto lambda = [&]{
        do {
            d += 2; qpi -= 1.0 / d;
            d += 2; qpi += 1.0 / d;
        } while (qpi-target > EPSILON);
    };

    // 引数に渡さなくとも、d,qpi,target を元のスコープの変数へ自動でバインド
    lambda();

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

これだけでも、すごくクリーン。
元のプログラムの侵蝕率、可読性の悪化が少ない。 :blush:


## 3.2. 時間測定用の関数

更に時間測定用の関数へ、切り出したラムダ式を渡して、そこで実行する。

```cpp:ラムダ式を利用した時間測定コード
template <typename inner_loop>
void time_elapsed_lambda(inner_loop body)
{
    auto t0 = std::chrono::high_resolution_clock::now();
    body();
    auto t1 = std::chrono::high_resolution_clock::now();

    std::cout << std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count() << " msec" << std::endl;
}


int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

    time_elapsed_lambda([&]{

        do {
            d += 2; qpi -= 1.0 / d;
            d += 2; qpi += 1.0 / d;
        } while (qpi-target > EPSILON);

    });

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

とってもクリーン。

ここまで来ると、冒頭の例にとても近くなりました。


## 3.3. 最後にマクロでお化粧する

マクロを利用して、ファイル名と行番号を出力に追加します。
そして、`NO_TIME_ELAPSED_MEASUREMENT`で性能測定コードを無効化できる仕組みも加え、冒頭の形に到達します。

```cpp:最終形態
#ifdef NO_TIME_ELAPSED_MEASUREMENT
#define TIME_ELAPSED(...)    time_elapsed_lambda_noop([&]{__VA_ARGS__;})
#else
#define TIME_ELAPSED(...)    time_elapsed_lambda_with_loc([&]{__VA_ARGS__;},__FILE__,__LINE__)
#endif

#define TIME_ELAPSED_HEADER  "ElapsedTime: "

template <typename inner_loop>
inline void time_elapsed_lambda_with_header(inner_loop body, std::string &header)
{
    auto t0 = std::chrono::high_resolution_clock::now();
    body();
    auto t1 = std::chrono::high_resolution_clock::now();

    std::cout << (TIME_ELAPSED_HEADER + header + " ") <<
    std::chrono::duration_cast<std::chrono::milliseconds>(t1 - t0).count() << " msec" << std::endl;
}

template <typename BlockBody>
inline void time_elapsed_lambda_noop(BlockBody body)
{
    body();
}

template <typename BlockBody>
inline void time_elapsed_lambda_with_loc(BlockBody body, const char * const path, const int lno)
{
    std::string basename{ path + std::string(path).find_last_of("\\/") + 1 };
    time_elapsed_lambda_with_header(body, basename + " at L." + std::to_string(lno));
}

int main(void)
{
    std::cout.precision(15);

    double target = atan(1.0);
    std::cout << 4.0*target << std::endl;

    // Leibniz formula: qpi->PI/4
    long long int d = 1;
    double qpi = 1.0;

    TIME_ELAPSED(
        do {
            d += 2; qpi -= 1.0 / d;
            d += 2; qpi += 1.0 / d;
        } while (qpi-target > EPSILON);
    );

    std::cout << 4.0*qpi << std::endl;
    return 0;
}
```

## 4. その他

### 4.1. GitHub

少し強化し、`#include "TimeElapsed.hpp"` で即使えるヘッダーファイルにまとめ、GitHub に置きました。

 - [TimeElapsed @ GitHub](https://github.com/h2suzuki/TimeElapsed/)

もしよければご利用ください。 :smiley_cat:

### 4.2. 変更履歴

 * 2015/03/31 更新 - バグ修正
   - マクロに渡すコードブロックのトップレベルにカンマ（`,`）が含まれる場合、このカンマがマクロ引数の区切り文字となり、コンパイルエラーが発生する初歩的なバグがありました。
   - VisualStudio 2013ではWarning C4002となり、コンパイルは通るがカンマ以降の文字列をドロップするという残念な動作になります。マクロ引数`body`を、可変長マクロの`...`と`__VA_ARGS__`で置換するよう、本記事とGitHub上のコードを修正しました。
   - 親切にもコメントを下さった @yohhoy さんに心より感謝します！


以上です。

------------------
[^1]: プロファイラを使うのも良いけれど、このようなログ出力の方が便利な場合もある。
[^2]: 今いるスコープからアクセスできる全変数のテーブルを **実行環境** と呼んでいる。個々のスコープの変数テーブルを「フレーム」と呼ぶので、今いるスコープと全ての取り囲むスコープの「**フレームの集合**」のこと。
[^3]: 関数オブジェクトは、カプセル化の仕組み `class` を使っているから、この用途で使いにくいのは本質的で、当然かもしれない。最初からラムダ式があれば、関数オブジェクトの利用局面はずいぶん少なくなる気がする。