共用方式為

SharePoint ブロッキング問題の調査手法 (後編)

  • 發行項
<連載>SharePoint ブロッキング問題の調査手法 (前編)SharePoint ブロッキング問題の調査手法 (後編)

 

こんにちは。SharePoint サポートチームの荒川です。
前回に引き続き、ブロッキングの要因となった操作を特定する方法について解説します。

前編では、利用状況モニターを使用してリアルタイムにブロッキングを確認する方法について解説しましたが、利用状況モニターを見ただけではブロッキングの発生有無は確認できてもその原因となった操作までは特定できませんでした。ブロッキングの原因となった操作を特定するためには、SQL Server 側の情報と合わせて、SharePoint 側の情報も確認する必要があります。

 

SQL Server 側での情報採取

SharePoint 側の処理を特定する前に、SQL Server 側で先頭ブロックの SQL クエリの内容と、セッション情報を取得する必要があります。前編でも述べたとおり、ブロッキングは通常 SharePoint 側からは単なる処理の遅延として扱われるため、SharePoint 側のログには一目でそれとわかるようなエラー情報は出力されません。タイムアウトエラーが記録されたときには既に遅く、ブロッキングの原因となっているアクセスに関するログはそれよりずっと前に記録されていることが殆どであり、診断ログの情報量はとても多いため、問題の発生個所の特定は容易ではありません。このため、SQL Server 側からのアプローチが必要になります。

利用状況モニターの情報は、リアルタイムでの調査には向いていますが、データを採取しておき後から調べるのには向いていませんので、利用状況モニターと同様の情報に加えて後の調査に必要となる様々な情報を一括で採取できるスクリプトを使用します。以下のスクリプトの内容をコピーして [新しいクエリ] に貼り付けて実行してみましょう。このスクリプトでは、ブロッキングに関するセッション情報、ブロッキングに関連しているプロセスで実行されているクエリ、ロックされているオブジェクトを特定するためのオブジェクト情報の一覧がまとめて採取できます。
すぐに調査しない場合であっても、[クエリ] メニューの [結果の出力] で「結果をファイルに出力」を選択して結果を保存しておけば、後から調査する際の参考データとしても使用できます。

