HotSpot JVMの落とし穴 - sumiiのブログ

とある自動生成されたJavaプログラムで、

while (true) {
  ...
  if (xxx) {} else {break;}
}

と

while (true) {
  ...
  if (!xxx) {break;} else {}
}

みたいな二つのコードがあったのですが、前者のほうが後者より20％ぐらい遅くて悩まされました。いや、そこまで突き止めてしまえば明らかなのですが、javapで逆アセンブルしたら、バイトコードレベルで制御流がねじれていて、HotSpot VMも最適化してくれないという…（JIT コンパイルはされている）。フローグラフで自明に無駄なノードをちょっと融合すれば、これぐらい簡単に消去できると信用していたのに…。いよいよJITコンパイルされたネイティブコードを直接確認する方法が必要になってきました…

追記：再現しないというツッコミをいただいたので、さらに実験してみたら、もっと悪質な原因でした。;_; ~~クラス名が一文字だけ違ったら4.99秒が6.08秒になるって、マジですか…。~~JIT コンパイルされたネイティブコードのアラインメントのせい？一応、ソースコードはこちら↓（breakは手動でdo-whileにしてあります）
http://www.kb.ecei.tohoku.ac.jp/~sumii/tmp/Fannkuch_.java
http://www.kb.ecei.tohoku.ac.jp/~sumii/tmp/Fannkuch__.java

> uname -a
Linux primergy2.kb-private 2.6.9-55.0.12.ELsmp #1 SMP Wed Oct 17 08:19:30 EDT 2007 i686 i686 i386 GNU/Linux
> diff Fannkuch_.java Fannkuch__.java
1c1
< public class Fannkuch_ {
---
> public class Fannkuch__ {
> /usr/java/jdk1.6.0_03/bin/javac -version
javac 1.6.0_03
> /usr/java/jdk1.6.0_03/bin/javac -O Fannkuch_.java
> /usr/java/jdk1.6.0_03/bin/javac -O Fannkuch__.java
> /usr/java/jdk1.6.0_03/bin/java -version
java version "1.6.0_03"
Java(TM) SE Runtime Environment (build 1.6.0_03-b05)
Java HotSpot(TM) Server VM (build 1.6.0_03-b05, mixed mode)
> time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch_ 11 > /dev/null
4.971u 0.021s 0:04.99 100.0%    0+0k 0+0io 1pf+0w
> time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch__ 11 > /dev/null
6.068u 0.017s 0:06.08 99.8%     0+0k 0+0io 1pf+0w
> time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch_ 11 > /dev/null
4.972u 0.022s 0:04.99 100.0%    0+0k 0+0io 1pf+0w
> time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch__ 11 > /dev/null
6.064u 0.022s 0:06.08 100.0%    0+0k 0+0io 1pf+0w

追記２：やっぱり再現しないとのツッコミ。自分でもわけがわからないので、時間のあるときに*1もっと丁寧に検証してみます…

追記３：とりあえず途中経過。というか、これ以上は正直に言ってお手上げ。クラス名に関わらず、このプログラム(Fannkuch)だけ実行時間が1秒単位でぶれる。他のJavaプログラムは0.01秒単位でしかぶれない。同じようなプログラムをCで書いてもまったくぶれない。他のプロセスはほとんど動いていない。SMPマシン（2ソケット4コア）だが割り当てられるCPUとの相関は皆無。他のマシン（Pentium M 1.86 GHzとCore 2 6400 2.13 GHz）で試しても、同じくFannkuchだけ大きくぶれる。なんで？？？

> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch_ 11 > /dev/null
4.96user 0.02system 0:04.99elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2963minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch_ 11 > /dev/null
6.03user 0.02system 0:06.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3030minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch_ 11 > /dev/null
5.93user 0.02system 0:05.92elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2968minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch__ 11 > /dev/null
6.03user 0.02system 0:06.03elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2970minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch__ 11 > /dev/null
5.91user 0.01system 0:05.93elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3157minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch__ 11 > /dev/null
4.97user 0.02system 0:04.99elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2966minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch_ 11 > /dev/null
5.85user 0.02system 0:05.87elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2967minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Fannkuch__ 11 > /dev/null
6.03user 0.02system 0:06.08elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2969minor)pagefaults 0swaps

> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Mandelbrot 3000 > /dev/null
3.05user 0.26system 0:03.19elapsed 103%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+6257minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Mandelbrot 3000 > /dev/null
3.06user 0.24system 0:03.22elapsed 102%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+6134minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Mandelbrot 3000 > /dev/null
3.07user 0.23system 0:03.18elapsed 103%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+6128minor)pagefaults 0swaps

> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Nbody 20000000 > /dev/null
9.33user 0.02system 0:09.35elapsed 100%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2878minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Nbody 20000000 > /dev/null
9.31user 0.02system 0:09.48elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2878minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server Nbody 20000000 > /dev/null
9.32user 0.03system 0:09.36elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+2876minor)pagefaults 0swaps

追記４：-Xintオプションや-Xbatchオプションをつけるとぶれないようだ。つまりバックグラウンドのJIT コンパイルの影響？

> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server -Xbatch Fannkuch_ 11 > /dev/null
5.97user 0.03system 0:06.06elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3323minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server -Xbatch Fannkuch__ 11 > /dev/null
5.98user 0.02system 0:06.06elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3324minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server -Xbatch Fannkuch_ 11 > /dev/null
5.98user 0.02system 0:06.05elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3324minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server -Xbatch Fannkuch__ 11 > /dev/null
5.98user 0.02system 0:06.05elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3325minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server -Xbatch Fannkuch_ 11 > /dev/null
5.99user 0.02system 0:06.11elapsed 98%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3324minor)pagefaults 0swaps
> /usr/bin/time /usr/java/jdk1.6.0_03/bin/java -server -Xbatch Fannkuch__ 11 > /dev/null
6.01user 0.02system 0:06.05elapsed 99%CPU (0avgtext+0avgdata 0maxresident)k
0inputs+0outputs (1major+3324minor)pagefaults 0swaps

追記５：学生さんのPenitum 4マシンで実行したら、同じクラス名でのブレはほとんどなかった（オプションをつけなくても）。そもそも初めの「thenをelseを入れ替えると遅い」は、そのマシンで観察された現象だったのですが…。どう見ても（話が）ループです。本当にありがとうございました。

*1:休日にお風呂を洗ったり、子供のウンチを取り替えながら実験するのは限界が（←アホ）