2003/06/06

記事一覧へ >>

学生がインターネットを介して大学の履修科目を登録する「Web科目登録システム」。早稲田大学は3月20日にこのシステムを稼働させたが，トラブルが相次ぎ3月28日に利用を中止した。トラブル原因の一つはプログラム中のSQL文のミス。初歩的なミスだが事前のテストで見つけられなかった。

図1●早稲田大学のトラブル状況 3つのトラブルが相次いで発生し「Web科目登録」の利用中止に追い込まれた。3つのトラブルの原因は，(1)SQL文のミス，(2)php.iniファイルなどの設定が不適切だったこと，(3)負荷分散装置のファームウエアのバグ――であった

　Web科目登録システムは，2002年12月から稼働している早稲田大学のポータル・システム「Waseda-netポータル」のサービスの一つである。Waseda-netポータルでログイン処理を実施し，ユーザー認証した後でWeb科目登録が利用できる仕組みになっている。Web科目登録システムのリリースは2003年3月20日。システム開発はNECが担当した。

　最初のトラブルは，Web科目登録がリリースされる当日の3月20日に起きた。その後Web科目登録にトラブルが相次いで発生し，Web科目登録はほとんど利用できない状態が約1週間にわたって続いた。3つのトラブルが連続して起きた（図1[拡大表示]）。

　3つのトラブルのうち2つの原因は，アプリケーションのミスである。Web科目登録システムはリリースする約3カ月前に完成し，NECが早稲田大学に納めていた。大学側では動作確認テストのほか，商用の負荷テスト・ツールを用いた高負荷テストを実施。「テスト結果は問題なしと判断していた」（早稲田大学 教務部情報企画課 神馬豊彦氏）が，実際はアプリケーションの品質は低かった。ミスを見つけられなかったテストの方法にも問題があったと考えられる。

　最初のトラブルから8日後の28日午前1時ごろに問題は解決した。だがトラブルが相次いだため，4月からの新学期の科目登録ではこのシステムの利用中止を決定。その時点で科目登録できていない学生には，従来通り大学に出向いて実施してもらうことにした。

不正アクセスを疑ったが“シロ”

　第1のトラブルは，Web科目登録の利用を開始する12時間前に起きた。3月20日午前0時ごろから，Waseda-netポータルに対するアクセスが急増。「ログイン・ページが表示できない」「ログインに時間がかかる」といった状況に陥り，Waseda-netポータル自体にログインできなくなった。

　Web科目登録をまだリリースしていないのにアクセス数が急増したため「最初は不正アクセスを疑った」（神馬氏）。ネットワークを切断して調査したところ，正当なユーザーIDを用いたログイン要求であると判断。同日午前3時ごろにネットワークを再接続した。再接続後は小康状態が続いた。

図2●「Waseda-netポータル」と「Web科目登録」のシステム構成 アプリケーションはPHPで記述し，RDBMSはPostgreSQL 7.2を採用していた

　アクセス数が急増した確かな理由は不明だが，(1)20日午前0時に一部の学部で試験結果をポータルで発表したこと，(2)Web科目登録の開始時間は20日午後0時（正午）であるが，学生がそれを午前0時と間違えたことが考えられた。

不要な全件検索を実施していた

　20日の午前9時を過ぎたころから再びアクセス数が増加し始め，ログインに時間がかかるといった症状が再発した。正当な利用者からのアクセスであるにもかかわらず，ログイン処理がパンクしてしまった。サーバーのリソース状況を調査したところ，データベース・サーバーのCPU使用率が95％を超えており，データベースがボトルネックになっていることが分かった。

　システムはWebサーバーとDBサーバーの2層構造で，WebサーバーにはApacheを，データベースにはPostgreSQLを利用し，アプリケーションはPHPで開発していた（図2[拡大表示]）。

　セッション情報をデータベースに格納しているため，ログイン処理中にデータベースに書き込みを行っている。だがCPUの使用率が95％になるのは異常であったため，ログイン処理プログラムのSQL文を疑い調査した。そこで不適切なSQL文を見つけた。

図3●トラブルの原因となったSQL文 「セッションID」カラムにはインデックスが張られているが，関数を利用したため，インデックスが使われなかった

　ログイン処理ではセッション・テーブルにデータを追加するだけでよかったにもかかわらず，セッション・テーブルを検索していた。しかも，セッション・テーブルにはインデックスを張っているが，SQL文の書き方が不適切で，インデックスが使われないようになっていた。

　図3[拡大表示]が，問題を起こしたSQL文のプログラムである。一般的に検索条件で関数を適用するとインデックスが使われなくなる。図3のケースでは「セッションID」カラムのインデックスが使われず，ログイン処理のたびに負荷の重い全件検索が行われていた。ログイン時にセッション・テーブルを検索しないようにSQL文を修正すると，ログイン処理の負荷は下がった。

　ポータルは2002年12月から稼働していたが，このトラブルが起きるほどのアクセスは無かった。

DBオープン処理を毎回実施

　第2のトラブルは，Web科目登録システムで起きた。「応答が悪い」というトラブルだった。

　実はこのトラブルは，ある程度予想することができていた。PHPのアプリケーションからPostgreSQLに接続するプログラムにおいて，データベースのオープン処理を少なくする「DBコネクション・プーリング機能」を使っていなかったからだ。

図4●トラブルの原因となった各種設定ファイルの設定値 図左の設定ではデータベース・コネクション・プーリングが有効に働かず，応答が悪いというトラブルが起きた

　当初は，DBコネクション・プーリング機能を利用するDB接続関数「pg_pconnect」を使ってアプリケーションを開発していた。ところがテストしたところDBコネクション・プーリング機能が有効に働かず，性能が低かった。むしろDBコネクション・プーリング機能を利用しないDB接続関数「pg_connect」を使った方が性能が高かった。このような経緯からWeb科目登録システムではpg_connect関数を使っていた。

　しかし，Web科目登録のアプリケーションは各WebページでDBを接続するようになっている。DBコネクション・プーリング機能を使わないと，ページを表示するごとにデータベースのオープン処理を行うことになる。

　「応答が悪い」という問題が実際に起きてしまったため，なぜテスト時にDBコネクション・プーリング機能が有効に機能しなかったかを改めて調査。実験環境を構築して試行錯誤し，php.iniとhttpd.confという2つの設定ファイルの値が不適切だったことを突き止めた（図4[拡大表示]）。設定ファイルの値を適切にしてpg_pconnect関数を使うように変更し，Web科目登録の応答時間が短くなった。

負荷分散装置が機能しない

　第3のトラブルは，第2のトラブルが解決する前に起きた。その時Web科目登録用のWebサーバーは8台あったが，そのうちの2台に処理が集中し，Web科目登録がほとんど応答しなくなった。Webサーバーの挙動がそれまでと変わったため，第2のトラブルとは別の問題だと判断した。

　原因は，負荷分散装置だった。6台のWebサーバーと通信できなくなっていた。また，勝手にリブートするなどの症状も表れた。一度装置を取り替えたが状況は変わらず，メーカーの調査でファームウエアのバグだと分かり，ファームウエアをバージョンアップすることでトラブルを解決した。