/*出力1 - セッション一覧*/SELECT[Session ID] = s.session_id,[Last Request Start Time] = s.last_request_start_time,[Host Name] = ISNULL(s.host_name, N''),[Host Process ID] = ISNULL(s.host_process_id, N''),[User Process] = CONVERT(CHAR(1), s.is_user_process),[Blocked By] = ISNULL(CONVERT (varchar, w.blocking_session_id), N''),[Head Blocker] =CASEWHEN r2.session_id IS NOT NULL AND (r.blocking_session_id = 0 OR r.session_id IS NULL) THEN '1'ELSE N''END,[Login] = s.login_name,[Database] = case when p.dbid=0 then N'' else ISNULL(db_name(p.dbid),N'') end,[Task State] = ISNULL(t.task_state, N''),[Command] = ISNULL(r.command, N''),[Application] = ISNULL(s.program_name, N''),[Wait Time (ms)] = ISNULL(w.wait_duration_ms, 0),[Wait Type] = ISNULL(w.wait_type, N''),[Wait Resource] = ISNULL(w.resource_description, N''),[Login Time] = s.login_time,[Total CPU (ms)] = s.cpu_time,[Total Physical I/O (MB)] = (s.reads + s.writes) * 8 / 1024,[Memory Use (KB)] = s.memory_usage * 8192 / 1024,[Open Transactions] = ISNULL(r.open_transaction_count,0),[Net Address] = ISNULL(c.client_net_address, N''),[Execution Context ID] = ISNULL(t.exec_context_id, 0),[Request ID] = ISNULL(r.request_id, 0)FROM sys.dm_exec_sessions s LEFT OUTER JOIN sys.dm_exec_connections c ON (s.session_id = c.session_id)LEFT OUTER JOIN sys.dm_exec_requests r ON (s.session_id = r.session_id)LEFT OUTER JOIN sys.dm_os_tasks t ON (r.session_id = t.session_id AND r.request_id = t.request_id)LEFT OUTER JOIN(SELECT *, ROW_NUMBER() OVER (PARTITION BY waiting_task_address ORDER BY wait_duration_ms DESC) AS row_numFROM sys.dm_os_waiting_tasks) w ON (t.task_address = w.waiting_task_address) AND w.row_num = 1LEFT OUTER JOIN sys.dm_exec_requests r2 ON (s.session_id = r2.blocking_session_id)LEFT OUTER JOIN sys.sysprocesses p ON (s.session_id = p.spid)WHERE s.session_id > 50ORDER BY s.session_id;/*出力2 - ブロッキングに関連しているプロセスで実行されているクエリ*/DECLARE @SessionId intDECLARE @WaitTime intDECLARE @WaitType nvarchar(60)DECLARE @WaitResource nvarchar(1024)DECLARE cursor_blocking CURSOR FORSELECT[Session ID] = s.session_id,[Wait Time (ms)] = ISNULL(w.wait_duration_ms, 0),[Wait Type] = ISNULL(w.wait_type, N''),[Wait Resource] = ISNULL(w.resource_description, N'')FROM sys.dm_exec_sessions s LEFT OUTER JOIN sys.dm_exec_connections c ON (s.session_id = c.session_id)LEFT OUTER JOIN sys.dm_exec_requests r ON (s.session_id = r.session_id)LEFT OUTER JOIN sys.dm_exec_requests r2 ON (s.session_id = r2.blocking_session_id)LEFT OUTER JOIN sys.dm_os_tasks t ON (r.session_id = t.session_id AND r.request_id = t.request_id)LEFT OUTER JOIN(SELECT *, ROW_NUMBER() OVER (PARTITION BY waiting_task_address ORDER BY wait_duration_ms DESC) AS row_numFROM sys.dm_os_waiting_tasks) w ON (t.task_address = w.waiting_task_address) AND w.row_num = 1WHERE (r2.session_id IS NOT NULLAND (r.blocking_session_id = 0 OR r.session_id IS NULL))OR (r.blocking_session_id <> 0)ORDER BY s.session_id;OPEN cursor_blockingFETCH NEXT FROM cursor_blockingINTO @SessionId, @WaitTime, @WaitType, @WaitResourceWHILE @@FETCH_STATUS = 0BEGINSELECT@SessionId AS [Session ID]SELECT@WaitTime AS [Wait Time (ms)],@WaitType AS [Wait Type],@WaitResource AS [Wait Resource]　DBCC INPUTBUFFER(@SessionId)FETCH NEXT FROM cursor_blockingINTO @SessionId, @WaitTime, @WaitType, @WaitResourceENDCLOSE cursor_blocking;DEALLOCATE cursor_blocking;GO/*出力3 - データベース オブジェクト一覧*/SELECT * FROM sys.databases;DECLARE @dbname sysnameDECLARE @dbid intDECLARE @sql varchar(1024)DECLARE databases_objects CURSOR FORSELECT name, database_id FROM sys.databasesOPEN databases_objectsFETCH NEXT FROM databases_objectsINTO @dbname, @dbidWHILE @@FETCH_STATUS = 0BEGINSELECT @dbid AS [Database ID], @dbname AS [Database]SET @sql = 'SELECT * FROM [' + @dbname + '].sys.objects inner join [' + @dbname + '].sys.partitions on [' + @dbname + '].sys.objects.object_id = [' + @dbname + '].sys.partitions.object_id'EXEC (@sql)FETCH NEXT FROM databases_objectsINTO @dbname, @dbidENDCLOSE databases_objects;DEALLOCATE databases_objects;GO

 

 

先頭ブロックのセッション情報およびクエリの特定

まず「出力1」の内容から、先頭ブロックの行 (Head Blocker が 1 になっている行) を探し出します。
以下の例では先頭ブロックのセッション ID は 418 となっており、WSS_Content データベースのテーブルに対する UPDATE の処理であることが分かります。また、後続の処理であるセッション ID 425 の処理がブロッキングの影響により待たされていることが分かります。
先頭ブロックのセッションを実行しているサーバーは SPS で、プロセス ID は 11868 であることも確認できます。

20160712c

次に、「出力2」の内容から、先頭ブロックのセッション ID で実行されていたクエリを特定します。

20160712d

 

待たされている処理の確認

待たされている処理が具体的にどのテーブルに対する処理で待たされているのか特定するために、「出力2」の内容から、待たされているセッション ID で実行されていたクエリを特定します。

