Text::ParseWords が遅い件。
妙に遅いルーチンがあって、ボトルネック探しに
Devel::DProf 使ってみてたら、Text::ParseWords が時間くってた。
あらー、そうなんだ。
・quotewords を使った場合のテストスクリプト
#!/usr/bin/perl -wuse strict;
use Text::ParseWords;
my $testString = "aaa,bbb,ccc,ddd,eee,fff,ggg\n";
&repeatSplit(\$testString);
exit;
sub repeatSplit(\$;$) {
my $refTestString = shift;
my $times = shift || 100;
for (1..$times) {
&splitLine($refTestString);
}
}
sub splitLine($) {
my $refTestString = shift;
my (@testArray) = "ewords(",", 0, $$refTestString);
print join "\t", @testArray;
}
・測定結果
Total Elapsed Time = 0.238056 SecondsUser+System Time = 0.208056 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
43.2 0.090 0.090 100 0.0009 0.0009 Text::ParseWords::parse_line
13.9 0.029 0.139 100 0.0003 0.0014 main::splitLine
9.61 0.020 0.158 1 0.0197 0.1582 main::repeatSplit
9.13 0.019 0.109 100 0.0002 0.0011 Text::ParseWords::quotewords
4.81 0.010 0.010 1 0.0100 0.0100 warnings::BEGIN
4.81 0.010 0.020 3 0.0033 0.0067 vars::BEGIN
4.81 0.010 0.040 2 0.0050 0.0199 main::BEGIN
4.81 0.010 0.030 4 0.0025 0.0075 Text::ParseWords::BEGIN
0.00 - -0.000 1 - - vars::import
0.00 - -0.000 1 - - warnings::unimport
0.00 - -0.000 1 - - re::bits
0.00 - -0.000 2 - - Exporter::import
0.00 - -0.000 2 - - warnings::register::mkMask
0.00 - -0.000 1 - - re::import
0.00 - -0.000 2 - - strict::bits
とにかく、quoterwords から呼ばれてる parse_line が遅い。
ExclSec が呼び出してる外部ルーチンの実行時間は含まず、
CumulS は呼び出してる外部ルーチンの実行時間も含むけど…
9.13 0.019 0.109 100 0.0002 0.0011 Text::ParseWords::quotewords
…とあるように、quoterwords 自体は 0.019 しかかかってないのに
そこから呼び出してるルーチンも含めると、0.109 になっちまう。
つまり、外部ルーチンで 0.09 かかってる訳ですが。
parse_line の結果を見てみると…
43.2 0.090 0.090 100 0.0009 0.0009 Text::ParseWords::parse_line
…となってて、そのモロに 0.09 な次第。嗚呼 orz
で、サンプル程度の簡単な構造のテキストだったら
split でカンマ区切りにしてやりゃいい訳で、
それも試しにやってみたところ。。。
・代わりに split を使った場合のテストスクリプト
#!/usr/bin/perl -wuse strict;
my $testString = "aaa,bbb,ccc,ddd,eee,fff,ggg\n";
&repeatSplit(\$testString);
exit;
sub repeatSplit(\$;$) {
my $refTestString = shift;
my $times = shift || 100;
for (1..$times) {
&splitLine($refTestString);
}
}
sub splitLine($) {
my $refTestString = shift;
my (@testArray) = split /,/, $$refTestString;
print join "\t", @testArray;
}
・計測結果
Total Elapsed Time = 0.139376 SecondsUser+System Time = 0.109376 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
82.2 0.090 0.090 100 0.0009 0.0009 main::splitLine
9.14 0.010 0.010 1 0.0100 0.0100 main::BEGIN
9.14 0.010 0.099 1 0.0097 0.0994 main::repeatSplit
0.00 - -0.000 1 - - strict::bits
0.00 - -0.000 1 - - strict::import
当たり前っちゃー当たり前だけど、速い。
quotewords と比べて、58%程度で済んでいるよね。
試しにもっとループ回数を増やすと、差はますます広がるのかな？
■10000回の繰り返しにした場合
・quotewords の場合
Total Elapsed Time = 12.66980 SecondsUser+System Time = 10.52980 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
61.2 6.445 6.445 10000 0.0006 0.0006 Text::ParseWords::parse_line
17.8 1.880 10.205 10000 0.0002 0.0010 main::splitLine
17.8 1.880 8.325 10000 0.0002 0.0008 Text::ParseWords::quotewords
3.66 0.385 10.590 1 0.3850 10.590 main::repeatSplit
0.19 0.020 0.030 3 0.0067 0.0100 vars::BEGIN
0.09 0.010 0.010 1 0.0100 0.0100 warnings::register::import
0.09 0.010 0.040 2 0.0050 0.0199 main::BEGIN
0.00 - -0.000 1 - - vars::import
0.00 - -0.000 1 - - warnings::BEGIN
0.00 - -0.000 1 - - warnings::unimport
0.00 - -0.000 1 - - re::bits
0.00 - -0.000 2 - - warnings::register::mkMask
0.00 - -0.000 1 - - re::import
0.00 - -0.000 2 - - strict::bits
0.00 - -0.000 2 - - Exporter::import
・split の場合
Total Elapsed Time = 7.669954 SecondsUser+System Time = 4.069954 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c Name
80.7 3.285 3.285 10000 0.0003 0.0003 main::splitLine
19.5 0.795 4.080 1 0.7950 4.0800 main::repeatSplit
0.00 - -0.000 1 - - strict::bits
0.00 - -0.000 1 - - strict::import
0.00 - -0.000 1 - - main::BEGIN
あら、60%程だそうで。
まぁ、とにかく速いこた速いから、無闇に quotewords 使わずに
必要なところでだけ、quotewords 使うのが良いようだね。。。
あ、ついでに忘れちゃうから、 DProf 関連メモ。
・DProf で測定しながら実行
perl -d:Dprof テストスクリプト
・Dprof の測定結果表示
dprofpp
・測定結果から、通過したサブルーチンを表示
dprofpp -t
・dprofpp で表示される結果の項目
%Time
このルーチンの実行時間が全体のうち何パーセントか
ExclSec
このルーチンの実行時間（秒）※このルーチンから呼ばれた外部のルーチンの実行時間は含まず
CumulS
このルーチンの実行時間（秒）※このルーチンから呼ばれた外部のルーチンの実行時間も含む
#Calls
呼ばれて実行された回数
sec/call
1回の実行につき、平均何秒かかったか
Csec/c
1回の実行につき、平均何秒かかったか ※このルーチンから呼ばれた外部のルーチンの実行時間も含む
Name
サブルーチン（メソッド）名
