NetBSD 絹の日記

2003年07月17日(木) 旧暦 [n年日記]

#1 [Perl] Dprof

多分知っている人は知っているのだろうけれど、 (僕は知らなかったので) DProf というのを試して見た。(LANG=C)。

ttyp2:makoto@harry  12:16:04/030717(...software/NetBSD)> perl -d:DProf /usr/pkg/bin/mknmz -O /tmp/O .
[Base]
Date:                Thu Jul 17 12:14:40 2003
Added Documents:     424
Size (bytes):        1,651,659
Total Documents:     424
Added Keywords:      53,050
Total Keywords:      53,050
Wakati:              module_kakasi -ieuc -oeuc -w
Time (sec):          94
File/Sec:            4.51
System:              netbsd
Perl:                5.006001
Namazu:              2.0.13pre1

ttyp2:makoto@harry  12:15:31/030717(...software/NetBSD)> dprofpp tmon.out 
Total Elapsed Time = 84.51746 Seconds
  User+System Time = 79.96798 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 51.5   41.24 41.228    302   0.1366 0.1365  html::get_author
 11.0   8.815  7.561 119868   0.0001 0.0001  mknmz::hash
 9.51   7.607  7.606    426   0.0179 0.0179  File::MMagic::checktype_data
 6.19   4.948  4.881   1664   0.0030 0.0029  mknmz::wordcount_sub
 4.48   3.585 10.969    424   0.0085 0.0259  mknmz::make_phrase_hash
 4.11   3.288  2.873  32123   0.0001 0.0001  File::MMagic::readMagicLine
 3.92   3.137  5.460  32123   0.0001 0.0002  File::MMagic::magicMatchStr
 2.24   1.790  1.790      1   1.7900 1.7896  mknmz::write_index_sub
 2.09   1.675  6.515    424   0.0040 0.0154  mknmz::count_words
 1.46   1.170  1.170      1   1.1700 1.1698  mknmz::write_phrase_hash_sub
 1.11   0.890  0.726   9897   0.0001 0.0001  IO::File::open
 1.11   0.887  2.241    424   0.0021 0.0053  mknmz::put_field_index
 0.97   0.779  0.976    302   0.0026 0.0032  html::weight_element
 0.90   0.719  6.060    422   0.0017 0.0144  File::MMagic::checktype_magic
 0.68   0.540  0.538    302   0.0018 0.0018  html::get_alt_attr

ちょっとこの数字は意外。半分が html::get_author ?

＠ Mail で LANG=ja_JP.eucJPの時:

[基本]
日付:                Thu Jul 17 12:21:44 2003
追加された文書数:    2,909
大きさ (bytes):      19,412,929
合計の文書数:        2,909
追加検索語数:        2,910
合計検索語数:        2,910
わかち書き:          module_kakasi -ieuc -oeuc -w
経過時間 (秒):       120
譜/秒:               24.24
系:                  netbsd
Perl:                5.006001
Namazu:              2.0.13pre1

ttyp4:makoto@harry  12:21:44/030717(~/Mail/inbox)> dprofpp tmon.out  
Total Elapsed Time = 98.30404 Seconds
  User+System Time = 89.79705 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 71.2   63.98 63.928   2909   0.0220 0.0220  File::MMagic::checktype_data
 7.48   6.717 16.190   2909   0.0023 0.0056  mknmz::put_field_index
 5.90   5.298  4.212  67063   0.0001 0.0001  IO::File::open
 3.54   3.176 10.995  67063   0.0000 0.0002  util::fopen
 3.41   3.058  4.679  67063   0.0000 0.0001  IO::File::new
 2.39   2.146 70.887   2910   0.0007 0.0244  mknmz::load_document
 2.32   2.079  1.442  67063   0.0000 0.0000  Symbol::gensym
 2.12   1.908  1.631  52385   0.0000 0.0000  util::tmpnam
 2.11   1.899  2.525  67063   0.0000 0.0000  IO::Handle::new
 1.81   1.629  1.348   2909   0.0006 0.0005  File::MMagic::checktype_byfilename
 1.64   1.469  0.713 134127   0.0000 0.0000  IO::Handle::DESTROY
 1.62   1.459 10.176  61223   0.0000 0.0002  util::efopen
 1.38   1.240  0.707  93133   0.0000 0.0000  util::dprint
 1.17   1.054 91.894   2910   0.0004 0.0316  mknmz::namazu_core
 1.15   1.029  1.487   2943   0.0003 0.0005  util::readfile
