本記事では、ZOZOTOWNを裏側から支えているバックオフィスシステムにおけるトラブルシューティング事例をご紹介したいと思います。
尚、今回の話題はバックオフィスシステムで使用しているVBScript言語がメインとなります。WEBサーバーはIIS、DBMSはSQL Serverを使っている環境です。
ZOZOTOWNのバックオフィスシステムについて
ZOZOTOWNのバックオフィスシステム（以後、BOと呼ぶ）では、顧客管理や物流管理などを行っています。
BOの開発はすべて弊社の社員で行っています。ZOZOTOWNを裏側から支えるシステムを開発する責任は大きいですが、その分やりがいを感じることも多いです。例えば、顔見知りの社員がユーザーのため、直接システムへのフィードバックがもらえます。システム改善によって別の部署の業務効率を向上させることができたり、抱えている問題を解決することができたときはとても喜んでくれて、それが次の開発へのモチベーションにつながります。
社内の様々な部署でBOが使われていますが、物流拠点「ZOZOBASE」は最もBOユーザーが多い拠点の一つです。
ZOZOBASEではメンバーの大半がBOを使って業務を行っています。そのため、BOのレスポンスタイムは作業効率に大きな影響を及ぼします。
ある時期から、BOのレスポンスタイムが突発的に著しく低下する事象が断続的に発生するようになりました。その問題の調査と解決方法について、順を追ってご紹介します。
BOで発生した問題について
ある日、物流部門から「BOが重い」との問い合わせを受けました。
アプリケーションのタイムアウト発生状況を確認すると、確かにタイムアウトエラーが頻発していました。
ただし、通常時と比較して平均のレスポンスタイムがどの程度増加しているのかについては確認する仕組みがありませんでした。その日は1時間ほど経過後、自然解消しましたが、その後1日1回程度の頻度で同様の事象が発生するようになりました。
BOのレスポンスタイムが低下すると、処理効率が低下し、結果的に人件費というコストの増加につながります。
出来る限り迅速に問題を解決すべく、調査を実施しました。
原因調査
DBでスロークエリが多発している可能性を疑い、DBで現在実行中のクエリリストを取得してみました。
その結果、DBでスロークエリが多発しているわけではありませんでした。このためDB起因でのレスポンス低下ではないと判断しました。
次に、WEBサーバー側で処理中の要求一覧を確認しました。
[インターネットインフォメーションサービス(IIS)マネージャー]を起動し、[ワーカープロセス]へ
該当のアプリケーションプール名をダブルクリック
現在の要求一覧を確認
上記の例では要求が6件ですが、調査実行時は、100件ほどの要求を常時処理している状況でした。通常時と比べて明らかに「経過時間」が遅くなっており、そのため同時実行数が多くなっていました。
この時点で、物流拠点から問い合わせをもらった「BOが重い」という事象について以下のように整理しました。
・WEBサーバーのレスポンスタイムが通常時より遅延している
・そのためWEBサーバーで実行中の要求数が増加している
・ただし、DBでスロークエリが多発しているわけではなく、DB起因の遅延ではない
・したがって、WEBサーバー側で何らかの問題が発生して遅延につながっているはず
さらに調査を続けます。タイムアウトエラーが発生したときのエラーメッセージを確認すると、「[DBNETLIB][ConnectionOpen (Connect()).]SQL Server が存在しないか、アクセスが拒否されました。」となっていました。DBへの接続を確立しようとしてタイムアウトしているようです。
タイムアウトエラーが発生したプログラムの該当行を確認すると、DBに対してクエリを実行する処理でした。SQL Serverへの接続にはOLE DB Provider for SQL Server (SQLOLEDB)を使用しています。
SQLOLEDBを介して接続する場合は、既定でコネクションプーリングが有効になっています。ですが、エラーメッセージを確認する限りプールから接続を再利用せずに新規で接続しているようでした。なぜこのような挙動をしているかこの時点では理解できませんでした。
まずは本当に新規で接続しているのか検証するために、該当プログラムの該当関数を開発環境で実行し、その時の接続状況をSQL Server Profilerで確認してみました。
SSMS（SQL Server Management Studio）の[ツール]-[SQL Server プロファイラー]からProfilerを起動します。
[イベントの選択]で[すべての列を表示する]にチェックを入れた後、[Security Audit]-[Audit Login]を選択します。
次に[実行]を押してProfilerを開始し、接続状況を確認したい関数を実行後、Profilerを停止します。
↑Profilerで取得したイベントです。[EventSubClass]という項目を確認すると、[2-Pooled]（コネクションプールから再利用された）の次に、[1-Nonpooled]（新規接続が発生）という順番でAudit Loginイベントが発生していました。
推測していた通り、該当関数では新規接続が発生していることが確認できました。
今までの調査から、コネクションプールにプールされたコネクションをうまく再利用できておらず、新規接続が大量に発生している可能性があると推測しました。コネクションまわりのトラブルのため、WEBサーバーのポートの状態を確認してみました。
Power Shellで以下のコマンドを実行します。
Get-NetTCPConnection | GROUP-Object State
その結果、利用可能な動的ポート数の大半がstate=TIME_WAITとなっていました。監視製品のグラフで確認しても、物流拠点の稼働中は大量のTIME_WAITなポートが確認できました。
緑色：TIME_WAIT 赤色:ESTABLISHED 黒色:Total
ポートのstateがTIME_WAITになると、そのポートが再利用可能な状態となるまでに一定時間（デフォルト値は4分）経過する必要があります。そのため、使用可能な動的ポート数の大半がstate=TIME_WAITとなってしまうと、使用可能なTCPポートが枯渇し、新規接続時にエラーとなってしまう可能性があります。
したがって、今回の不具合の原因としては「何らかの理由で使用可能な動的ポートの大半がTIME_WAITとなり、新規接続に時間がかかることによるレスポンス遅延や、タイムアウトエラーの多発につながった」可能性が高いと判断しました。
次に、使用可能な動的ポートの大半がTIME_WAITとなっている原因を調査しました。
マイクロソフトのドキュメントによると、コードの書き方によっては、暗黙の接続が発生するようです。また、暗黙の接続はプールされないとの記述もありました。プールされないということは、接続を閉じるとstate=TIME_WAITになります。コードの書き方が今回の事象の根本的な原因のようです。
暗黙の接続が発生するコードの例としては以下のようなパターンが考えられます。レコードセットを開いた状態で、同一コネクションオブジェクトで二つ目のクエリを実行しようとすると、既にコネクションが使われている状態のため、暗黙の接続が発生してしまいます。
Dim ConnectionObject
Dim RecordSet
Set ConnectionObject= CreateObject("ADODB.Connection")
ConnectionObject.open "接続文字列"
Set RecordSet= ConnectionObject.Execute("select * from SomeTable") '//初回実行
Set RecordSet= ConnectionObject.Execute("select * from SomeTable") '//二回目の実行（暗黙の接続発生）
ここまでの調査内容をまとめると、不具合の原因は「暗黙の接続が発生するコードの書き方になっている関数が短期間に大量に実行され、結果として使用可能な動的ポートの大半がTIME_WAITとなり、新規接続に時間がかかることによるレスポンス遅延や、タイムアウトエラーの多発につながった」と結論づけました。
対応内容
調査結果を受けて、2つの方針で対応を実施しました。
1. ワークアラウンドな対応
以下の2つを実施しました。
■ 1-1. 動的TCPポート数の増加
こちらを参考に、動的TCPポートの数を増加させました。これにより、TIME_WAITなポートが多発する状況下でも現状より多くのポートを使用できる状態にしました。
手順：
1. 「ファイル名を指定して実行」で「regedit」と入力し、レジストリエディタを立ち上げる
2. HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters 配下まで移動
3. 右クリック→「新規」→「DWORD(32ビット）値」を選択
4. 名前「TcpTimedWaitDelay」、値「30」を入力
5. 再起動
■ 1-2. TCPポートの解放時間を短縮
TcpTimedWaitDelayの値を最小の30秒に設定しました。これにより、TIME_WAITになったポートが再利用可能になるまでの時間を規定の4分から30秒へと短縮しました。
手順：
コマンドプロンプトで以下を実行（管理者として実行が必須）
１．現在の数をみる。あわせて、表示された数値をメモ（万一何かあったとき元に戻すため）
netsh interface ipv4 show dynamicportrange protocol=tcp
２．設定を変更する
ipv4 の場合:
netsh int ipv4 set dynamicport tcp start=動的ポートの開始番号 num=動的ポート数
３．変更が反映されたことを確認
netsh interface ipv4 show dynamicportrange protocol=tcp
この対応の結果、以下のようにTIME_WAIT（緑色）のポート数の減少が確認できました。
（左：設定前の24時間 / 右：設定後の24時間）
2. 根本的な対応
タイムアウトが多発していたプログラムについては暗黙の接続が発生しないようコードを修正しました。修正前後の該当関数の平均処理速度を計測したところ、約半分にまで実行時間を減少させることができました。
コードの修正については、以下のようなパターンで修正を実施しましたのでご紹介します。暗黙の接続が発生しないように、1つのコネクションオブジェクトにつき、一度に実行されているクエリが必ず一つだけになるように意識しました。
A. コネクションオブジェクトを使いまわしている場合
■ before
Dim ConnectionObject
Dim RecordSet
Set ConnectionObject= CreateObject("ADODB.Connection")
ConnectionObject.open "接続文字列"
Set RecordSet= ConnectionObject.Execute("select * from SomeTable") '//初回実行
Set RecordSet= ConnectionObject.Execute("select * from SomeTable") '//二回目の実行（暗黙の接続発生）
■ after
Dim ConnectionObject
Dim RecordSet
Set ConnectionObject= CreateObject("ADODB.Connection")
ConnectionObject.open "接続文字列"
Set RecordSet= ConnectionObject.Execute("select * from SomeTable") '//初回実行
RecordSet.Close()
set RecordSet= Nothing '//一度レコードセットを破棄すれば、同一コネクションを再利用できる
Set RecordSet= ConnectionObject.Execute("select * from SomeTable") '//二回目の実行（暗黙の接続発生無し）
B. oRS.open(**, ConnectionObject, **)を利用している場合
■ before
set oRS = Server.CreateObject("ADODB.Recordset")
oRS.Open sSQL, ConnectionObject, 1, 1
■ after
set oRS = Server.CreateObject("ADODB.Recordset")
oRS.Open sSQL, "接続文字列", 1, 1 '//コネクションオブジェクトではなく、接続文字列を渡すことで確実にコネクションの使いまわしが発生しないため、暗黙の接続を回避
C. CommandObject.Execute()を利用している場合
■ before
Set CommandObject = CreateObject("ADODB.Command")
CommandObject.ActiveConnection = ConnectionObject
CommandObject.CommandText = "Stored Procedure Name"
CommandObject.CommandType = 4
CommandObject.Execute
■ after
Set CommandObject = CreateObject("ADODB.Command")
CommandObject.ActiveConnection = "接続文字列"
CommandObject.CommandText = "Stored Procedure Name" '//コネクションオブジェクトではなく、接続文字列を渡すことで確実にコネクションの使いまわしが発生しないため、暗黙の接続を回避
CommandObject.CommandType = 4
CommandObject.Execute
まとめ
SQL Serverに接続しているシステムにおけるトラブルシューティングの事例をご紹介しました。