追記

追記1

コメントで説得力がないという指摘を受けましたが、今回の問題では原因が特定しきれていませんし、私の想像で書いてしまっているところがあるので、指摘はごもっとも。今回実査に使ったコードの特定の問題かもしれませんし、あくまでこういう事もあったという事例として捉えてください。

追記2

皆さんのコメントのおかげで、TLBと断定した形のタイトルは適切ではないと思うようになりましたので、修正しました(最初は「TLBキャッシュ編」と書いていました)。

概要

ベンチマーク時には、測定対象の場所（関数・ルーチン）以外におけるメモリ確保と解放の回数が、測定対象の速度に影響を及ぼすことがある。TLBヒットミスが原因の模様。特に粒度の小さいベンチマーク時には注意が必要。

環境

参考までに今回の環境は次のようなものです。

OS: CentOS 7.9
コンパイラ: Intel C+ (icpc) 2021.5.0
CPU: Intel(R) Xeon(R) Silver 4208 CPU @ 2.10GHz

背景

あるプログラムにおいて、一部の関数(もしくは長いコードのうちの一部分)だけのベンチマークをしたいことはあるでしょう。しかし、その関数をコールするには、前処理としてメモリの確保やその中身の値の初期化が必要という事が度々あります。特に大きなプログラムから一部を切り出してきてベンチマークをするのは結構大変です。

ずぼらな私はあるベンチマークにおいて前処理部分を適当に作って、以下のようなベンチマークコードを書いていました。これをCase 1とします。概要を伝えるために色々と端折っています。

# ベンチマークコード Case 1
int main(){
  int STEPS = 1000;
  double total_time = 0.0;
  for(int step=0; step<STEPS; ++steps){
    //(A)allocate mem.
    int* buf0 = new int[N];
    int* buf1 = new int[M];
    ...
    ...
    double* buf19 = new double[N];
    double* buf20 = new double[100];
    
    //(B)initialize
    Init(buf0, buf1, ..., buf20);
    
    //(C)measure time of Target()
    double start_tm = my_get_time();
    Target(buf0, but1, ..., buf20);
    total_time += my_get_time() - start_tm;

    //(D)deallocate mem.
    delete[] buf0;
    delete[] buf1;
    ...
    delete[] buf19;
    delete[] buf20;
  }
  printf("Case 1: total_time = %f[s]\n",total_time);
}

コードの概要を簡単に説明します。粒度の小さい関数Target()の計算時間を測るために、STEPS=1000回繰り返してその合計時間を測定しています。前処理として(A)でメモリの確保、(B)で値の初期化を行っています。(C)で目的の関数Target()の計算時間を測定しています。ただし、my_get_time()関数で高精度タイマーの値をdoubleで取得できるものとしています。最後に(D)でメモリの解放をしています。

ところが、凡ミスで、一箇所だけメモリの解放を忘れた次のようなメモリリークするコードを書いてしまいました。これをCase 2とします。

# ベンチマークコード Case 2
int main(){
  int STEPS = 1000;
  double total_time = 0.0;
  for(int step=0; step<STEPS; ++steps){
    //(A)allocate mem.
    int* buf0 = new int[N];
    int* buf1 = new int[M];
    ...
    ...
    double* buf19 = new double[N];
    double* buf20 = new double[100];
    
    //(B)initialize
    Init(buf0, buf1, ..., buf20);
    
    //(C)measure time of Target()
    double start_tm = my_get_time();
    Target(buf0, but1, ..., buf20);
    total_time += my_get_time() - start_tm;

    //(D)deallocate mem.
    delete[] buf0;
    delete[] buf1;
    ...
    delete[] buf19;
    //delete[] buf20;  //ここの解放を忘れてメモリリーク//
  }
  printf("Case 2: total_time = %f[s]\n",total_time);
}

これはCase 1と比べると、最後のbuf20に関する解放だけを忘れています。ただ、確保していたメモリが少なかったので、メモリリークしてもプログラムは最後まで実行できてしまっていました。もちろん計算結果も正しい結果が返ります。

しかしこれらのコードでは、計算時間のベンチマークを取ると、大きな違いがありました。以下には実際にこの問題に遭遇したコードでの時間を示します。

Case 1: total time = 4.649958[s]
Case 2: total time = 2.654766[s]

なぜかメモリリークしたCase 2の方が倍近く速いのです。

なぜか？

Linux kernel 3.0以降で使えるperf statで計測して見ると、次のような結果になりました。

Case1コードの計測結果