20160712d2

「Wait Resource」の dbid および associatedObjectId の情報から、対象のデータベースとテーブルを特定します。
今回のケースでは、「AllListsAux」テーブルのロック開放待ちであることが確認できます。

20160712d3

 

診断ログから問題の処理を特定する

次に、SharePoint 診断ログから、ブロック チェーンの先頭ブロックのセッションで実行されているクエリが含まれるエントリーを検索します。ケースバイケースですが、ブロッキングの要因となった処理が SharePoint の標準機能によるものであった場合、診断ログに該当のクエリが出力される可能性が高くなります。
ここで診断ログからクエリを特定できない場合、診断ログを用いた調査は困難になりますので、この場合後述の詳細な診断ログまたはダンプ ファイルを用いた調査手法を検討する必要があります。
今回は運良く該当のクエリーを見つけ出すことに成功したため、該当の処理を関連付け ID でフィルターします。以下の ULS Viewer を使用すると診断ログの解析とフィルター処理が簡単に行えます。

ULS Viewer https://www.microsoft.com/en-us/download/details.aspx?id=44020

今回の例では、該当する時間帯に一致するクエリが1件のみヒットしたため、この処理がブロッキングの要因として、処理の内容を確認していきます。

20160712e

ホスト プロセス ID は先ほど確認した 11868 (16進数では 0x2E5C) であり、診断ログに記録された w3wp.exe のプロセス ID と一致します。また、処理の実行時間帯も一致しています。
関連付け ID でまとめられた一連の処理が開始されてから終了するまでには約 41 秒かかっており、特にブロッキングの要因となったクエリの実行には約 30 秒かかっていることが分かります。

一連の処理の先頭行をみると、ユーザーのリクエスト内容が確認できますが、この情報だけでは、クライアントから何かしらの POST メソッドが実行されたということしかわかりません。
そこで、運よく同時に出力されていた「Slow Query StackTrace」のスタックトレースの情報に着目します。通常 SQL コマンド実行時にスタックトレース情報は、既定の診断ログの出力レベルがでは出力されませんが、今回のようにブロッキングが生じている場合は「Slow Query Duration」の情報とともに出力される可能性が高くなります。

20160712f

このスタック トレース情報から、SPListItem.Update() メソッドから発生している処理の流れでブロッキングが生じていることが分かりますので、トリガーとなっているユーザー操作は、リストまたはライブラリのアイテム (またはフォルダー) の更新であることが推測できます。

20160712g

次に、具体的にどのリストにおいて更新が生じたか確認する必要があるため、IIS ログの解析を行います。
診断ログでは、アクセス時刻が 07/14/2016 07:08:25 となっていますが、IIS ログは UTC 時刻で記録されるため、サーバーが日本時間の場合は診断ログの時間から 9 時間マイナスした時間が IIS ログの時刻になります。
IIS ログには応答が返された時刻が記録されるため、検索対象となる時刻は診断ログで「Leaving Monitored Scope」が返された 07/14/2016 07:09:06.69 から 9 時間マイナスした時刻 07/13/2016 22:09:06 付近です。

20160712h

該当時間帯には上記のように同一ユーザーによるリストアイテムの編集ページの URL へのアクセスが確認できましたので、この操作が影響していた可能性が高いと判断できます。
実際に該当のリストアイテムを確認したところ、子に10万件のアイテムを含むフォルダー アイテムであることが確認できました。恐らく子に大量のアイテムを含むフォルダのリネームにより処理に時間がかかり、ブロッキングが生じたものと推測されます。

ここまでの調査で、ある程度の推測ができる状況になりました。ここから先、さらに確度の高い調査結果を求めるためには、詳細レベルの診断ログが必要になります。
SharePoint 診断ログの既定の設定では重要度の高いエラーや警告のみが診断ログに出力される設定になっており、クエリの詳細やスタックト レース情報など、パフォーマンスの分析に必要な周辺情報は出力されない設定になっています。このため、ブロッキング問題を詳細に調べるには、診断ログの出力レベルを予め詳細にしておく必要があります。

診断ログの出力レベルを詳細にするには、ファームの任意のサーバー上の SharePoint 管理シェルで以下のコマンドを実行します。

Set-SPLogLevel -EventSeverity Verbose -TraceSeverity VerboseEx

