ベンチマークが速すぎた話

ステンシル計算のベンチマークを最適化していたら，下のように主要な計算部分のループの処理時間が異常に速くなった．

元のコード：約70ms
私のコード：0.0004ms

どう考えてもおかしい．x10とかx100とかならまだ分かるが，元がベンチマークでそれなりに早く動くように書かれているはずなのにx10万はやりすぎだ．こんなに早くステンシルができたらJournalに通ってしまう．

そもそも，

(ループ回数*ループ1回分の処理のステップ数) / (クロック数*CPUのクロック*CPI)

と考えると，キャッシュアクセスやメモリアクセスの時間を差し引いても数msはかかる処理なはずだ．ファイルI/Oなどもない単純なコードなので，そもそもアルゴリズム的には最適化する余地があまりない．

コードを見ても，元からほとんどいじっていないので分からない．
不思議なことに，最適化オプションを-O3から-O0にすると，元のコードと同じくらいの「まともな」実行時間になった．

どうやら最適化でゴッソリ何かを削っているようだ．

コンパイルオプションに-save-tempsを付けてアセンブリを読んでみる．
まず，行数が元のコードが1200行ほどなのに，私のものは160行程度であった．
元のコードが同じなのにこれは如何に？

計算部分を見てみる．こういう時にprintfなどのライブラリコールを呼んでおくと良い目印になると思った．

私のコード
 call omp_get_wtime
 leaq .LC1(%rip), %rcx
 movapd %xmm0, %xmm6
 movl $548720, %edx
 call printf
 call omp_get_wtime

元のコード
  call omp_get_wtime
 movsd .LC4(%rip), %xmm12
 movl $10, 340(%rsp)
 movapd %xmm0, %xmm10
 movq %r13, %r11
 movapd %xmm12, %xmm13
.L26:
 movq $12800, 248(%rsp)
     ++400行省略++
 leaq .LC5(%rip), %rcx
 movq %r11, %r13
 movl $548720, %edx
 call printf
 call omp_get_wtime

コンパイラは賢い．ループ回数を記録するつもりで1ループごとに++していた変数に対しても，いきなりループ回数の合計を定数として突っ込んでprintしている．(下線部)

とりあえず，私のコードでは一番時間のかかるはずの計算部分の約400行がごっそり抜けている．

元のコードではこの計算の後に検算をする関数を読んでいたのだが，ループで計算した結果はその時だけしか使われない．私のコードでは，デバッグのためにその関数のcallを省いていたのが原因だったようだ．そして，gccが，「この計算結果どこにも使われていないから計算自体省いていいよね」という判断をしたようだ．確かにその理論は正しい．
私のコードでも検算の関数をcallするようにしたら，ちゃんとした結果になった．

いままでMIPSアセンブリしか勉強したことないのだが，x86もなんとなく雰囲気は伝わってきたので，アセンブリの勉強をしておいて良かったと感じた出来事だった．