$ perf stat -d -d -d ./case1.out
Case 1: total time = 4.649958[s]

 Performance counter stats for './case1.out':

          5,943.84 msec task-clock:u              #    1.000 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
         1,599,137      page-faults:u             #    0.269 M/sec
    10,538,432,191      cycles:u                  #    1.773 GHz                      (61.51%)
    16,837,187,586      instructions:u            #    1.60  insn per cycle           (69.22%)
     1,772,895,320      branches:u                #  298.274 M/sec                    (69.23%)
        38,968,446      branch-misses:u           #    2.20% of all branches          (69.25%)
     2,517,149,592      L1-dcache-loads:u         #  423.489 M/sec                    (69.25%)
       272,026,643      L1-dcache-load-misses:u   #   10.81% of all L1-dcache hits    (69.25%)
         2,547,720      LLC-loads:u               #    0.429 M/sec                    (69.25%)
            24,481      LLC-load-misses:u         #    0.96% of all LL-cache hits     (69.25%)
   <not supported>      L1-icache-loads:u
         1,800,936      L1-icache-load-misses:u                                       (69.25%)
     2,515,596,682      dTLB-loads:u              #  423.228 M/sec                    (69.24%)
         1,342,752      dTLB-load-misses:u        #    0.05% of all dTLB cache hits   (61.52%)
             1,992      iTLB-loads:u              #    0.335 K/sec                    (61.50%)
            27,298      iTLB-load-misses:u        # 1370.38% of all iTLB cache hits   (61.50%)
   <not supported>      L1-dcache-prefetches:u
   <not supported>      L1-dcache-prefetch-misses:u

       5.944925133 seconds time elapsed

       3.831362000 seconds user
       2.113199000 seconds sys

Case2コードの計測結果

$ perf stat -d -d -d ./case2.out
Case 2: total time = 2.654766[s]

 Performance counter stats for './case2.out':

          3,393.06 msec task-clock:u              #    1.000 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
            94,606      page-faults:u             #    0.028 M/sec
     9,060,674,324      cycles:u                  #    2.670 GHz                      (61.55%)
    17,293,595,627      instructions:u            #    1.91  insn per cycle           (69.24%)
     1,797,891,950      branches:u                #  529.874 M/sec                    (69.24%)
        35,874,718      branch-misses:u           #    2.00% of all branches          (69.23%)
     2,695,248,608      L1-dcache-loads:u         #  794.342 M/sec                    (69.23%)
       255,403,145      L1-dcache-load-misses:u   #    9.48% of all L1-dcache hits    (69.21%)
         2,343,263      LLC-loads:u               #    0.691 M/sec                    (69.21%)
             3,707      LLC-load-misses:u         #    0.16% of all LL-cache hits     (69.21%)
   <not supported>      L1-icache-loads:u
           585,657      L1-icache-load-misses:u                                       (69.21%)
     2,686,719,648      dTLB-loads:u              #  791.829 M/sec                    (69.24%)
           105,966      dTLB-load-misses:u        #    0.00% of all dTLB cache hits   (61.55%)
             1,862      iTLB-loads:u              #    0.549 K/sec                    (61.55%)
             2,356      iTLB-load-misses:u        #  126.53% of all iTLB cache hits   (61.55%)
   <not supported>      L1-dcache-prefetches:u
   <not supported>      L1-dcache-prefetch-misses:u

       3.394230264 seconds time elapsed

       3.270796000 seconds user
       0.123029000 seconds sys

これらを比較すると、次のことが見て取れます。

最後の行のseconds sysの項目で、Case1コードでは異常に時間が掛かっていることが分かります。
L1キャッシュL1-dcache-loads:uの項目の左側の数字は両者に差がなく、L1-dcache-load-misses:uの項目も殆ど差がありません。しかし、L1-dcache-load-misses:uの右側に表示される読み込み速度はCase 1はCase 2の約半分しか出ていません。

私はここまで見て、良く分からずに悩んでいました。キャッシュヒットは変わらないのに読み込みが倍も違うのはなぜなんだろうかと。

また、最初はperf statコマンドのオプションの-dを1つしかつけていなかったのでTLB関連の項目が表示されなかった、というのも事情としてありました。オプションの-dを2つ以上つけるとTLB関連が表示されます。

さて、さらにTLB関連の項目を見てみると

dTLB-loads:uの項目も、Case1コードではCase2コードの半分しか速度が出ていません。
また、dTLB-loads:uの読み込み速度がL1-dcache-loads:uの読み込み速度とほぼ同じことから、今回のコードではL1キャッシュの速度がほぼTLBのロードで律速していると予想されます。
そして、dTLB-load-misses:uが、Case 1では1,342,752と大きな値になっており、一方でCase2では105,966とかなり小さく抑えられています。

ということで、どうやらTLBのヒットミスがL1の読み込み速度に大きな影響を与え、結果としてシステム側の時間(seconds sys)に影響を与えているようです。

速度低下の原因とTLB

TLBとはTranslation Lookaside Bufferの略です。TLBについてはそれほど詳しくないので、簡単にしか書けませんが、要はユーザースペースのメモリアドレスと、実際の物理アドレスの間のマッピングを行う機能です。テーブルか何らかのアルゴリズムで実装されており、キャッシュに近い機構で保持されているらしいです。詳しくはweb検索された方がよいでしょう。

さて、今回の問題ではTLBのヒットミスが多発しているのが原因でした。おそらく、STEPS=1000回の計算において、毎回メモリを再確保していたので、TLBが毎回書き換わっているのでしょう。そのため、Target()でメモリに触るときにTLBのヒットミスが起こり、待たされる羽目になっているのでしょう。

