namazu-dev(ring)

[Satoru Takabayashi <satoru-t@xxxxxxxxxxxxxxxxxx>]

knok@xxxxxxxxxxxxx (NOKUBI Takatsugu) wrote:

>
>  実際のボトルネックがどこにあるのかを調べるために、profilerにかけて
>ました。
>  Devel::DProfをインストールし、perl -d:DProf mknmzとして実行した後生
>成されたtmon.outをdprofpp -uにかけた結果、以下の通りになりました。

perl に profilerがあったとは知りませんでした。さっそく試して
みました。

| Total Elapsed Time = 46.39440 Seconds
|          User Time = 37.79985 Seconds
| Exclusive Times
| %Time ExclSec CumulS #Calls sec/call Csec/c  Name
|  15.5   5.870  5.870      1   5.8700 5.8698  mknmz::write_phrase_hash_sub
|  13.9   5.277  5.160  21796   0.0002 0.0002  mknmz::hash
|  10.8   4.082  6.489   6972   0.0006 0.0009  File::MMagic::readMagicEntry
|  8.94   3.379  3.377    504   0.0067 0.0067  mknmz::wordcount_sub
|  7.41   2.802  7.960     84   0.0334 0.0948  mknmz::make_phrase_hash
|  6.24   2.359  2.330   5460   0.0004 0.0004  File::MMagic::readMagicLine
(snip)

hash() 関数が 21,796回も呼び出されているので、その辺の処理を
改良したところ、

| Total Elapsed Time = 39.93897 Seconds
|   User+System Time = 38.46897 Seconds
| Exclusive Times
| %Time ExclSec CumulS #Calls sec/call Csec/c  Name
|  15.4   5.950  5.950      1   5.9500 5.9497  mknmz::write_phrase_hash_sub
|  13.0   5.013  7.399   6972   0.0007 0.0011  File::MMagic::readMagicEntry
|  11.0   4.267  4.139  20080   0.0002 0.0002  mknmz::hash
|  7.80   2.999  2.997    504   0.0060 0.0059  mknmz::wordcount_sub
|  7.26   2.791  6.928     84   0.0332 0.0825  mknmz::make_phrase_hash
|  6.49   2.498  2.465   5460   0.0005 0.0005  File::MMagic::readMagicLine

と改善されました。すばらしい。「ここは遅いぞ」という点があれ
ばどんどん修正していきましょう。:-)

# mknmz::hash()	の回数が減ったのは、周辺の処理が変わったから
# です。よって、NMZ.p, NMZ.pi の内容もわずかに変わります。

-- Satoru Takabayashi