ZOZOTOWNのバックオフィスシステムのレスポンスが突発的に低下する問題を解決した話

SQL Server IIS

f:id:vasilyjp:20190530161303p:plain

こんにちは。開発部の廣瀬です。

本記事では、ZOZOTOWNを裏側から支えているバックオフィスシステムにおけるトラブルシューティング事例をご紹介したいと思います。 尚、今回の話題はバックオフィスシステムで使用しているVBScript言語がメインとなります。WebサーバーはIIS、DBMSはSQL Serverを使っている環境です。

ZOZOTOWNのバックオフィスシステムについて

ZOZOTOWNのバックオフィスシステム（以後、BOと呼ぶ）では、顧客管理や物流管理などを行っています。 BOの開発はすべて弊社の社員で行っています。ZOZOTOWNを裏側から支えるシステムを開発する責任は大きいですが、その分やりがいを感じることも多いです。例えば、顔見知りの社員がユーザーのため、直接システムへのフィードバックがもらえます。システム改善によって別の部署の業務効率を向上させることができたり、抱えている問題を解決できたときはとても喜んでくれて、それが次の開発へのモチベーションにつながります。

社内の様々な部署でBOが使われていますが、物流拠点「ZOZOBASE」は最もBOユーザーが多い拠点の1つです。 ZOZOBASEではメンバーの大半がBOを使って業務を行っています。そのため、BOのレスポンスタイムは作業効率に大きな影響を及ぼします。 ある時期から、BOのレスポンスタイムが突発的に著しく低下する事象が断続的に発生するようになりました。その問題の調査と解決方法について、順を追ってご紹介します。

BOで発生した問題について

ある日、物流部門から「BOが重い」との問い合わせを受けました。 アプリケーションのタイムアウト発生状況を確認すると、確かにタイムアウトエラーが頻発していました。 ただし、通常時と比較して平均のレスポンスタイムがどの程度増加しているのかについては確認する仕組みがありませんでした。その日は1時間ほど経過後、自然解消しましたが、その後1日1回程度の頻度で同様の事象が発生するようになりました。

BOのレスポンスタイムが低下すると、処理効率が低下し、結果的に人件費というコストの増加につながります。 できる限り迅速に問題を解決すべく、調査を実施しました。

原因調査

DBでスロークエリが多発している可能性を疑い、DBで現在実行中のクエリリストを取得してみました。 その結果、DBでスロークエリが多発しているわけではありませんでした。このためDB起因でのレスポンス低下ではないと判断しました。

次に、Webサーバー側で処理中の要求一覧を確認しました。

・[インターネットインフォメーションサービス（IIS）マネージャー]を起動し、[ワーカープロセス]へ f:id:vasilyjp:20190530161203p:plain

・該当のアプリケーションプール名をダブルクリック f:id:vasilyjp:20190530161207p:plain

・現在の要求一覧を確認 f:id:vasilyjp:20190530161212p:plain

上記の例では要求が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]を選択します。 f:id:vasilyjp:20190530161214p:plain

次に[実行]を押してProfilerを開始し、接続状況を確認したい関数を実行後、Profilerを停止します。 f:id:vasilyjp:20190530161219p:plain ↑Profilerで取得したイベントです。[EventSubClass]という項目を確認します。 [2-Pooled]（コネクションプールから再利用された）の次に、[1-Nonpooled]（新規接続が発生）という順番でAudit Loginイベントが発生していました。 推測していた通り、該当関数では新規接続が発生していることが確認できました。

今までの調査から、コネクションプールにプールされたコネクションをうまく再利用できておらず、新規接続が大量に発生している可能性があると推測しました。コネクションまわりのトラブルのため、Webサーバーのポートの状態を確認してみました。 PowerShellで以下のコマンドを実行します。

Get-NetTCPConnection | GROUP-Object State