ところが、Case 2ではメモリリークしていたせいで、メモリ確保しても開放しない部分があります。それが毎回のTLBの再構築において何らかの影響を与え、ヒットミスを抑える効果に繋がったのでしょう。

※「TLBが書き換わる」とか「TLBの再構築」という表現が適切か分かりませんが、ご容赦ください。

対策

ではどうするのか。速いコードを作りたいからと言ってメモリリークのあるCase2を採用するわけにはいきません。

基本に立ち返って、ずぼらなことはせずに、stepループの外側でメモリ確保と解放をするようにしてみました。それを次のCase3コードとします。

# ベンチマークコード Case 3
int main(){
  int STEPS = 1000;
  double total_time = 0.0;

  //(A)allocate mem.
  int* buf0 = new int[N];
  int* buf1 = new int[M];
  ...
  ...
  double* buf19 = new double[N];
  double* buf20 = new double[100];

  for(int step=0; step<STEPS; ++steps){    
    //(B)initialize
    Init(buf0, buf1, ..., buf20);
    
    //(C)measure time of Target()
    double start_tm = my_get_time();
    Target(buf0, but1, ..., buf20);
    total_time += my_get_time() - start_tm;
  }
  
  //(D)deallocate mem.
  delete[] buf0;
  delete[] buf1;
  ...
  delete[] buf19;
  delete[] buf20;
  
  printf("Case 3: total_time = %f[s]\n",total_time);
}

このCase3コードでは、予想通りならTLBの再構築は抑えられ、ヒットミスが減るはずです。ベンチマークを行ってみると確かに速くなっています。

Case 3: total time = 2.177145[s]

perf statによる計測結果を見てみると：

$ perf stat -d -d -d ./case3.out
Case 3: total time = 2.177145[s]

 Performance counter stats for './case3.out':

          3,145.27 msec task-clock:u              #    1.000 CPUs utilized
                 0      context-switches:u        #    0.000 K/sec
                 0      cpu-migrations:u          #    0.000 K/sec
           130,799      page-faults:u             #    0.042 M/sec
     8,043,527,891      cycles:u                  #    2.557 GHz                      (61.54%)
    17,240,217,848      instructions:u            #    2.14  insn per cycle           (69.23%)
     1,798,036,935      branches:u                #  571.663 M/sec                    (69.23%)
        34,873,318      branch-misses:u           #    1.94% of all branches          (69.20%)
     2,690,582,577      L1-dcache-loads:u         #  855.437 M/sec                    (69.20%)
       275,079,997      L1-dcache-load-misses:u   #   10.22% of all L1-dcache hits    (69.20%)
         2,432,773      LLC-loads:u               #    0.773 M/sec                    (69.20%)
             2,161      LLC-load-misses:u         #    0.09% of all LL-cache hits     (69.23%)
   <not supported>      L1-icache-loads:u
           543,661      L1-icache-load-misses:u                                       (69.26%)
     2,692,984,129      dTLB-loads:u              #  856.200 M/sec                    (69.26%)
            24,450      dTLB-load-misses:u        #    0.00% of all dTLB cache hits   (61.57%)
             1,540      iTLB-loads:u              #    0.490 K/sec                    (61.57%)
            33,607      iTLB-load-misses:u        # 2182.27% of all iTLB cache hits   (61.54%)
   <not supported>      L1-dcache-prefetches:u
   <not supported>      L1-dcache-prefetch-misses:u

       3.146474247 seconds time elapsed

       2.990067000 seconds user
       0.156003000 seconds sys

TLB関連の項目は予想通り改善しており、

dTLB-loads:uの項目は、Case2よりもさらに速度が向上しました。
そして、dTLB-load-misses:uは、Case2の105,966と比べて、Case3では24,450とさらに小さく抑えられています。

という結果になりました。

まとめ

ということで、メモリの確保と解放の回数を抑えることで、TLBのヒットミスを抑え、速度の低下を防ぐことが出来ました。

あらためて、何が問題だったのかというと、私の認識の問題として、

【間違い1】 計測対象箇所だけの時間計測を行えば、それ以外の個所はほとんど影響しないと思っていた。
- →実際は、対象箇所以外でのメモリ確保によって対象箇所でのTLBヒットミスが変わる。
【間違い2】 L1キャッシュのヒット率が同じなら、L1キャッシュの読み込み速度も同じだと思っていた。
- →実際は、TLBのヒットミスによって遅延が発生し、L1の読み込み速度に影響を与える。

ということに原因があるのだと考えています。

ということで、結論としては、たとえ小さなな箇所のベンチマークでも、メモリの確保と解放は出来るだけループの外側に書いて回数を抑えましょうということですね。

おわりに

とはいえ、大きなコードの一部を切り出す際には、メモリの確保の場所を変えるのは結構面倒だったりするので、悩ましいですよね。ずぼらな私には特に。

また、もっと詳しい方なら違った見方もあると思いますので、ご指摘いただけたら嬉しいです。（コメントの返信が遅かったらすみません。）