89
96

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?

More than 5 years have passed since last update.

スタートトゥデイ工務店Advent Calendar 2017

Day 20

SQLServer: 現在実行中クエリのリアルタイムトラブルシューティング

Last updated at Posted at 2017-12-04

システムが突然遅くなる、特定の機能が突然遅くなった、いつまでたっても実行中のクエリが完了しない、などのトラブルの原因調査をリアルタイムで行うのに使えるクエリと、それらを組み合わせてトラブルシュートする一例を紹介します。
動的管理ビュー(DMV)を使用します。

#1. 現在実行中のクエリ一覧を取得する

SELECT TOP 100
     der.session_id as spid
    ,der.blocking_session_id as blk_spid
    ,datediff(s, der.start_time, GETDATE()) as elapsed_sec
    ,DB_NAME(der.database_id) AS db_name
    ,des.host_name
    ,des.program_name
    ,der.status -- Status of the request. (background / running / runnable / sleeping / suspended)
    ,dest.text as command_text
    ,REPLACE(REPLACE(REPLACE(SUBSTRING(dest.text, 
    (der.statement_start_offset / 2) + 1, 
    ((CASE der.statement_end_offset
    WHEN -1 THEN DATALENGTH(dest.text)
    ELSE der.statement_end_offset
    END - der.statement_start_offset) / 2) + 1),CHAR(13), ' '), CHAR(10), ' '), CHAR(9), ' ') AS current_running_stmt
    ,datediff(s, der.start_time, GETDATE()) as time_sec
    ,wait_resource --ロックされているリソース名
    ,wait_type
    ,last_wait_type --最後または現在の待機の種類の名前
    ,der.wait_time  as wait_time_ms
    ,der.open_transaction_count
    ,der.command
    ,der.percent_complete
    ,der.cpu_time
    ,(case der.transaction_isolation_level
      when 0 then 'Unspecified'
      when 1 then 'ReadUncomitted'
      when 2 then 'ReadCommitted'
      when 3 then 'Repeatable'
      when 4 then 'Serializable'
      when 5 then 'Snapshot'
    else cast(der.transaction_isolation_level as varchar) end) as transaction_isolation_level
    ,der.granted_query_memory * 8 as granted_query_memory_kb --キロバイト単位
    ,deqp.query_plan -- 実行プラン
FROM
    sys.dm_exec_requests der
JOIN sys.dm_exec_sessions des ON des.session_id = der.session_id
OUTER APPLY sys.dm_exec_sql_text(sql_handle) AS dest
OUTER APPLY sys.dm_exec_query_plan(plan_handle) AS deqp
WHERE
    des.is_user_process = 1
AND datediff(s, der.start_time, GETDATE()) >= 1 -- 例:1秒以上実行中のクエリに限定
AND dest.text like '%%' -- クエリの中身でlike検索したいときはここを編集
ORDER BY
    datediff(s, der.start_time, GETDATE()) DESC

現在実行中のクエリ一覧が取得できます。〇秒以上経過しているクエリだけや、クエリに〇〇という文字を含むクエリだけに限定するなどwhere句に指定する条件によって便利な使い方ができるかと思います。
また、「システムが遅いんだけど」といった問い合わせがきたときにとりあえず実行してみるとDB側の状況がつかめるので、とりあえず実行してみるのがおすすめです。

参考:http://www.carehart.org/blog/client/index.cfm/2015/2/10/show_running_sql_server_queries

#2. 特定のプロセスのボトルネックを推定する

select * from master.dbo.sysprocesses
OUTER APPLY sys.dm_exec_sql_text(sql_handle) AS qt
where 
spid = *** -- 1番で取得したsession_idをここにセット

いつまでたっても終わらないクエリが、何に時間がかかっているのかを推定するのに使えます。
image.png
↑実行することで取得できるカラムの一部です。特に役立ちそうなカラムを黄色で塗っています。

[blocked]
 ここが0でない場合、その値をIDとして持つプロセスにブロックされています(ロック取得待ちなど)

[lastwaittype]
 クエリが最後に待ち状態になったときの原因が表示されます。問題なく実行されているクエリであれば、2番のクエリを実行するたびにカラムの内容が何度か変化しますが、何度実行してもlastwaittypeが同じ値の場合は、そのwaittypeからクエリのボトルネックを特定できる可能性が高いです。経験上、いつまでも終わらないプロセスを調査した際に見かけるlastwaittypeと、それぞれどういった待ち状況なのかを説明します。

PAGEIOLATCH_SH : 物理的にディスクからデータを読み込むときに、その完了を待っている状況を示します。この待ち状態が続く場合、大量のデータを読み取るような実行プランになっていないか確認が必要です。統計情報が古い等の理由で最適な実行プランが生成されていない可能性もありますので、実行プランをまずチェックしてみてください。
RESOURCE_SEMAPHORE : メモリリソースの獲得待ちです。大量にメモリを確保しているクエリが無いかチェックしてみてください。各クエリがどれだけメモリリソースを確保しているかチェックするクエリは以降で紹介します。
SOS_SCHEDULER_YIELD : CPUリソースの獲得待ちです。この待ち状態がずっと続くときは、基本的にDBサーバーのCPU負荷がかなり高い状態にあるはずです。ただし、統計情報が古い等の理由で最適な実行プランが生成されず、並列実行すればすぐ終わるのに1コアで延々と関数を計算しているために長時間実行されてしまうようなケースも稀に経験したことがあります。最初にサーバーのCPU負荷を、問題なければ実行プランの中で推定レコード数と実際のレコード数に大きく乖離がある箇所が無いかチェックし、もしあれば統計情報の更新によって解消される可能性が高いです。
LCK_M***_ : ロックの獲得待ちです。***にはU/S/Xなどいろんな文字が入ります。この待ち状態が続くときは、他のプロセスによってロックの獲得がブロックされ続けている可能性が高いです。[blocked]カラムのプロセスIDからブロックしているクエリをチェックして、なぜ長時間実行されているかの確認が必要です。
ASYNC_NETWORK_IO : DB側での実行は終わっているけど、そのレコードセットを使うプログラム側で(ループ処理などが原因で)長時間レコードセットを使用し続けている場合にこの待ち状態が続きます。本当にプログラム側でループ処理が必要なのか、DB側で一気に処理できないのか、検討する価値があると思います。

