トップ 差分 一覧 Farm ソース 検索 ヘルプ RSS ログイン

BugTrack-wiki/317

ページの作成や編集にはユーザ登録が必要です。

非 login 時のページ表示が遅い

  • 投稿者: ぐうます
  • カテゴリ: 本体
  • 優先度: 普通
  • 状態: リリース済
  • 日時: 2008年03月16日 22時12分58秒

 内容

login していないときの方が、login しているときに比べて、1 ページの表示に要する時間が長くなります。

試行時の環境と方法

  • FreeStyle Wiki 3.6.3dev3 (未改造)
    • 注:試したバージョンはこれですが、後述の通り、本件に該当するバージョンは多岐に渡ります。
  • 某共用サーバに、setup_rev01.zip(1714)(BugTrack-plugin/218)を使用して FSWiki をインストール
    • 注:これも試行環境の具体的説明であって、問題の発生要件ではありません。
  • Wiki ページ数:約 10000 ページ
  • wiki.cgi に -d:DProf を指定してプロファイル測定

試行結果

1 ページの表示に要する時間の測定結果は次の通りでした。

  • login 時、非 login 時、それぞれにて FrontPage 1 ページを表示したときの User+System Time。
  • 10 回試行

User+System Time 測定結果[sec]
状態 平均 最小 最大
login 時 0.840 0.573 1.050
非 login 時 1.786 1.274 2.260

次に、User+System Time の結果が上記の平均値に最も近い、それぞれの条件での dprofpp の結果例を示します。

  • login 時の dprofpp 結果の一例
Total Elapsed Time = 1.161642 Seconds
  User+System Time = 0.825704 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 21.3   0.176  0.337      8   0.0220 0.0421  Util::load_config_hash
 16.9   0.140  0.140  10027   0.0000 0.0000  HTML::Template::param
 10.4   0.086  0.350      2   0.0429 0.1752  Wiki::DefaultStorage::get_page_lis
                                             t
 9.33   0.077  0.295  20036   0.0000 0.0000  Wiki::can_show
 9.33   0.077  0.077  20260   0.0000 0.0000  Util::_unescape
 9.20   0.076  0.076  30446   0.0000 0.0000  Util::trim
 8.48   0.070  0.070  20036   0.0000 0.0000  Wiki::DefaultStorage::get_page_lev
                                             el
 7.39   0.061  0.061  40278   0.0000 0.0000  Wiki::config
 6.66   0.055  0.382  10022   0.0000 0.0000  Wiki::DefaultStorage::get_last_mod
                                             ified2
 5.69   0.047  0.061  20044   0.0000 0.0000  Wiki::get_login_info
 4.72   0.039  0.109  20036   0.0000 0.0000  Wiki::get_page_level
 3.75   0.031  0.126      8   0.0039 0.0158  main::BEGIN
 2.79   0.023  0.023     13   0.0018 0.0018  Util::load_config_text
 1.82   0.015  0.060      8   0.0019 0.0075  Wiki::BEGIN
 1.82   0.015  0.397  10022   0.0000 0.0000  Wiki::get_last_modified2
  • 非 login 時の dprofpp 結果の一例
Total Elapsed Time = 2.491163 Seconds
  User+System Time = 1.795851 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 25.6   0.461  0.461  20060   0.0000 0.0000  CGI::Util::rearrange
 13.4   0.241  0.896  20044   0.0000 0.0000  CGI::cookie
 11.3   0.204  0.400      8   0.0255 0.0500  Util::load_config_hash
 9.97   0.179  1.605  20036   0.0000 0.0001  Wiki::can_show
 8.24   0.148  1.044  20044   0.0000 0.0001  CGI2::get_session
 7.52   0.135  0.135  30446   0.0000 0.0000  Util::trim
 6.07   0.109  1.168  20044   0.0000 0.0001  Wiki::get_login_info
 5.23   0.094  0.093  20036   0.0000 0.0000  Wiki::DefaultStorage::get_page_lev
                                             el
 5.18   0.093  0.093  20068   0.0000 0.0000  UNIVERSAL::isa
 4.79   0.086  1.029      2   0.0429 0.5146  Wiki::DefaultStorage::get_page_lis
                                             t
 4.79   0.086  0.179  20036   0.0000 0.0000  Wiki::get_page_level
 4.57   0.082  0.082  10027   0.0000 0.0000  HTML::Template::param
 4.29   0.077  0.077  40275   0.0000 0.0000  Wiki::config
 3.01   0.054  0.054  20044   0.0000 0.0000  CGI::Cookie::get_raw_cookie
 3.01   0.054  0.054  20260   0.0000 0.0000  Util::_unescape

この結果を見ると、login 時の結果には見られない CGI 関連の処理が呼ばれている分、非 login 時は処理時間がかかっているように見えます。この中で、非 login 時の CGI2::get_session() に着目すると、FrontPage の表示でこの処理が呼ばれるのは、lib/Wiki.pm の get_login_info() からのみなので、このメソッドを調べてみました。login 情報を取得する get_login_info() は、最初に 1 回呼ばれたときの実行結果を $self->{'login_info'} にキャッシュし、次回以降はその値を返すことによって何度も同じ値を求めることを回避しているので、本来 CGI2::get_session() は 1 回しか呼ばれないはずなのですが、非 login 時にはどうもそうなっていないようです。

修正箇所:lib/Wiki.pm get_login_info()

よく考えると、非 login 時の get_login_info() の戻り値は undef なので、get_login_info() 冒頭におけるキャッシュ有無判定にあたり、現状の defined($self->{'login_info'}) では正しく判定できないようです。この判定を、

