| ■ あまつぶWiki □ あまつぶ過去ログ □ Macソフト □ Winソフト □ 掲示板 □ | |
| ＜カレンダー＞
2003 | 09 | 10 | 11 | 12 |
2004 | 01 | 02 | 03 | 04 | 05 | 06 | 07 | 08 | 09 | 10 | 11 | 12 | 2005 | 01 | 02 | 03 | 04 | 05 | 06 | 07 | 08 | 09 | 10 | 11 | 12 | 2006 | 01 | 02 | 03 | 04 | 05 | 06 | 07 | 08 | 09 | 10 | 12 | 2007 | 01 | 02 | 03 | 04 | 05 | 06 | 07 | 08 | 09 | 10 | 11 | 12 | 2008 | 01 | 02 | 03 | 04 | 05 | 06 | 07 | 08 | 09 | 10 | 11 | 12 | 2009 | 01 | 02 | 03 | 06 | 07 | 08 | 09 | 10 | 11 | 12 | 2010 | 01 | 03 | 04 | 05 | 06 | 07 | 09 | 11 | 2011 | 02 | 07 | 08 | 11 | |
[Diary]名古屋情報セキュリティ勉強会 #2
[POPFile] POPFile 1.1.2 が公開されました。 [Diary] Lion メモ [Diary] Adblock Plus で特定の要素を非表示に 雪！ geko のファームウェアアップデート Bad Elf GPS 購入 やっと届いた！ 整理券げっと 135 |
POPFile 0.22.2 から 0.22.3、0.22.4 から 0.22.5 のバージョンアップにおいて少しずつ細かな速度向上を図ってきたが、実際にどの程度の効果があったのか調べてみた。
テストには最近受信したメール 500 通を用い、POPFile に付属の bayes.pl スクリプトでメールを分類するのにかかる時間を測定した（実際のメールの受信時には、分類処理以外にもメールをサーバから受信してクライアントへ送る処理やメッセージを履歴に記録するといった処理があるが、今回は分類処理部分のみに注目した）。測定に際しては、どのルーチンで時間がかかっているのかを調べるため、Devel::DProf モジュールを用いた。結果にばらつきがあるようだったので、同じテストをそれぞれ 3 回行い、最も結果のよいものを比べることにした。
また、POPFile 0.22.3 では特に処理速度が向上するような修正を行っていないことから、このバージョンは除き、0.22.2、0.22.4、0.22.5 を比較することにした。現在テスト中の分かち書きプログラム切替パッチについてもテストしてみた。
まずは全体での比較から。500 通のメールを分類するのにかかった時間は、
0.22.2 104.5725 秒 4.78 通/秒 0.22.4 81.51022 秒 6.13 通/秒 0.22.5 61.09028 秒 8.18 通/秒 0.22.5+分かち書きパッチ Kakasi 53.75493 秒 9.30 通/秒 0.22.5+分かち書きパッチ MeCab 52.55238 秒 9.51 通/秒 0.22.5+分かち書きパッチ Internal 47.67753 秒 10.49 通/秒
という結果であった。それぞれのバージョン間で速度比較すると、
0.22.2 0.22.4 0.22.5 0.22.4 1.2829x - 0.22.5 1.7718x 1.3343x - 0.22.5+パッチ Kakasi 1.9434x 1.5163x 1.1365x 0.22.5+パッチ MeCab 1.9899x 1.5510x 1.1625x 0.22.5+パッチ Internal 2.1933x 1.7096x 1.2813x
という感じになった（横方向から見て、縦方向のバージョンに比べてどの程度速度が向上したかをあらわす）。最新バージョンの 0.22.5 は（分類処理だけで比べれば）0.22.2 よりも 1.77 倍高速になっている（もちろん、これは適当に選んだ 500 通のメールでのテスト結果なので、どんな場合でもこれだけ向上するという意味ではない）。また、0.22.4 と比べても 1.33 倍だ。いずれも個人的には「少しは速くなったかな」と体感できるくらいの変化があったことから、このくらいの効果はあったのだろう。
分かち書き切替パッチについては、現状のバージョンよりも 10 数%〜30%弱の向上が見込まれるとの結果が出た。こちらは体感としては違いを感じなかったが、数値では若干の差があるということだろうか。
0.22.2 から 0.22.3 のバージョンアップでは、分かち書き処理で使用している Kakasi の初期化を、メールの 1 行ごとではなくメール 1 通ごとに行うという修正を行った。バージョン 0.22.2 の Devel::DProf の結果は
Total Elapsed Time = 119.0525 Seconds User+System Time = 104.5725 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 31.3 32.77 37.465 40647 0.0008 0.0009 Classifier::MailParse::add_line 29.8 31.20 31.208 49765 0.0006 0.0006 Text::Kakasi::xs_getopt_argv 8.22 8.598 8.598 49765 0.0002 0.0002 Text::Kakasi::xs_do_kakasi 7.31 7.641 7.641 246276 0.0000 0.0000 DBI::st::fetchrow_arrayref 5.74 6.001 6.001 1512 0.0040 0.0040 DBI::st::execute 5.58 5.839 6.565 49904 0.0001 0.0001 Encode::Guess::guess 4.95 5.173 101.39 51068 0.0001 0.0020 Classifier::MailParse::parse_line 4.10 4.289 120.16 500 0.0086 0.2403 Classifier::Bayes::classify 3.27 3.424 33.148 31239 0.0001 0.0011 Classifier::MailParse::parse_html 3.25 3.400 3.400 187977 0.0000 0.0000 Classifier::WordMangle::mangle 3.22 3.367 3.367 51434 0.0001 0.0001 Encode::JP::JIS7::jis_euc 1.98 2.066 33.274 49765 0.0000 0.0007 Text::Kakasi::getopt_argv 1.85 1.938 1.938 49765 0.0000 0.0000 Text::Kakasi::xs_close_kanwadict 1.53 1.595 7.196 49904 0.0000 0.0001 Classifier::MailParse::convert_enc oding 1.19 1.240 2.119 10042 0.0001 0.0002 Classifier::MailParse::add_url 0.91 0.951 0.951 187857 0.0000 0.0000 Classifier::MailParse::increment_w ord 0.87 0.915 11.807 9212 0.0001 0.0013 Classifier::MailParse::parse_heade r 0.87 0.913 102.79 500 0.0018 0.2056 Classifier::MailParse::parse_file 0.77 0.806 9.404 49765 0.0000 0.0002 Text::Kakasi::do_kakasi 0.65 0.681 44.982 49765 0.0000 0.0009 Classifier::MailParse::parse_line_ with_kakasi 0.48 0.500 1.156 9325 0.0001 0.0001 Classifier::MailParse::update_tag 0.38 0.397 0.397 1017 0.0004 0.0004 DBD::SQLite2::st::_prepare 0.30 0.314 0.833 13234 0.0000 0.0001 Classifier::MailParse::update_pseu doword 0.28 0.296 0.627 6211 0.0000 0.0001 Classifier::MailParse::decode_stri ng 0.23 0.239 0.271 500 0.0005 0.0005 Classifier::MailParse::start_parse 0.22 0.234 0.296 301064 0.0000 0.0000 Encode::getEncoding 0.22 0.230 0.410 31984 0.0000 0.0000 Encode::utf8::decode_xs 0.17 0.180 0.180 31984 0.0000 0.0000 Encode::Encoding::renewed 0.16 0.168 4.000 174743 0.0000 0.0000 Classifier::MailParse::update_word 0.14 0.149 0.149 2483 0.0001 0.0001 Classifier::MailParse::compute_rgb _distance
となっており、Classifier::MailParse::parse_line_with_kakasi サブルーチン内で約 45 秒（表中で、ExclSec はそのルーチンのみ（そこから呼ばれるサブルーチンは除く）でかかった時間を、CumulS はそのルーチンとそこから呼ばれるサブルーチンでかかった時間の合計をあらわしている）という長い時間がかかっていることがわかる。ここから呼ばれているサブルーチンを探すと、Text::Kakasi::getopt_argv に約 33 秒、Text::Kakasi::do_kakasi に約 9 秒がかかっている。このうち Text::Kakasi::getopt_argv を呼ぶ回数を減らしたバージョン 0.22.4 では、
Total Elapsed Time = 92.22022 Seconds User+System Time = 81.51022 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 35.0 28.58 37.239 40763 0.0007 0.0009 Classifier::MailParse::add_line 10.9 8.920 8.920 247076 0.0000 0.0000 DBI::st::fetchrow_arrayref 8.32 6.778 13.787 49949 0.0001 0.0003 Encode::Guess::guess 8.20 6.683 95.696 500 0.0134 0.1914 Classifier::Bayes::classify 7.68 6.259 6.259 1512 0.0041 0.0041 DBI::st::execute 5.31 4.327 4.327 188926 0.0000 0.0000 Classifier::WordMangle::mangle 4.92 4.012 4.012 9674 0.0004 0.0004 Text::Kakasi::xs_do_kakasi 4.54 3.698 70.480 51068 0.0001 0.0014 Classifier::MailParse::parse_line 3.73 3.041 8.322 175676 0.0000 0.0000 Classifier::MailParse::update_word 3.47 2.830 2.830 51463 0.0001 0.0001 Encode::JP::JIS7::jis_euc 3.11 2.539 31.671 31242 0.0001 0.0010 Classifier::MailParse::parse_html 2.09 1.701 18.974 49949 0.0000 0.0004 Classifier::MailParse::convert_enc oding 1.97 1.608 1.608 188806 0.0000 0.0000 Classifier::MailParse::increment_w ord 1.61 1.309 1.345 301245 0.0000 0.0000 Encode::getEncoding 1.50 1.222 2.567 301245 0.0000 0.0000 Encode::find_encoding 1.42 1.158 2.549 10050 0.0001 0.0003 Classifier::MailParse::add_url 1.13 0.919 4.876 51463 0.0000 0.0001 Encode::JP::JIS7::decode 1.11 0.902 72.783 500 0.0018 0.1456 Classifier::MailParse::parse_file 1.08 0.882 2.965 49928 0.0000 0.0001 Encode::from_to 1.00 0.815 12.103 9212 0.0001 0.0013 Classifier::MailParse::parse_heade r 0.93 0.754 4.950 49810 0.0000 0.0001 Classifier::MailParse::parse_line_ with_kakasi 0.82 0.666 0.666 100598 0.0000 0.0000 DBD::_::db::quote 0.73 0.599 1.068 51463 0.0000 0.0000 Encode::decode 0.62 0.507 0.507 187560 0.0000 0.0000 Encode::XS::decode 0.58 0.475 1.269 9492 0.0001 0.0001 Classifier::MailParse::update_tag 0.52 0.422 0.422 59692 0.0000 0.0000 Encode::Encoding::name 0.50 0.407 0.407 500 0.0008 0.0008 Text::Kakasi::xs_getopt_argv 0.48 0.392 0.518 32004 0.0000 0.0000 Encode::utf8::decode_xs 0.48 0.391 14.177 49949 0.0000 0.0003 Encode::Guess::guess_encoding 0.43 0.351 1.017 100598 0.0000 0.0000 DBI::db::quote
という結果になった。0.22.2 で大きな時間がかかっていた Classifier::MailParse::parse_line_with_kakasi は 5 秒弱に短縮され、上位にいた Text::Kakasi::xs_getopt_argv は 500 回（＝メール数）しか呼ばれなくなった。代わりに目立つようになったのは文字コードを変換する Encode 関係のルーチンだ。中でも文字コードを推測する Encode::Guess::guess が（そこから呼び出されるルーチンを含めて）14 秒弱を占めている。バージョン 0.22.5 ではここに手を加えた。その結果、
Total Elapsed Time = 72.14028 Seconds User+System Time = 61.09028 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 48.0 29.34 34.571 40763 0.0007 0.0008 Classifier::MailParse::add_line 12.3 7.521 7.521 247127 0.0000 0.0000 DBI::st::fetchrow_arrayref 10.7 6.543 6.543 1512 0.0043 0.0043 DBI::st::execute 8.18 4.996 68.601 500 0.0100 0.1372 Classifier::Bayes::classify 6.18 3.774 3.774 9674 0.0004 0.0004 Text::Kakasi::xs_do_kakasi 5.74 3.508 3.508 189216 0.0000 0.0000 Classifier::WordMangle::mangle 3.77 2.303 48.033 51068 0.0000 0.0009 Classifier::MailParse::parse_line 3.08 1.882 29.035 31242 0.0001 0.0009 Classifier::MailParse::parse_html 2.16 1.320 2.228 10150 0.0001 0.0002 Encode::Guess::guess 1.95 1.191 1.191 19881 0.0001 0.0001 Encode::JP::JIS7::jis_euc 1.68 1.024 1.816 10050 0.0001 0.0002 Classifier::MailParse::add_url 1.59 0.970 0.970 189096 0.0000 0.0000 Classifier::MailParse::increment_w ord 1.38 0.846 3.513 49949 0.0000 0.0001 Classifier::MailParse::convert_enc oding 1.23 0.754 4.583 175966 0.0000 0.0000 Classifier::MailParse::update_word 1.14 0.699 10.194 9212 0.0001 0.0011 Classifier::MailParse::parse_heade r 0.92 0.564 0.564 500 0.0011 0.0011 Text::Kakasi::xs_getopt_argv 0.73 0.449 0.449 1017 0.0004 0.0004 DBD::SQLite2::st::_prepare 0.51 0.312 49.829 500 0.0006 0.0997 Classifier::MailParse::parse_file 0.46 0.283 0.713 9492 0.0000 0.0001 Classifier::MailParse::update_tag 0.44 0.267 0.924 500 0.0005 0.0018 Classifier::MailParse::start_parse 0.33 0.199 0.199 10129 0.0000 0.0000 Encode::XS::encode 0.32 0.193 0.193 100619 0.0000 0.0000 DBD::_::db::quote 0.24 0.148 0.263 6211 0.0000 0.0000 Classifier::MailParse::decode_stri ng 0.22 0.134 0.134 21433 0.0000 0.0000 Encode::XS::decode 0.18 0.113 0.761 13250 0.0000 0.0001 Classifier::MailParse::update_pseu doword 0.18 0.108 0.125 13 0.0083 0.0096 Classifier::Bayes::BEGIN 0.16 0.099 0.099 1021 0.0001 0.0001 DBI::_new_handle 0.15 0.093 0.093 1512 0.0001 0.0001 Classifier::Bayes::valid_session_k ey__ 0.15 0.089 0.319 11 0.0081 0.0290 POPFile::Loader::load_module_ 0.14 0.088 0.341 500 0.0002 0.0007 Classifier::Bayes::get_buckets_wit h_magnets
となり、Encode::Guess::guess の 1 回あたりの実行時間はそれほど変わらない（0.22.4 では 13.787/49949=0.000276 秒/回、0.22.5 では 2.228/10150=0.000220 秒/回）が、呼び出し回数が大幅に減った（約 1/5）ため時間を節約することができた。文字コード変換ルーチン（Classifier::MailParse::convert_encoding）全体で見れば、19 秒弱から 4 秒弱と大きく速度が向上しているのがわかる。
最後に分かち書き切り替えパッチを適用し、内蔵パーサを使った場合の結果。
Total Elapsed Time = 57.98753 Seconds User+System Time = 47.67753 Seconds Exclusive Times %Time ExclSec CumulS #Calls sec/call Csec/c Name 57.1 27.23 29.545 40762 0.0007 0.0007 Classifier::MailParse::add_line 15.3 7.321 7.321 239882 0.0000 0.0000 DBI::st::fetchrow_arrayref 12.9 6.150 6.150 1512 0.0041 0.0041 DBI::st::execute 7.88 3.757 54.967 500 0.0075 0.1099 Classifier::Bayes::classify 5.43 2.587 2.587 187868 0.0000 0.0000 Classifier::WordMangle::mangle 3.67 1.751 37.585 51068 0.0000 0.0007 Classifier::MailParse::parse_line 3.32 1.583 25.460 31242 0.0001 0.0008 Classifier::MailParse::parse_html 2.52 1.202 1.202 19881 0.0001 0.0001 Encode::JP::JIS7::jis_euc 2.14 1.021 1.304 10150 0.0001 0.0001 Encode::Guess::guess 2.02 0.962 1.464 10051 0.0001 0.0001 Classifier::MailParse::add_url 1.98 0.942 0.942 49810 0.0000 0.0000 Classifier::MailParse::parse_line_ with_internal_parser 1.42 0.675 2.113 49949 0.0000 0.0000 Classifier::MailParse::convert_enc oding 1.31 0.626 7.908 9212 0.0001 0.0009 Classifier::MailParse::parse_heade r 1.11 0.529 0.529 187742 0.0000 0.0000 Classifier::MailParse::increment_w ord 0.79 0.377 0.377 1017 0.0004 0.0004 DBD::SQLite2::st::_prepare 0.69 0.327 38.682 500 0.0007 0.0774 Classifier::MailParse::parse_file 0.54 0.258 0.850 9491 0.0000 0.0001 Classifier::MailParse::update_tag 0.47 0.223 0.250 6211 0.0000 0.0000 Classifier::MailParse::decode_stri ng 0.44 0.211 0.211 21433 0.0000 0.0000 Encode::XS::decode 0.30 0.141 0.206 500 0.0003 0.0004 Classifier::MailParse::start_parse 0.29 0.137 0.137 2503 0.0001 0.0001 Classifier::MailParse::compute_rgb _distance 0.23 0.109 0.307 11 0.0099 0.0279 POPFile::Loader::load_module_ 0.18 0.088 0.114 13 0.0068 0.0087 Classifier::Bayes::BEGIN 0.16 0.075 0.075 3427 0.0000 0.0000 Classifier::MailParse::map_color 0.13 0.060 0.060 1512 0.0000 0.0000 Classifier::Bayes::valid_session_k ey__ 0.10 0.048 0.048 10129 0.0000 0.0000 Encode::XS::encode 0.10 0.047 0.082 232 0.0002 0.0004 Encode::Alias::find_alias 0.10 0.047 0.047 1021 0.0000 0.0000 DBI::_new_handle 0.09 0.043 0.439 13251 0.0000 0.0000 Classifier::MailParse::update_pseu doword 0.08 0.037 0.060 502 0.0001 0.0001 Classifier::Bayes::get_buckets
先ほどの 0.22.5 の表には（そのルーチン自体の処理時間が短いため）出てきていなかったが、分かち書き処理を行っているルーチン（Classifier::MailParse::parse_line_with_kakasi）は全体で 4 秒弱の時間がかかっていた（そこから呼ばれている Text::Kakasi::xs_do_kakasi は表に載っている）。これの代わりとなる Classifier::MailParse::parse_line_with_internal_parser は 1 秒弱なので、メール 500 通あたり約 3 秒（メール 1 通あたりでは 0.006 秒）の時間短縮ができたことになる。初期化ルーチン（0.64 秒 / 500 通）とあわせても微々たる差でしかないが、多少は効果があると言えるだろうか（まあ、内蔵パーサに対応する目的は、速度向上というよりも外部モジュールがなくても動作するようにすることなので速度的な効果がなくても問題はない）。
ここまでくると、日本語処理のメインルーチンである、Classifier::MailParse::convert_encoding と Classifier::MailParse::parse_line_with_internal_parser をあわせても全体の 6% ほどにしかならない（0.22.2 の時点ではほぼ半分、0.22.4 では約 3 割、0.22.5 では約 12% であった）。これはもうこれらのルーチンを改善してもほとんど効果はないということだ。あとどこかあるとしたら、呼び出し回数も多く時間も比較的かかっている Classifier::MailParse::add_line あたりだろうか。このルーチンだけで半分以上の時間を使っているのだから調べてみない手はない。単語に切り分ける処理で使っている正規表現あたりに改善の余地があるかもしれない。ちょっと考えてみよう。