追記
追記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の読み込み速度に影響を与える。
ということに原因があるのだと考えています。
ということで、結論としては、たとえ小さなな箇所のベンチマークでも、メモリの確保と解放は出来るだけループの外側に書いて回数を抑えましょうということですね。
おわりに
とはいえ、大きなコードの一部を切り出す際には、メモリの確保の場所を変えるのは結構面倒だったりするので、悩ましいですよね。ずぼらな私には特に。
また、もっと詳しい方なら違った見方もあると思いますので、ご指摘いただけたら嬉しいです。（コメントの返信が遅かったらすみません。）