ttyp4:makoto@harry  12:23:02/030717(~/Mail/inbox)>

こちらは 70% が File::MMagic::checktype_data これもかなり意外。 (もし上の数字が合っているとしてだけれど) foreach の中での sort と外側の sort と sort が二か所もあるのが問題か ? 僕の使っているのが古い ?

# $Id: MMagic.pm,v 1.45 2001/06/15 08:08:10 knok Exp $

該当の部分は新しいものと同じらしい。

# $Id: MMagic.pm,v 1.57 2003/05/08 13:36:11 knok Exp $

つまらなく安易な話として、mail に決っているものだったら、File::MMagic をとばす方が(自分としては)楽しい気がする。

＠ --mailnews を指定するとそうなる ?:

[基本]
日付:                Thu Jul 17 13:50:07 2003
追加された文書数:    2,909
大きさ (bytes):      19,412,929
合計の文書数:        2,909
追加検索語数:        2,910
合計検索語数:        2,910
わかち書き:          module_kakasi -ieuc -oeuc -w
経過時間 (秒):       51
譜/秒:               57.04
系:                  netbsd
Perl:                5.006001
Namazu:              2.0.13pre1

ttyp4:makoto@harry  13:50:07/030717(~/Mail/inbox)> dprofpp tmon.out
Total Elapsed Time = 27.06984 Seconds
  User+System Time = 17.11984 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 35.5   6.082 14.059   2909   0.0021 0.0048  mknmz::put_field_index
 34.0   5.837  4.358  67063   0.0001 0.0001  IO::File::open
 19.4   3.324 10.468  67063   0.0000 0.0002  util::fopen
 17.6   3.016  4.378  67063   0.0000 0.0001  IO::File::new
 14.3   2.459  1.618  67063   0.0000 0.0000  Symbol::gensym
 12.6   2.167  2.743  67063   0.0000 0.0000  IO::Handle::new
 10.8   1.858  1.307  52385   0.0000 0.0000  util::tmpnam
 10.4   1.795  4.821   2910   0.0006 0.0017  mknmz::load_document
 9.92   1.699  0.645 134127   0.0000 0.0000  IO::Handle::DESTROY
 9.16   1.568  9.319  61223   0.0000 0.0002  util::efopen
 7.54   1.290 23.065   2910   0.0004 0.0079  mknmz::namazu_core
 6.89   1.179  0.489  90224   0.0000 0.0000  util::dprint
 5.95   1.018  0.783   2915   0.0003 0.0003  mknmz::add_target
 5.48   0.939  1.130   2943   0.0003 0.0004  util::readfile
 5.30   0.907  1.193   2909   0.0003 0.0004  mknmz::complete_field_info
ttyp4:makoto@harry  13:51:23/030717(~/Mail/inbox)>

( つっこみ )

#2 Devel::DProf って初めて知った

かなりボケている。

＠ 2.0.12 mef:

[基本]
日付:                Thu Jul 17 16:04:18 2003
追加された文書数:    2,909
大きさ (bytes):      19,412,929
合計の文書数:        2,909
追加検索語数:        2,910
合計検索語数:        2,910
わかち書き:          module_kakasi -ieuc -oeuc -w
経過時間 (秒):       46
譜/秒:               63.24
系:                  netbsd
Perl:                5.006001
Namazu:              2.0.12

