SharePoint と SQL ブロッキングの話 Part3

<関連記事> SharePoint と SQL ブロッキングの話 Part1 SharePoint と SQL ブロッキングの話 Part2 SharePoint と SQL ブロッキングの話 Part3

皆さんこんにちは

SharePoint サポートチームの荒川です。

前回、前々回に引き続き、SharePoint と SQL ブロッキングの話をします。これで一応最後です。

■イベントログから発生の有無を診断できるのか

前回説明したとおり、実際にブロッキングが起きたかどうかを後から正確に判断する術はありません。しかし、私は多くの経験のなかから、ブロッキング問題が発生した際によく見かける特徴的なイベントを見つけていますので、これがヒントになるかもしれません。

ブロッキング問題が起きた際には、多くの場合 Web サーバーのイベント ログに以下のイベント ID 2262 が記録されます。

アプリケーションイベントログ イベントの種類: 警告 ソース: W3SVC-WP 分類: なし イベント ID: 2262 日付: <日付> 時刻: <時刻> ユーザ: N/A コンピュータ: <コンピュータ名> 説明: 次の理由のため、ISAPI 'C:\WINDOWS\Microsoft.NET\Framework\v1.1.4322\aspnet_isapi.dll' は自身が危険な状況であると報告しました : 'デッドロックが検出されました。'。

注意したいのは、このイベントが記録されたからと言って、必ずしもブロッキング問題が発生していることを示すものでは無いということです。また、逆に、このイベントが出ていないからブロッキングが起きていないと判断することも適切ではありません。

上記イベントログは、ASP.NET のデッドロック検知機能が動作した事を示します。このイベント ログが記録された後、該当の w3wp.exe は IIS によって自動的に再起動されます。このイベントログは、後述の条件を満たした事によって ASP.NET がデッドロックが発生している疑いを検知した事を示し、実際に何らかのデータや内部変数等がデッドロックしている事を ASP.NET が認識した事を示すものではありません。

ASP.NET が自身の状態をデッドロックではないかと検知する条件は以下の二つです。

・リクエストの処理 (ユーザーコード) に responseDeadlockInterval (既定値 3 分) 以上、かかっているリクエストが存在する

・同時実行処理数が上限 (既定値 12 x CPU 数) に達している

以上の条件が双方とも満たされると、ASP.NET はデッドロックが発生していると判断します。発生シナリオの一例として以下が考えられます。

1) アプリケーションのリクエスト処理が何らかの要因によってハングする。

2) 後続のリクエスト処理が 1) に依存 (処理終了待ちなど) していて、それらもハングする。

3) 3 分が経過、かつ、後続のハングしたリクエスト数が 12 x CPU 数 を超えた時点で ASP.NET はデッドロックを検知した旨イベントログに発報してプロセスを不健全とマークする。

4) W3SVC は ある w3wp.exe が不健全とマークされた事を確認してプロセスに対して終了依頼する。

5) 終了依頼 (ExitProcess) に応じない場合、[ワーカープロセスをシャットダウンする時間] の設定値だけ待機した後、TerminateProcess を発行して強制終了する。その際、TerminateProcess した事をイベントログに発報する。

つまり、バックエンド SQL Server でブロッキングが発生し、さらに多数のユーザーがリクエストを試みている状況においては、上記イベントに遭遇する確率が高くなるわけです。

何度も言いますが、上記イベントはあくまで指標であって、実際にこのイベントとブロッキング問題を直結することは適切ではありません。しかし、過去事例の実績ベースでみると、多くの場合 SQL ブロッキングの結果として上記イベントが記録されるパターンが多いことも事実です。

■ロックエスカレーションの有無を確認する方法

ブロッキングと同様に、ロックエスカレーションが実際に発生したかどうかを後から確認する方法はありません。ただし、事前に SQL プロファイラ―を仕掛けておくことで、ロックエスカレーションの発生の瞬間をとらえることは可能です。

大抵の場合、一度ブロッキングが発生した環境は、以降も引き続き発生する可能性が高いと言えます。原因を特定せず、いきなりトレースフラグの設定を行うことが好ましくない状況では、先述のブロッキングの確認方法と併せて以下の方法でロックエスカレーションが発生したことを裏付けてから対応を検討するとよいでしょう。

SQL プロファイラーの詳細な解説についてはここでは触れませんが、簡単な確認方法を参考まで、紹介しておきます。(SQL プロファイラーの詳細について知りたい方は SQL Server の Books オンラインやヘルプ ドキュメントをご参照ください。)

ロックエスカレーションのイベントを記録するには、「Locks - Lock:Escaration」イベントを記録するようにトレースを設定します。

※他のイベントも併せて記録しても構いませんが、SQL プロファイラーによるトレースログの採取は SQL Server に大きな負担をかけますので、運用環境下での実施は避けたほうが良いでしょう。「Locks - Lock:Escaration」イベント程度であれば、それほど大量にログが出力されることは無いでしょうから、パフォーマンスへの極端な影響は無いものと思われます。

これで実際にロックエスカレーションが発生した際には、以下のようにロック エスカレーション イベントが記録されます。

上記で確認したデータベース名と、オブジェクト ID から以下のようにエスカレーションが発生したテーブルを特定することができます。

SELECT object_name(53575229)

サーバートレースを長期間仕掛けておく場合には、以下の手順を実行します。これによりファイルにログを出力することができます。

-----------------------------

サーバ トレース採取手順概要：

サーバー トレースの使用は、大きく分けて以下の 3 つの作業に分けられます。

i) スクリプト生成

