コグノスケ

未来から過去へ表示(*) link

過去から未来へ表示

もっと前

2014年8月26日 >>> 2014年8月26日

もっと後

2014年8月26日

permalink

編集する

hprofプロファイラ

Javaのhprofというプロファイラは、準備を必要とせず（JDK標準だから）に、CPU、ヒープ、モニタの衝突など、一通り測れる便利なプロファイラです。

特に各メソッドのカウントを「全て取る」モード（-Xrunhprof:cpu=times）は、明らかに呼び過ぎのメソッドが一発で分かるため、大変に便利です。

しかし便利な反面、実行速度が下がりすぎて使い物にならなくなる場合があります。

今日遭遇したケースは、7MBのファイルをDataInputStreamからreadByte() するプログラムです。通常のデバッグ実行であれば、ほんの一瞬で終わりますが、cpu=timesでプロファイリングすると10分経っても終わりません…。

どうも、細かいメソッドが頻繁に呼ばれすぎるせいで、メソッド呼び出しのカウントを行う部分がパンクしているようです。

思い出してみればInputStream系はInputStream -> BufferedInputStream -> DataInputStreamなどのように連鎖させるのでメソッド呼び出しが深く、データをロードするという処理はループ回数が多くなりがちなので、深さ×ループ回数の掛け算に比例してどんどん遅くなってしまいます。

これはよろしくありません。

頑張って軽くするには

待てるくらいの時間に収まるように、何とか軽くしてみましょう。

まず目を付けたのはreadByte() です。readByte() で1バイトつずつ読むから呼び出しカウントが多くなるわけです。ならばreadLong() で8バイトずつ読めばカウントは1/8です。

コードもちょい変えで済むし、お手軽高速化としては、プロファイリング時の実行速度もほぼ8倍になる、という中々の効果です。

しかしreadLong() を持ってしても100MBオーバーとなると厳しいでしょう。もし本当にそこまで必要なら、根底から覆す（InputStreamを使わないとか）別の手立てを考える必要がありそうです。

編集者:すずき(2014/08/26 03:15)

コメント一覧

IKeJIさん(2014/08/26 17:13)
BufferedInputStreamのうしろは何回もは呼ばれないのでは？
すずきさん(2014/08/26 21:43)
＞IKeJI さん
そうか、確かに BufferedInputStream 以降はあまり呼ばれないから、BufferedInputStream のバックエンドは呼び出し回数にほとんど関係無いですね。すみません、間違ってました。

ただ BufferedInputStream 自体が結構遅くて、readByte() だとつらいという点は変わりません。
試しに DataInputStream(new BufferedInputStream(new FileInputStream())) に対して、readLong() で 30万回読みだしてみますと、

count : method
307547 : java.io.BufferedInputStream.read
307547 : java.io.DataInputStream.readLong
307547 : java.io.DataInputStream.readFully
307567 : java.io.BufferedInputStream.read1
307568 : java.io.BufferedInputStream.getBufIfOpen
307894 : java.io.BufferedInputStream.getBufIfOpen
301 : java.io.FileInputStream.read
3584 : java.io.BufferedInputStream.read
301 : java.io.BufferedInputStream.fill

こんな感じになっていて、getBufIfOpen がプロファイリングを激しく邪魔します。
IKeJIさん(2014/08/27 00:42)
なるほど。
その辺のprivateなメソッドはインライン展開できそうなもんですが、何かできない理由があるんですかね？
BufferedInputStream.readをfinalにしたら早くなるんだろうか？
すずきさん(2014/08/27 02:09)
＞IKeJI さん
BufferedInputStream をコピーした OreBufferedInputStream を作って、read を final にして試してみました。

（final にする前）
count method
616787 net.katsuster.semu.arm.OreBufferedInputStream.read
616787 java.io.DataInputStream.readFully
616787 java.io.DataInputStream.readLong
616787 net.katsuster.semu.arm.OreBufferedInputStream.read1
616787 net.katsuster.semu.arm.OreBufferedInputStream.getBufIfOpen
617390 net.katsuster.semu.arm.OreBufferedInputStream.getBufIfOpen
603 java.io.FileInputStream.read
2 java.io.FileInputStream.<init>
3584 java.io.BufferedInputStream.read
896 java.io.DataInputStream.readInt
3584 java.io.BufferedInputStream.getBufIfOpen

（final にした後）
616787 net.katsuster.semu.arm.OreBufferedInputStream.read
616787 java.io.DataInputStream.readFully
616787 java.io.DataInputStream.readLong
616787 net.katsuster.semu.arm.OreBufferedInputStream.read1
617390 net.katsuster.semu.arm.OreBufferedInputStream.getBufIfOpen
616787 net.katsuster.semu.arm.OreBufferedInputStream.getBufIfOpen
603 java.io.FileInputStream.read
3584 java.io.BufferedInputStream.getBufIfOpen
2 java.io.FileInputStream.<init>
896 java.io.DataInputStream.readInt

速度も変わらないですね。
IKeJIさん(2014/08/27 13:32)
DataInputStreamがOreBufferedInputStreamをInputStreamとして扱っているからでしょうか？
すずきさん(2014/08/28 10:11)
＞IKeJI さん
もしかして JIT でインライン展開されようとされまいと、関数呼び出しカウントは行われるんじゃないですかね？
BufferedInputStream.read が遅いわけではないので、単にカウントが遅いのでは。
IKeJIさん(2014/08/28 14:26)
そうですが、プロファイルしない時の実行速度はあがるのでは？ > 関数呼び出しカウントは行われる
すずきさん(2014/08/29 17:02)
＞IKeJI さん
プロファイルするときと、しないときとで、JIT の動作が変われば、インライン展開されそうなメソッドなのに、プロファイラにカウントされる理由が付きますかね…？
うーむ、でも自分で書いておいてなんですが、そこまでやらないよな…さすがに…。