[cpu]
 このクエリの実行に使用したcpu時間です(単位はリファレンスにも書いてない。。)lastwaittypeがSOS_SCHEDULER_YIELDのままの場合、実行するたびにこのカラムの値が増えていくのを確認できるかと思います。

[physical_io]
 物理IO数です(単位はリファレンスにも書いてない。。)lastwaittypeがPAGEIOLATCH_SHのままの場合、実行するたびにこのカラムの値が増えていくのを確認できるかと思います。

#3. DB別のコネクション数の分布をチェック

SELECT DB_NAME(sP.dbid) AS the_database
  , COUNT(sP.spid) AS total_database_connections
FROM sys.sysprocesses sP
GROUP BY DB_NAME(sP.dbid)
ORDER BY 1;

現在のコネクション数を確認できます。SQLServerでは仕様上、32767コネクションが上限で、それ以上はエラーになってしまいます。
この数値が高い場合は、プログラム側でコネクションをこまめにclose()しているかコードの見直しを検討するといいかもしれません。また、(結果として高コネクション数につながる)実行時間が長いクエリが大量に実行されていないかチェックし、クエリチューニングの実施も必要かもしれません。

#4. メモリを消費しているクエリをチェック

SELECT * FROM sys.dm_exec_query_memory_grants a
outer APPLY sys.dm_exec_sql_text(a.sql_handle) AS sql_text
outer APPLY sys.dm_exec_query_plan(a.plan_handle) AS query_plan
order by grant_time desc, granted_memory_kb desc

各クエリがどれだけメモリリソースを確保しているか確認できます。
SELECT結果の中のgranted_memory_kbカラムが、確保したメモリ総量(KB単位)となるので、granted_memory_kbを全レコードについて足し合わせた結果がサーバー全体で確保を許可しているメモリ(最大サーバーメモリ)に近くなると、RESOURCE_SEMAPHORE待ちのクエリが大量に発生してしまいシステムのレスポンスが全体的に遅くなってしまう場合があります。メモリを大量に消費しているクエリのチューニングによって解消される可能性があります。

参考: https://www.mssqltips.com/sqlservertip/2827/troubleshooting-sql-server-resourcesemaphore-waittype-memory-issues/

#5. ブロッキングが起きているクエリをチェック

CREATE TABLE #sp_who2 (SPID INT,Status VARCHAR(255),
      Login  VARCHAR(255),HostName  VARCHAR(255),
      BlkBy  VARCHAR(255),DBName  VARCHAR(255),
      Command VARCHAR(255),CPUTime INT,
      DiskIO INT,LastBatch VARCHAR(255),
      ProgramName VARCHAR(255),SPID2 INT,
      REQUESTID INT)
INSERT INTO #sp_who2 EXEC sp_who2
SELECT      *
FROM        #sp_who2
WHERE       DBName <> 'master'
--and Status in ('runnable', 'running')
and blkby <> '  .' 
and spid <> blkby
and SPID > 50
ORDER BY    cpuTime desc

DROP TABLE #sp_who2

このクエリを実行することで取得できるデータは、現在実行がブロックされているクエリ達です。
BlkByカラムにブロックしているプロセスが表示されるため、どんなクエリがブロッキングの原因となっているかさらに調査します。
頻発する場合は、BlkByカラムにでてくるクエリのチューニングによって軽減/解消される可能性があります。

※5番だけ自分の中で精度が怪しく、正しく取得できないケースがあるかもしれません。。高精度なクエリをご存知の方いましたら教えていただけると嬉しいです。

#6. 調査用のクエリ達を組み合わせてトラブルシュートする
実際に上記クエリたちを組み合わせることで原因を特定できる可能性があがると思います。
例えばいつまでも終わらないクエリについて調査したときに、下記の手順で解消することができました。

1番のクエリを実行してプロセスIDを取得

2番のクエリを実行して待ち状態がずっと同じ状態かチェック

SOS_SCHEDULER_YIELDの待ち状態がずっと続いていたため、CPUボトルネックと判断

サーバーのCPU負荷を確認。まったく問題が無いため、実行プランをチェック

直列の実行プランが推定実行プランとして表示された。推定コストもかなり小さいにも関わらず、ずっとCPUリソースを使用し続けている(しかも1コア固定で)状況から、実行プランが最適なものでない可能性が高いと推測

参照テーブルの統計情報を確認したところ、古かったため最新の状態に更新(UPDATE STATISTICS)

再度実行したところ並列プランが生成され短時間で実行が完了

#7. まとめ
原因を特定すること、もしくは特定できなくても推測の確度を高めることがトラブルシューティングのためには大切だと思います。
今回紹介した方法が役に立てれば嬉しいです!

89
96
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
89
96

Delete article

Deleted articles cannot be recovered.

Draft of this article would be also deleted.

Are you sure you want to delete this article?