ii) トレース実行

iii) トレース停止

それぞれの作業について説明いたします。

i) スクリプト生成

~~~~~~~~~~~~

以下の手順で、スクリプトを生成します。

1) スタート メニューから [Microsoft SQL Server 2005] - [パフォーマンスツール] - [SQL Server Profiler] を起動し、[ファイル] - [新しいトレース] を選択します。

2) 対象のデータベース インスタンスに接続します。

3) 「トレースのプロパティ」 画面の [全般] タブにおいて、[ファイルに保存する] をチェックし、保存するトレースファイルを UNC パスで指定します。(*1)

4) [最大ファイル サイズを設定 (MB) ] を、100 MB に変更します。 (*2)

5) [ファイルロールオーバーを有効にする] をチェックします。

6) [サーバが SQL Server トレースデータを処理する] をチェックします。

7) [イベントの選択] タブで、[すべてのイベントを表示する] オプションと[すべての列を表示する] オプションをチェックします。

8) 以下のイベントのすべての列を追加します。また、それ以外の既定のチェックを外します。

   Locks - Lock:Escaration

9) 一旦プロファイラを実行し、すぐに停止します。(停止 (四角) ボタンをクリックします。)

10) [ファイル] - [エクスポート] - [トレース定義のスクリプト] - [SQL Server 2005] で、任意のファイル名でトレース スクリプトを保存します。

*1) 指定するイベントとサーバで実行される処理量、監視期間によって大量のデータがファイルに出力される可能性があるため、十分余裕のあるディスクに対して保存を行うようにします。また、SQL プロファイラのトレースを出力するファイルは、可能であれば、SQL Server のデータベースが配置されているディスクとは別の物理ディスク (別の物理ディスクがない場合には別の論理ドライブ) への配置を検討してください。

*2) ファイルサイズについては、任意のサイズを指定します。サイズが小さすぎるとファイル数が増え、トレース追跡が困難になる場合があります。また、サイズが大きすぎると、ファイルを開くことが困難になる場合があります。

ii) トレース実行

~~~~~~~~~~~~

［スクリプト生成］で作成したスクリプトを、Management Studio で開きます。

スクリプトの先頭には下記のような記述があります。

例)

**********<抜粋 ここから>**********

-- Create a Queue

declare @rc int

declare @TraceID int

declare @maxfilesize bigint

set @maxfilesize = 100

exec @rc = sp_trace_create @TraceID output, 0, N'<InsertFileNameHere>', @maxfilesize, NULL if (@rc != 0) goto error

**********<抜粋 ここまで>**********

@maxfilesize にファイルサイズを指定します。上記の例では 100 MB に指定しております。

上記 '<InsertFileNameHere>' の箇所に、トレース結果を保存する任意のファイル パスを指定します。この際、既存のトレースファイル名を指定するとエラーになるので、別の任意の名前を指定してください。

また、下記 sp_trace_create の第二引数が 2 になっていることを確認し、2 になっていない場合には 2 に変更します。

例) 保存先を c:\\testtrace にする場合

exec @rc = sp_trace_create @TraceID output, 2, N'c:\\testtrace', @maxfilesize, NULL if (@rc != 0) goto error

変更後、書き換えたスクリプトを実行します。

このスクリプトを実行した時点からトレースが実行され、指定したイベントがキャプチャされます。

なお、実行の際に TraceID が返されるので記録します。スクリプトの停止を行う際に必要となります。

iii) トレース停止

~~~~~~~~~~~~

必要な情報を採取し終わった後、以下のクエリを実行して、トレースを停止、サーバーから削除します。

なお、下記のコマンド内の {TraceID} はスクリプトの実行時に返される値です。c で記録した値を、{TraceID}{TraceID}と置き換えてください。

EXEC sp_trace_setstatus {TraceID},0

go

EXEC sp_trace_setstatus {TraceID},2

go

トレースを停止し、サーバーから削除することで、まだファイルに書き込まれていないすべてのイベントが、最新のトレースファイルに書き込まれます。

TraceID が不明な場合、次のコマンドで実行中のトレースの一覧を出力させることができます。

SELECT * FROM ::fn_trace_getinfo(default)

表示されたトレース情報のファイル名等から、目的のTraceIDを特定します。

※1 サーバー トレースは結果を直接ファイルに書き出しますが、ファイルバッファを持っているため書き込みデータが一定のサイズになるまでトレースファイルに書き出しが行われません。

※2 サーバー トレースのスクリプトを介した際に Error 12 を受け取った場合は、出力先のトレース ファイルが既に存在している可能性があります。

-----------------------------

全3回のシリーズでSharePoint と SQL ブロッキングの話についてお届けしてまいりましたが、先に述べたとおり、最近になってこの現象に関するサポートへのお問い合わせが増えてきているように感じます。恐らく SharePoint を長期運用されているユーザーが増えてきたことで、システムに格納されるデータ量が増えてきたことが一つの要因ではないかと思います。SharePoint では、キャパシティプランニングやパフォーマンス検証の資料において、リストに大量のアイテムを格納しないといったガイドラインがありますが、これらのガイドを守らなくとも、通常の動作には支障が無いケースもあります。ただし、一度に大量のデータを削除したり、更新したるするようなオペレーションが合わさることで突発的に問題が発生するケースもありますので、この記事の例のように、状況に応じた対策を行う必要が生じることもあるでしょう。運用において、最近データ量が増えてきたな、と感じられることがあれば、問題を未然に防止するための予防措置として、トレースフラグ 1224 の設定を検討してみてはいかがでしょうか。