ttyp1:makoto@harry  16:04:18/030717(~/Mail/inbox)> !dp:p
dp: Event not found.
ttyp1:makoto@harry  16:04:22/030717(~/Mail/inbox)> dprofpp -u
Total Elapsed Time = 31.28406 Seconds
         User Time = 20.16668 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 24.3   4.919 11.330   2909   0.0017 0.0039  mknmz::put_field_index
 18.4   3.720  1.476  67063   0.0001 0.0000  IO::File::open
 11.6   2.350  7.288  67063   0.0000 0.0001  util::fopen
 11.6   2.340  4.282  67063   0.0000 0.0001  IO::File::new
 9.97   2.010  1.836  67063   0.0000 0.0000  Symbol::gensym
 7.63   1.539  3.615   2910   0.0005 0.0012  mknmz::load_document
 7.09   1.430  1.191  52385   0.0000 0.0000  util::tmpnam
 5.75   1.160  2.489  67063   0.0000 0.0000  IO::Handle::new
 4.86   0.980  0.523 134127   0.0000 0.0000  IO::Handle::DESTROY
 4.80   0.969 18.422   2910   0.0003 0.0063  mknmz::namazu_core
 4.31   0.870  6.993  61223   0.0000 0.0001  util::efopen
 3.72   0.750  0.405  90224   0.0000 0.0000  util::dprint
 2.58   0.520  0.941   2909   0.0002 0.0003  mknmz::complete_field_info
 2.48   0.500  0.446   8727   0.0001 0.0001  mknmz::wordcount_sub
 2.13   0.430  0.757   2909   0.0001 0.0003  mknmz::count_words

＠ patch 後:

[基本]
日付:                Thu Jul 17 16:12:51 2003
追加された文書数:    2,909
大きさ (bytes):      19,412,929
合計の文書数:        2,909
追加検索語数:        2,910
合計検索語数:        2,910
わかち書き:          module_kakasi -ieuc -oeuc -w
経過時間 (秒):       46
譜/秒:               63.24
系:                  netbsd
Perl:                5.006001
Namazu:              2.0.12

ttyp1:makoto@harry  16:12:51/030717(~/Mail/inbox)> !dp:p
dprofpp -u
ttyp1:makoto@harry  16:12:56/030717(~/Mail/inbox)> dprofpp -u
Total Elapsed Time = 29.81235 Seconds
         User Time = 14.04638 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 32.3   4.537  8.980   2909   0.0016 0.0031  mknmz::put_field_index
 25.1   3.529  1.376  67063   0.0001 0.0000  IO::File::open
 15.0   2.119  3.579  67063   0.0000 0.0001  IO::File::new
 14.1   1.989  5.843  67063   0.0000 0.0001  util::fopen
 13.6   1.920  1.486  67063   0.0000 0.0000  Symbol::gensym
 10.7   1.506  3.250   2910   0.0005 0.0011  mknmz::load_document
 9.82   1.379  2.148  67063   0.0000 0.0000  IO::Handle::new
 8.83   1.240  0.806  52385   0.0000 0.0000  util::tmpnam
 7.48   1.050  0.452 134127   0.0000 0.0000  IO::Handle::DESTROY
 6.91   0.970  5.783  61223   0.0000 0.0001  util::efopen
 6.18   0.868 14.948   2910   0.0003 0.0051  mknmz::namazu_core
 5.62   0.790  0.290  90224   0.0000 0.0000  util::dprint
 3.42   0.480  0.684   2909   0.0002 0.0002  mknmz::complete_field_info
 3.13   0.440  0.301   2915   0.0002 0.0001  mknmz::add_target
 2.92   0.410  0.738   2909   0.0001 0.0003  mknmz::count_words
ttyp1:makoto@harry  16:14:01/030717(~/Mail/inbox)> ls -l /usr/pkg/bin/mkn*
-r-xr-xr-x  2 root  wheel  70168 Jul 17 16:09 /usr/pkg/bin/mknmz*
-r-xr-xr-x  1 root  wheel  70112 Jul 17 16:02 /usr/pkg/bin/mknmz-2.0.12*
-r-xr-xr-x  2 root  wheel  70168 Jul 17 16:09 /usr/pkg/bin/mknmz-2.0.12-put_field_index-patch*