その結果、利用可能な動的ポート数の大半がstate=TIME_WAITとなっていました。監視製品のグラフで確認しても、物流拠点の稼働中は大量のTIME_WAITなポートが確認できました。 f:id:vasilyjp:20190530161221p:plain （緑色：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つはワークアラウンドな対応で、もう1つは根本的な対応です。それぞれご紹介します。

1. ワークアラウンドな対応

ワークアラウンドな対応として、動的TCPポート数の増加とTCPポートの解放時間の短縮という2つの対応を実施しました。

1-1. 動的TCPポート数の増加

こちらを参考に、動的TCPポートの数を増加させました。これにより、TIME_WAITなポートが多発する状況下でも現状より多くのポートを使用できる状態にしました。

手順：コマンドプロンプトで以下を実行（管理者として実行が必須）

・現在の数を確認し、表示された数値をメモ（万一何かあったときに戻すため）

netsh interface ipv4 show dynamicportrange protocol=tcp

・設定を変更する（ipv4の場合）

netsh int ipv4 set dynamicport tcp start=動的ポートの開始番号 num=動的ポート数

・変更が反映されたことを確認

netsh interface ipv4 show dynamicportrange protocol=tcp

1-2. TCPポートの解放時間を短縮

TcpTimedWaitDelayの値を最小の30秒に設定しました。これにより、TIME_WAITになったポートが再利用可能になるまでの時間を規定の4分から30秒へと短縮しました。

手順
  1. 「ファイル名を指定して実行」で「regedit」と入力し、レジストリエディタを立ち上げる
  2. HKEY_LOCAL_MACHINE\SYSTEM\CurrentControlSet\Services\Tcpip\Parameters 配下まで移動
  3. 右クリック→「新規」→「DWORD(32ビット）値」を選択
  4. 名前「TcpTimedWaitDelay」、値「30」を入力
  5. 再起動

この対応の結果、以下のようにTIME_WAITのポート数の減少が確認できました。 f:id:vasilyjp:20190530161200p:plain （左：設定前の24時間 / 右：設定後の24時間）

2. 根本的な対応

タイムアウトが多発していたプログラムについては暗黙の接続が発生しないようコードを修正しました。修正前後の該当関数の処理速度の平均値を計測したところ、約半分にまで実行時間を短縮させることができました。

コードの修正については、以下のようなパターンで修正を実施しましたのでご紹介します。暗黙の接続が発生しないように、1つのコネクションオブジェクトにつき、一度に実行されているクエリが必ず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(xxx, ConnectionObject, xxx)を利用している場合

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

今後の課題

弊社ではプロダクトによっては外形監視のための製品が導入されていますが、BOでは未導入で、レスポンスタイムについてメンバーが監視や改善をしやすい環境ではありません。今回の問題も物流拠点からの問い合わせで問題に気づくのではなく、レスポンスタイムが増加しているアラートを受け取って気づくのが理想的だったと思います。そのため、BOにも外形監視の仕組みを導入し、みんなでレスポンスタイムについても責任を持てる状況を整備していきたいと考えています。

まとめ

今回はVBScriptというレガシーな技術を使って動いているシステムにおけるトラブルシューティングの事例をご紹介しました。 約15年前に誕生し、凄まじい勢いで成長してきたZOZOTOWNは、VBScriptなど当時のレガシーな技術を用いた開発も行っています。 一方で、アーキテクチャにDocker/Kubernetesを中心としたクラスタ構成を採用したZOZOTOWNのシステムリプレースプロジェクトも進めています。 このように弊社では最新の技術からレガシーな技術まで、さまざまな技術を使ってエンジニアが日々開発に取り組んでいますが、プロダクトをより良いものにしたいという想いはみんな一緒です。

ZOZOテクノロジーズでは、目の前の課題を解決していくことにモチベーションを持って取り組めるエンジニアを絶賛募集中です。 興味のある方はぜひこちらからご応募ください。

カテゴリー