--- ../wiki3.6.3dev3orig/lib/Wiki.pm  Mon Dec 31 12:05:37 2007
+++ lib/Wiki.pm Sun Mar 16 07:48:27 2008
@@ -120,7 +120,7 @@
 #==============================================================================
 sub get_login_info {
  my $self    = shift;
- if(defined($self->{'login_info'})){
+ if (exists($self->{'login_info'})){
    return $self->{'login_info'};
  }

と exists($self->{'login_info'}) に書き直した上で、非 login 時について再測定した結果は次の通りです。

User+System Time 測定結果[sec]
状態 平均 最小 最大
login 時(defined 使用) 0.840 0.573 1.050
非 login 時(defined 使用) 1.786 1.274 2.260
非 login 時(exists 使用) 0.815 0.648 1.052

  • 非 login 時(exists 使用)の dprofpp 結果の一例
Total Elapsed Time = 2.061968 Seconds
  User+System Time = 0.804156 Seconds
Exclusive Times
%Time ExclSec CumulS #Calls sec/call Csec/c  Name
 26.9   0.217  0.217  40275   0.0000 0.0000  Wiki::config
 17.2   0.139  0.139  20260   0.0000 0.0000  Util::_unescape
 16.4   0.132  0.148  20036   0.0000 0.0000  Wiki::get_page_level
 13.1   0.106  0.321      8   0.0133 0.0402  Util::load_config_hash
 8.46   0.068  0.068  30446   0.0000 0.0000  Util::trim
 7.71   0.062  0.062  10027   0.0000 0.0000  HTML::Template::param
 7.71   0.062  0.335      2   0.0312 0.1674  Wiki::DefaultStorage::get_page_lis
                                             t
 6.72   0.054  0.373  20036   0.0000 0.0000  Wiki::can_show
 5.84   0.047  0.390  10022   0.0000 0.0000  Wiki::get_last_modified2
 3.85   0.031  0.126      8   0.0039 0.0158  main::BEGIN
 2.86   0.023  0.023     13   0.0018 0.0018  Util::load_config_text
 1.99   0.016  0.016      4   0.0039 0.0039  CGI::_compile
 1.99   0.016  0.343  10022   0.0000 0.0000  Wiki::DefaultStorage::get_last_mod
                                             ified2
 1.87   0.015  0.060      8   0.0019 0.0075  Wiki::BEGIN
 1.87   0.015  0.015  20036   0.0000 0.0000  Wiki::DefaultStorage::get_page_lev
                                             el

修正によって CGI 関連の処理がほとんど呼ばれなくなり、処理時間も login 時とほぼ同等になることが確認できました。

該当する FreeStyle Wiki バージョン

FreeStyle Wiki 3.5.4 を含む、それ以降の全てのバージョン(それ以前はキャッシュ処理自体が入っていなかったので、login 時/非 login 時ともに遅いはず)。

備考

本件で指摘した login 時/非 login 時の表示時間差は、その原因である get_login_info() の 1 回の処理時間差としては微々たるものなので、get_login_info() の呼び出し回数が多い運用でないと体感できません。get_login_info() が呼ばれる回数は、その FSWiki に存在する Wiki ページ数にほぼ比例するようなので、使用しているサーバの能力や表示するページの内容にもよると思いますが、Wiki ページ数が 5000〜10000 ページ程度? にならないと問題が表面化してこないと思われます。とはいえ、意図した処理と異なっていると思いますので、本件は修正すべきではないでしょうか。

 コメント

  • 詳しい調査までしていただきありがとうございます。3.6.3の正式版では修正させていただこうと思います。 - たけぞう (2008年03月17日 10時30分11秒)
  • 修正をCVSにコミットしました。 - たけぞう (2008年03月19日 00時27分53秒)
  • 感謝。適用後、速度アップが体感できました。 - 名無しさん (2008年03月20日 17時45分20秒)
  • 1000ページ弱程度ですが、明らかに速くなりました。ありがとうございます。 - 名無しさん (2008年03月20日 19時01分11秒)
  • 適用後子wikiでログインできなくなる現象が出ました。未だ原因不明です。 - 名無しさん (2008年03月20日 20時06分12秒)
  • CVS へのコミット、ありがとうございました。> たけぞうさん - ぐうます (2008年03月20日 23時32分30秒)
  • さて、「子 wiki でログインできなくなる現象」について詳細を伺いたいのですが、発生した現象は次の(1),(2)のうち、どちらでしょうか? - ぐうます (2008年03月20日 23時33分04秒)
    • (1). 文字通り「ログインできない」。すなわち、正しい ID とパスワードを入力しても管理ページに行き着けない。
    • (2). ログインできて管理ページにも行き着けるが、参照権限あるはずのページで「参照権限がない」といわれてページ参照ができない。
  • 実は、うちのサイトでは、本件の修正の前から(2)の現象が常にではなくときたま起きています。たまにしか起きないので、未だ原因が掴めないでおります。これと同じ現象だったりしないでしょうか? ちなみに、ページ依存性があるようで、同じ参照権限レベルのページでも参照できるページはできるのですが、参照できなくなるページはできなくなってしまうんですよね...。 - ぐうます (2008年03月20日 23時33分34秒)
  • # PATH_INFOを調べる部分でif(!defined($path_info)){ $path_info = ~ s/(.+)\1/$1/; }としたりこちらの対処をしてみましたが画像が表示されないなどありましたので出直してきます。- 名無しさん (2008年03月21日 14時30分08秒)==
  • 3.6.3でリリースしました。 - たけぞう (2008年12月14日 23時31分08秒)
お名前: コメント:

最終更新時間:2010年10月19日 01時21分21秒