Outlook がハング状態に陥る複合的な問題この事例は、私の友人で Microsoft Exchange Server エスカレーション エンジニアの Andrew Richards が紹介してくれたものです。この事例では、私が特に Microsoft サポート サービス向けに作成した Sysinternals ツールの使用に焦点が当たっており、また、2 つの事例が組み合わさっているので、これは非常に興味深い事例となっています。 この事例は、ある企業のシステム管理者が、その企業のネットワーク上の複数のユーザーから苦情が出ていることを Microsoft サポートに報告したことから始まります。その苦情とは、Outlook のハング状態が最大 15 分間続くというものでした。複数のユーザーに問題が発生していることから、Exchange の問題であると思われたため、電話は Exchange Server サポート サービスに回されました。 Exchange チームは、パフォーマンス モニターのデータ コレクター セットを開発しました。このデータ コレクター セットには、Exchange に関する問題のトラブルシューティングに役立つことが実証されている数百のカウンター (LDAP メッセージ、RPC メッセージ、SMTP メッセージのアクティビティ、Exchange の接続数、メモリ使用量、プロセッサ使用率など) が含まれています。Exchange サポートは、管理者に、12 時間のログ サイクル (最初は午後 9 時から次の日の 午前 9 時まで) で、サーバーの活動のログを収集してもらいました。Exchange サポート エンジニアがログを確認したところ、グラフ上にはたくさんの線が記録されていましたが、2 つのパターンが明白でした。まず、予想どおり、Exchange サーバーの負荷は、ユーザーが仕事を始めて Outlook を使い始める朝の時間帯に増加していました。第 2 に、カウンターのグラフでは、午前 8:05 ～ 8:20 ごろに他の時間とは異なる動作が見られました。この時間の長さはまさに、ユーザーが報告した長い遅延の長さと一致しています。
サポート エンジニアは、その時間帯の部分を拡大し、その時間帯のカウンターについて考えたところ、Exchange の CPU 使用率が低下していること、アクティブな接続の数が減っていること、および発信応答の待ち時間が劇的に長くなっていることがわかりましたが、原因は特定できませんでした (下図参照)。
サポート エンジニアは、さらに上のレベルのサポートが必要だと判断し、この事例を Andrew に任せました。Andrew はログを調査し、停止中の Exchange の動作についてさらに情報が必要だと結論付けました。具体的には、Exchange が無応答状態にあるときの Exchange のプロセス メモリ ダンプが必要でした。これには、プロセス アドレス領域の内容 (データとコードなど)、およびプロセスのスレッドのレジスタ状態が含まれます。Andrew は、Exchange プロセスのダンプ ファイルで Exchange のスレッドを参照すれば、スレッドが停止する原因を確認できると考えました。 ダンプを取得する方法の 1 つは、Debugging Tools for Windows パッケージ (Windows ソフトウェア開発キットに含まれています) の一部として提供される Windbg などのデバッガーでプロセスに "アタッチ" し、.dump コマンドを実行するというものです。ですが、ツールをダウンロードしてインストールし、デバッガーを起動し、適切なプロセスにアタッチし、ダンプを保存するという一連の手順は手間がかかります。Andrew は、代わりに、管理者に Sysinternals の Procdump (英語) ユーティリティ (サーバーにソフトウェアをインストールせずに実行できる単一のユーティリティ) をダウンロードしてもらいました。Procdump を使用すると、プロセスのダンプを簡単に取得できます。また、Procdump には、指定した間隔で複数のダンプを作成するオプションが用意されています。Andrew は管理者に、次にサーバーの CPU 使用率が低下したときに Procdump を実行して、Exchange Server エンジンのプロセスである Store.exe のダンプを 3 秒間隔で 5 つ生成するよう頼みました。これを行うコマンドは次のとおりです。 翌日、問題は再び発生したので、管理者は Procdump で生成したダンプ ファイルを Andrew に送りました。多くの場合、プロセスが一時的にハング状態に陥る原因は、プロセス内の 1 つのスレッドが、他のスレッドがアクセスする必要があるデータを保護するロックを取得して、長時間にわたる操作を実行しているあいだじゅうロックをかけ続けることです。そのため、Andrew はまず、かかっているロックがあるかどうかを確認しました。最もよく使用されるプロセス間の同期ロックはクリティカル セクション (英語) で、!locks というデバッガー コマンドを使用すると、ダンプ内のロックされているクリティカル セクション、ロックを所有しているスレッドのスレッド ID、およびこのロックを取得するために待機しているスレッドの数が表示されます。Andrew は、これに似たコマンド (Sieext.dll デバッガ拡張機能の !critlist) を使用しました。Sieext.dll の一般向けバージョンである Sieextpub.dll は、こちら (英語)からダウンロードできます。このコマンドの出力から、スレッド 223 がクリティカル セクションを解放するのを待機しているスレッドが複数存在することがわかりました (下図参照)。
Andrew は次に、ロックを所有しているスレッドの動作を確認しました。これにより、長時間の遅延の原因となっているコードを特定できるのではないかと考えたためです。Andrew は ~ コマンドを使用して、ロックを所有しているスレッドのレジスタ コンテキストに切り替え、k コマンドを使用してスレッドのスタックをダンプしました (下図参照)。
以前にご紹介した "Case of the Unexplained" (原因不明の...の問題) の事例でも同じようなことがありましたが、デバッガーでは、イメージ Savfmsevsapi のシンボルを取得できなかったため、Savfmsevsapi を参照するスタック フレームに到達したところで、スタックをどのように解釈すればよいかわからなくなっています。ほとんどの Windows イメージのシンボルはマイクロソフトのシンボル サーバーに登録されているので、これは Store.exe プロセスに読み込まれたサードパーティ製 DLL である可能性が高いため、ハングの原因ではないかと思われました。モジュール一覧表示 ("lm") コマンドを使用すると、読み込まれたイメージのバージョン情報がダンプされます。以下に示すように、イメージのパスから、Savfmsevsapi は Symantec のメール セキュリティ製品の一部であることがわかりました。
Andrew は他のダンプも確認しましたが、どのダンプにも同じようなスタック トレースがありました。事例証拠から、Symantec の問題であるように思われたため、Andrew は管理者の許可を得て、ダンプと自身の分析を Symantec のテクニカル サポートに送りました。数時間後、Symantec から、メール アプリケーションの最新のウイルス対策シグネチャの配布に問題があることがダンプから判明したとの報告があり、バグを修正する更新プログラムが管理者に届きました。管理者はこの更新プログラムを適用し、問題が修正されたことを確認するためにサーバーの監視を続けました。思ったとおり、サーバーのパフォーマンスの動作レベルはかなり規則的になり、長時間の遅延は発生しなくなりました。 ところが後日、管理者は、以前ほど頻度は高くないものの、数人のユーザーから、Outlook が最大で 1 分間ハング状態になることがときどきあるという苦情を受けるようになりました。Andrew は管理者に、収集した一連の Exchange データが記録された関連する 12 時間分のパフォーマンス モニターのキャプチャを送ってもらいましたが、今回は、明らかな異常はありませんでした (下図参照)。
Andrew は、ハングは Store.exe の CPU 使用率の履歴に表れているのではないかと考えて、Store のプロセッサ使用率カウンターを除くすべてのカウンターを削除しました。ユーザーがログインし始めてサーバーの負荷が増加する朝の時間帯の部分を拡大すると、次のように、午前 8:30 ごろに 3 つのスパイクがあることに気付きました。
サーバーは 8 つのコアを搭載しているので、個々のプロセスのプロセッサ使用率カウンターの範囲は 0 ～ 800 です。そのため、この 3 つのスパイクによるシステムへの負荷は決して重くはありませんが、このシステムにおける Exchange の通常の負荷の範囲は明らかに超えています。次のようにさらに拡大して、スパイクがよりはっきりするようにグラフの縦軸を設定したところ、平均的な CPU 使用率は常に単一のコアの約 75% を下回っており、また、スパイクの長さは 15 ～ 30 秒であることがわかりました。
Exchange はスパイク中にどんな動作をしていたのでしょうか。今回のスパイクは短く不規則なので、管理者は、前のように、Procdump を実行して、スパイクの発生時に確実にダンプをキャプチャすることができませんでした。さいわい、私はまさにこのシナリオを念頭に置いて Procdump を設計しました。Procdump は、ダンプ生成のトリガー条件をいくつかサポートしており、こうした条件が満たされるとダンプが生成されます。たとえば、プロセスが終了したとき、またはプロセスのプライベート メモリ使用量が特定の値を超えたときにプロセスのダンプを生成するように Procdump を構成することができます。また、指定したパフォーマンス カウンターの値に基づいてプロセスのダンプを生成するように Procdump を構成することもできます。ただし、最も基本的なトリガーは、プロセスの CPU 使用率が、指定した期間にわたって、指定したしきい値を超えることです。 パフォーマンス モニターのログによって、Andrew は、今後発生する CPU スパイクのダンプをキャプチャする Procdump コマンド ラインを作成するのに必要な情報を得ることができました。次にそのコマンド ラインを示します。 上記のコマンドで指定されている引数では、Store の CPU 使用率が 10 秒 (-s 10) にわたって単一のコア (-u) の 75% (-c 75) を超えたときに Store.exe プロセスのダンプを生成するように Procdump を構成しています。最大 20 個 (-n 20) のダンプを生成したら終了するようにも構成しています。また、"store_75pc_10sec" で始まる名前で C:\Dumps ディレクトリにダンプを保存するようにも構成しています。管理者は退社前にコマンドを実行し、翌日の朝に進捗を確認したところ、既に 20 個のダンプ ファイルが作成されていました。管理者はこれらのファイルを Andrew に電子メールで送り、1 つずつ Windbg デバッガーで調査してもらいました。 CPU 使用率のトリガー条件が満たされ Procdump によってダンプが生成される際、ダンプ ファイルのスレッド コンテキストは、ダンプ時に最も多くの CPU を消費していたスレッドに設定されます。デバッガーのスタック ダンプ コマンドは現在のスレッド コンテキストに対応するので、スタック ダンプ コマンドを入力するだけで、CPU スパイクの原因である可能性が最も高いスレッドのスタックが表示されます。ダンプの半分以上は決め手に欠け、おそらくダンプをトリガーしたスパイクが既に終了した後にキャプチャされたか、明らかにスパイクとは直接関係がないコードを実行していたスレッドに関するものでした。ですが、次のようなスタック トレースが含まれるダンプがいくつかありました。
拡大表示されているスタック フレームでは Store の EcFindRow 関数が表示されています。これは、スパイクの原因が、時間のかかるデータベース クエリだったことを示しています。このようなクエリは、Outlook が何千もの項目が格納されたメールボックス フォルダーにアクセスするときに実行されます。これを手掛かりに、Andrew は、大きなメールボックスの一覧を作成することを管理者に勧め、また、Exchange の各バージョンでそれを行う方法について Exchange サポート チームが記した記事 (英語) を紹介しました (下図参照)。
思ったとおり、このスクリプトを使用すると、何万個ものアイテムが格納されたフォルダーを持つ何人かのユーザーが特定されました。管理者はこうしたユーザーに、アイテムをアーカイブしたり、削除したり、サブフォルダーにまとめたりして、5000 個 (Exchange 2003 の推奨値です。この値はバージョンを追うごとに大きくなっており、Exchange 2010 では 100,000 個にまで増えました) をはるかに下回るくらいの数まで減らすよう頼みました。こうしたユーザーは 2 ～ 3 日のうちに問題のあるフォルダーを整理し直し、ユーザーからはまったく苦情が寄せられなくなりました。次の週も継続して行った Exchange サーバーの監視によって、問題が解決したことが確認されました。 Procdump を活用することで、Outlook がハング状態に陥る複合的な問題は無事に解決されました。 ページのトップへ |
共有ブログにコピー: ([Ctrl] + [C] でコピーしてください) |
.png "図 1")
.png "図 2")
.png "図 3")
.png "図 4")
.png "図 5")
.jpg "図 6")
.png "図 7")
.png "図 8")
.png "図 9")
.png "図 10")