ログの出力増加により HDD の圧迫が懸念される場合は、以下のコマンドによりログの最大保存サイズを制限することも可能です。この場合最大保存サイズを超えた古いデータが適宜削除されます。

Set-SPDiagnosticConfig -LogMaxDiskSpaceUsageEnabled:$True
Set-SPDiagnosticConfig -LogDiskSpaceUsageGB 5

診断ログの設定を既定値に戻すには以下のコマンドを実行します。

Clear-SPLogLevel

補足：詳細な診断ログの出力にはディスクスペースが必要となり、場合によってはパフォーマンスに影響を及ぼす可能性があるため、検証環境や運用環境におけるトラブルシュートの目的以外では有効にしないことをお勧めします。

診断ログの出力レベルを予め詳細にしておくことで、実行に時間がかかったサブクエリの内容を特定することが可能になります。
以下は、既定レベルのログを採取した状況と同じ状況で診断ログの出力レベルを詳細にした場合に記録されるログの例です。

20160712i

このログでは、クエリの中で呼び出された各ストアドプロシージャごとの実行時間が出力されており、特に「proc_RenameDir」の実行中、「AllDocs」テーブルに対する処理の過程で顕著に時間を要していることが確認できます。
このような情報は既定のログ レベルでは出力されない情報であるため、トラブルが頻発する場合には予め診断ログの出力レベルを詳細にしておくことで、発生時の原因特定を容易にできる可能性が高くなります。

また、時間がかかる処理をこのように特定できた場合、ストアドプロシージャの引数の情報から、問題のサイトやリストアイテムを特定できるケースもあります。
例えば今回の場合、「proc_RenameDir」の処理で時間を要していることが明らかであるため、「proc_RenameDir」を起点とした調査が可能になります。

詳細レベルで取得された診断ログから「proc_RenameDir」を含み、且つ、イベントID「tzkv」に一致するログを検索してみると、ヒットしません。このことから、恐らく proc_RenameDir は親となる別のストアドプロシージャから呼び出されている可能性が高いと判断できます。この場合、関連付け ID でフィルタされた診断ログにおいて「proc_RenameDir」が最初に出現する箇所を探し出し、その直前に実行されているストアドプロシージャに着目します。

20160712j

今回のケースでは「proc_RenameUrl」が確認できました。名称から判断すると、フォルダ名の変更に伴い AllDocs テーブルに格納された各アイテムが持つ URL 情報を書き換える目的で使用されるストアドプロシージャのようです。次に、「proc_RenameUrl」を含み、且つ、イベントID「tzkv」に一致するログを検索してみると以下のログが検索でヒットしました。

20160712k

ここで、ログに出力されたストアドプロシージャの引数部分に着目します。診断ログの出力レベルを詳細にしていた場合、ストアドプロシージャの実行時に使用されたパラメーターの情報も出力されます。