しかも NMZ.p NMZ.pp が出来ていない。

＠ --mailnews を付けないと:

[基本]
日付:                Thu Jul 17 16:23:13 2003
追加された文書数:    2,909
大きさ (bytes):      19,412,929
合計の文書数:        2,909
追加検索語数:        2,910
合計検索語数:        2,910
わかち書き:          module_kakasi -ieuc -oeuc -w
経過時間 (秒):       113
譜/秒:               25.74
系:                  netbsd
Perl:                5.006001
Namazu:              2.0.12

ttyp1:makoto@harry  16:23:22/030717(~/Mail/inbox)> dprofpp -u
Total Elapsed Time = 98.40882 Seconds
         User Time = 82.86664 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 76.7   63.59 63.597   2909   0.0219 0.0219  File::MMagic::checktype_data
 6.01   4.981 10.325   2909   0.0017 0.0035  mknmz::put_field_index
 4.83   4.000  0.973  67063   0.0001 0.0000  IO::File::open
 3.05   2.529  4.185  67063   0.0000 0.0001  IO::File::new
 2.69   2.229  6.376  67063   0.0000 0.0001  util::fopen
 2.32   1.920  1.503  67063   0.0000 0.0000  Symbol::gensym
 2.31   1.917 68.317   2910   0.0007 0.0235  mknmz::load_document
 2.06   1.710  2.439  67063   0.0000 0.0000  IO::Handle::new
 1.93   1.600  1.313  52385   0.0000 0.0000  util::tmpnam
 1.46   1.210  1.207   2909   0.0004 0.0004  File::MMagic::checktype_byfilename
 1.34   1.110  6.476  61223   0.0000 0.0001  util::efopen
 1.32   1.090  0.446 134127   0.0000 0.0000  IO::Handle::DESTROY
 1.23   1.019 82.136   2910   0.0004 0.0282  mknmz::namazu_core
 0.97   0.800  0.347  93133   0.0000 0.0000  util::dprint
 0.83   0.690  0.812   2909   0.0002 0.0003  mknmz::complete_field_info
ttyp1:makoto@harry  16:24:27/030717(~/Mail/inbox)>

これでも NMZ.p* が出来ていない。

( つっこみ )

#3 [Namazu] また久し振りに初めから作る

--mailnews 付だとやはり速い。

perl -d:DProf /usr/pkg/bin/mknmz --mailnews -f /home/makoto/.mknmzrc-Mail-40 -O /export/namazu-Mail2 Mail

...
334359/334359 - /export/home/makoto/Mail/uucpconfig/tamagw/63 [message/rfc822]
索引を書き出しています...
[基本]
日付:                Thu Jul 17 17:48:30 2003
追加された文書数:    334,359
大きさ (bytes):      1,264,406,175
合計の文書数:        334,359
追加検索語数:        31,279
合計検索語数:        31,279
わかち書き:          module_kakasi -ieuc -oeuc -w
経過時間 (秒):       13,841
譜/秒:               24.16
系:                  netbsd
Perl:                5.006001
Namazu:              2.0.13pre2

ttyp0:makoto@u  17:48:38/030717(~)>

これは G4/400 での速さ。前回の機械は分らない。
と思ったら、また NMZ.p が出来ていない。

＠ perl -dDProf すると、NMZ.p が出来ない:

ようだ。起動に絶対 path を教える必要があるのと多分関係があるのだろう。

( つっこみ )

最近の日記
2025年02月13日
・dvipdfmx ICC profile format spec. version 4.3.0
2025年01月29日
・ham/wsjtx
2025年01月27日
・wip/wsjtx 5.4.2
2025年01月25日
・ham/wsjtx
2025年01月15日
・今更 advent calendar