SqlCommand: 'DECLARE @S uniqueidentifier; DECLARE @W uniqueidentifier; DECLARE @NewListId uniqueidentifier; DECLARE @iRet int; DECLARE @OldFU nvarchar(260); DECLARE @NewFU nvarchar(260); DECLARE @NewDoclibRowIdInput int; DECLARE @MaxNewRowsInput int; DECLARE @OldItemId int; DECLARE @bIsCopy bit; SET @OldFU=@wssp0;SET @NewFU=@wssp1;SET @S=@wssp2;SET @W=@wssp3;SET @bIsCopy=@wssp4; EXEC @iRet = proc_GetNewListItemId @S, @OldFU, @wssp5, @bIsCopy, @NewDoclibRowIdInput OUTPUT, @MaxNewRowsInput OUTPUT; SELECT @NewDoclibRowIdInput, @MaxNewRowsInput; BEGIN TRAN; IF @iRet <> 0 GOTO done; EXEC @iRet = proc_RenameUrl @S, @W, @OldFU , @NewFU, @wssp6, @wssp7, @wssp8, @NewDoclibRowIdInput, @MaxNewRowsInput, @wssp9, @wssp10, @wssp11, @wssp12, @wssp13, @OldItemId OUTPUT, @wssp14 OUTPUT, @wssp15 OUTPUT;;IF @iRet = 0 BEGIN EXEC @iRet = proc_EnsureTranLockNotRequired @wssp16, @wssp17, @wssp18; END;EXEC proc_GetAuditMaskOutput @wssp19, @wssp20, @wssp21, @wssp22, @wssp23 OUTPUT, @wssp24 OUTPUT, @wssp25 OUTPUT, @wssp26 OUTPUT; done: IF @iRet = 0 BEGIN COMMIT; EXEC proc_UpdateListItemCount @wssp27, @wssp28; EXEC proc_UpdateListItemCount @wssp29, @wssp30; EXEC proc_UpdateDiskUsed @S; END ELSE ROLLBACK SET @wssp31=@iRet;' CommandType: Text CommandTimeout: 0 Parameter: '@wssp0' Type: NVarChar Size: 4000 Direction: Input Value: 'Lists/list01/Folder01a' Parameter: '@wssp1' Type: NVarChar Size: 4000 Direction: Input Value: 'Lists/list01/Folder01' Parameter: '@wssp2' Type: UniqueIdentifier Size: 0 Direction: Input Value: 'fa0bf3ea-a140-475f-a219-45a118e89d57' Parameter: '@wssp3' Type: UniqueIdentifier Size: 0 Direction: Input Value: 'ba9bb92d-e9fb-483b-b5e1-8726f31d315e' Parameter: '@wssp4' Type: Bit Size: 0 Direction: Input Value: 'False' Parameter: '@wssp5' Type: UniqueIdentifier Size: 0 Direction: Input Value: '4718115d-8ab8-4e5d-a6f3-2280e177c8a5' Parameter: '@wssp6' Type: Int Size: 0 Direction: Input Value: '1073741823' Parameter: '@wssp7' Type: Int Size: 0 Direction: Input Value: '0' Parameter: '@wssp8' Type: Int Size: 0 Direction: Input Value: '0' Parameter: '@wssp9' Type: Int Size: 0 Direction: Input Value: '262148' Parameter: '@wssp10' Type: Int Size: 0 Direction: Input Value: '1' Parameter: '@wssp11' Type: Int Size: 0 Direction: Input Value: '1' Parameter: '@wssp12' Type: Int Size: 0 Direction: Input Value: '0' Parameter: '@wssp13' Type: Int Size: 0 Direction: Input Value: '0' Parameter: '@wssp14' Type: Bit Size: 0 Direction: Output Value: '' Parameter: '@wssp15' Type: NVarChar Size: 520 Direction: Output Value: '' Parameter: '@wssp16' Type: UniqueIdentifier Size: 0 Direction: Input Value: 'fa0bf3ea-a140-475f-a219-45a118e89d57' Parameter: '@wssp17' Type: UniqueIdentifier Size: 0 Direction: Input Value: '4718115d-8ab8-4e5d-a6f3-2280e177c8a5' Parameter: '@wssp18' Type: Bit Size: 0 Direction: Input Value: 'False' Parameter: '@wssp19' Type: Int Size: 0 Direction: Input Value: '1' Parameter: '@wssp20' Type: UniqueIdentifier Size: 0 Direction: Input Value: 'fa0bf3ea-a140-475f-a219-45a118e89d57' Parameter: '@wssp21' Type: NVarChar Size: 4000 Direction: Input Value: 'Lists/list01' Parameter: '@wssp22' Type: NVarChar Size: 4000 Direction: Input Value: 'Folder01' Parameter: '@wssp23' Type: UniqueIdentifier Size: 0 Direction: Output Value: '' Parameter: '@wssp24' Type: Int Size: 0 Direction: Output Value: '' Parameter: '@wssp25' Type: Int Size: 0 Direction: Output Value: '' Parameter: '@wssp26' Type: Int Size: 0 Direction: Output Value: '' Parameter: '@wssp27' Type: UniqueIdentifier Size: 0 Direction: Input Value: 'fa0bf3ea-a140-475f-a219-45a118e89d57' Parameter: '@wssp28' Type: UniqueIdentifier Size: 0 Direction: Input Value: '4718115d-8ab8-4e5d-a6f3-2280e177c8a5' Parameter: '@wssp29' Type: UniqueIdentifier Size: 0 Direction: Input Value: 'fa0bf3ea-a140-475f-a219-45a118e89d57' Parameter: '@wssp30' Type: UniqueIdentifier Size: 0 Direction: Input Value: '4718115d-8ab8-4e5d-a6f3-2280e177c8a5' Parameter: '@wssp31' Type: Int Size: 0 Direction: Output Value: ''

3) 利用状況モニターが右ペインに表示されるため、その中の [プロセス] をクリックして展開します。
4) 列 [ブロック元] に数字が表示されている行の [セッション ID] がブロッキングされているプロセスです。ブロック元になっているセッション ID は該当行の [ブロック元] から確認できます。ブロック チェーンの先頭ブロックを特定するには [先頭ブロック] に 1 が表示されているセッション ID を探します。先頭ブロックが 1 になっているレコードの待機時間に注目し、問題が発生している期間中この値が増加し続けている場合は、該当のセッションの処理が原因でブロッキングが発生している可能性が考えられます。

20160712a

「proc_RenameUrl」ストアドプロシージャの実装を確認すると、以下のような実装になっていることが確認できます。

  • 第１引数：Site ID //fa0bf3ea-a140-475f-a219-45a118e89d57
  • 第２引数：Web ID //ba9bb92d-e9fb-483b-b5e1-8726f31d315e
  • 第３引数：変更前の URL // Lists/list01/Folder01a
  • 第4引数：変更後の URL // Lists/list01/Folder01

20160712l

他にも有用なパラメータ情報が確認できますが、少なくとも該当のサイト、リスト、変更前と変更後のフォルダ名を上記パラメーターから特定することができます。実際に今回のテスト シナリオではサイト コレクションのルート サイト https://sps 上の list01 リストのルート フォルダの名前を Folder01a から Folder01 に変更していますので、ログからも裏付けが取れた形になります。

20160712m

また、詳細な診断ログからは待たされている処理でロックの開放待ちとなっている「AllListsAux」テーブルの参照も確認できます。このことから、フォルダ名をリネームする一連の処理の過程で対象のテーブルに対するロックが発生し、リネーム処理が完了するまでの間対象のテーブルを利用する他の処理が待たされていたと考えられます。

20160712n

 

診断ログからの問題の特定が難しいケース

診断ログを詳細レベルにしても以下のような状況では問題の原因を特定することが難しいケースがあります。

  • ユーザーのアクセス数が多く IIS ログから特定の処理を判断できない
  • 類似の処理が多数混在しており診断ログと SQL Server 側の情報のマッピングが困難な場合
  • ユーザー独自のカスタムソリューションからキックされた処理がブロックチェーンの先頭ブロックを引き起こしている場合

このような場合、問題が発生している最中に対象のプロセスのダンプを採取することで、ダンプ ファイルに記録されたコールスタックの情報から問題の処理の呼び出し元を特定する必要があります。

//ダンプの採取手順
1) タスクマネージャを起動します。
2) [表示] - [列の選択] より PID (プロセス ID) を有効にします。
3) [すべてのユーザーのプロセスを表示] をクリックしてプロセスの一覧から事前に確認した先頭ブロックの原因となっているプロセス ID を確認します。(多くの場合 w3wp.exe になります。)
4) プロセス名を右クリックして [ダンプ ファイルの作成] をクリックします。
5) 「ファイルは正しく作成されました。」メッセージが表示されたら、ダイアログに表示されたファイルの保存先ディレクトリのデータをコピーしてダンプを採取します。
6) 30 秒程度時間を空けて再度同じプロセスのプロセス ダンプを採取します。

WinDbg 等のツールでプロセス ダンプを解析し、異なる 2 つの時点でのスタック情報から処理が完了していないスレッドの呼び出し履歴を調べて原因となっている処理を特定します。
ダンプ ファイルの解析は高度なトラブルシュートになりますので、必要に応じてマイクロソフト サポート サービスの利用をご検討ください。

 

最後に

本投稿では SharePoint のブロッキング問題の調査に着手する際のガイドラインを示しました。私の経験上、ブロッキングに関連する問題は情報不足が原因でスッキリとした原因特定に至らないことが多いように感じます。実際の運用では今回使用したテスト シナリオよりも複雑な要因により発生すると考えられるため簡単に答えに辿り着くのは難しいかもしれませんが、いざ問題が発生した際に、最低限必要な情報を採取しておくことで、再発防止策につながる有益な情報が得られる可能性が高くなりますので、本投稿の内容が今後の運用の参考になれば幸いです。