背景

プロダクション環境で、トランザクション開きっぱなし、ロック掴みっぱなしでstatus=sleepingとなり、長時間そのままになっているセッションが原因で断続的なブロッキングが発生していました。

なぜsleepingかつblockingなセッションが発生してしまうかについては、この記事の対象外としますが、今回はそういった「ブロッキングに関与する可能性があり、かつKILLしても問題ないようなクエリ」を自動でKILLする仕組みを考えてみたので紹介したいと思います。

クエリ

※一部バージョンが2016以降じゃないと対応していないクエリを使っています。

-- KILL履歴用のテーブル作成
CREATE TABLE [dbo].[AutoKilledSessionLog](
	[collect_date] [datetime] NULL,
	[command] [varchar](1000) NULL,
	[session_id] [int] NULL,
	[status] [nvarchar](30) NULL,
	[program_name] [nvarchar](128) NULL,
	[client_interface_name] [nvarchar](32) NULL,
	[total_resource_usage] [bigint] NULL,
	[last_request_start_time] [datetime] NULL,
	[last_request_end_time] [datetime] NULL,
	[event_info] [nvarchar](max) NULL
) ON [PRIMARY] TEXTIMAGE_ON [PRIMARY]
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'収集日時' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'collect_date'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'実行したKILLコマンド' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'command'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'session id' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'session_id'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'status(running/runnable/sleeping/suspended/etc...)' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'status'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'program name' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'program_name'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'cliend interface name' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'client_interface_name'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'該当セッションの使用リソースの合算値(cpu,memory等). KILLの判断に使用する' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'total_resource_usage'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'最後にリクエストを開始した日時' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'last_request_start_time'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'最後にリクエストが完了した日時' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'last_request_end_time'
GO

EXEC sys.sp_addextendedproperty @name=N'MS_Description', @value=N'event info' , @level0type=N'SCHEMA',@level0name=N'dbo', @level1type=N'TABLE',@level1name=N'AutoKilledSessionLog', @level2type=N'COLUMN',@level2name=N'event_info'
GO

set nocount on
set transaction isolation level read uncommitted
 
declare @message nvarchar(max)
declare @profile_name varchar(30)
declare @mailto nvarchar (500)
declare @crlf nvarchar(2)
 
set @message = ''
set @profile_name = '***'
set @mailto = '********'
set @crlf = nchar(13) + nchar(10)
 
-- kill対象の情報を定義
declare @kill_target_event varchar(1000) = '***************'
declare @target_program_name nvarchar(128) = '***************'
declare @target_interface_name  nvarchar(32) = '**************'
 
declare
     @command nvarchar(1000)
    ,@session_id int
    ,@status nvarchar(30)
    ,@program_name nvarchar(128)
    ,@client_interface_name nvarchar(32)
    ,@total_resource_usage bigint
    ,@last_request_start_time datetime
    ,@last_request_end_time datetime
    ,@event_info nvarchar(max)
 
declare @sessionList table (
    command varchar(1000),
    session_id int,
    status nvarchar(30),
    program_name nvarchar(128),
    client_interface_name nvarchar(32),
    total_resource_usage bigint,
    last_request_start_time datetime,
    last_request_end_time datetime,
    event_info nvarchar(max)
)
 
-- 対象となるセッションの一覧を作成
insert into @sessionList
select top (10) -- 一応上限を設定
    'kill ' + cast(session_id as varchar) as command
    ,session_id
    ,status
    ,program_name
    ,client_interface_name
    ,(cpu_time + memory_usage + reads + logical_reads + writes) as total_resource_usage
    ,last_request_start_time
    ,last_request_end_time
    ,event_info
from sys.dm_exec_sessions
outer apply sys.dm_exec_input_buffer(session_id, null) as ib
where session_id in (
     select distinct request_session_id from sys.dm_tran_locks with(nolock)
     where request_session_id in
     (
         --5分以上前にトランザクション開始し、sleepingかつ、Sロック以外を取得しているプロセスリスト
         select c.session_id from sys.dm_tran_active_transactions a join sys.dm_tran_session_transactions b on a.transaction_id = b.transaction_id
         join sys.dm_exec_sessions c on c.session_id = b.session_id
         where transaction_begin_time < dateadd(minute, -5, getdate())
         and c.status = 'sleeping'
     )
     and request_mode <> 'S' and request_mode <> 'Sch-S'
)
 
--select * from @sessionList
 
declare kill_cursor cursor for
    select * from @sessionList
 
open kill_cursor
fetch next from kill_cursor into
     @command
    ,@session_id
    ,@status
    ,@program_name
    ,@client_interface_name
    ,@total_resource_usage
    ,@last_request_start_time
    ,@last_request_end_time
    ,@event_info
 
--ループで1セッションずつチェックし、KILLしていいと判断したらKILLを実行
while @@fetch_status = 0
begin
    -- 次ステップで最新の状況で処理が進んでいないかを確認するために、待機を入れる
    waitfor delay '00:00:02'
    -- 該当セッションの処理が進んでいる場合 (情報取得時とリソースの使用状況 / 最終実行時間異なる)、プログラム名が想定のものでない場合はセッションの終了は行わない
    if exists (
        select *
        from sys.dm_exec_sessions
        where
            session_id = @session_id and
            (cpu_time + memory_usage + reads + logical_reads + writes) = @total_resource_usage and
            last_request_start_time = @last_request_start_time and
            last_request_end_time = @last_request_end_time and
            program_name = @target_program_name and
            client_interface_name = @target_interface_name
        )
    begin
        -- コマンドが kill 対象のコマンドの場合
        if @event_info = @kill_target_event
        begin
            execute(@command)
            --print @command
            set @message = @message + @command + @crlf
            -- 履歴テーブルに保存
            insert into AutoKilledSessionLog (collect_date, command, session_id, status, program_name, client_interface_name, total_resource_usage, last_request_start_time, last_request_end_time)
                    values (getdate(), @command, @session_id, @status, @program_name, @client_interface_name, @total_resource_usage, @last_request_start_time, @last_request_end_time, @event_info)
        end
    end
 
    fetch next from kill_cursor into
         @command
        ,@session_id
        ,@status
        ,@program_name
        ,@client_interface_name
        ,@total_resource_usage
        ,@last_request_start_time
        ,@last_request_end_time
        ,@event_info
end
 
close kill_cursor
deallocate kill_cursor
 
if @message <> ''
begin
    exec msdb.dbo.sp_send_dbmail @profile_name = @profile_name, @recipients = @mailto, @subject = '■ DB session auto kill', @body = @message
end

クエリの概要としては、
まず「あやしいセッション」をリストアップします。
あやしいセッションの定義は「5分以上前にトランザクション開始し、sleepingかつ、Sロック以外を取得しているプロセスリスト」です。「あやしい」の定義は環境によって様々かもしれません。

次に、各セッションの進行状況をチェックします。2秒sleepした後でもcpu/reads等、リソースの使用状況がカウントアップされておらず、last_request_***_timeの変化もない場合は、ずっとsleepingであり、KILLしても問題ないと判断します。

最後にKILLして、履歴テーブルに結果を保存します。

安全性を高めるために「よくsleeping/blockingとなるevent_info/program_name/client_interface_nameの組み合わせ」を事前に定義しておき、それらと完全に一致するときだけKILLを実行するようにクエリを組んでいます。

本運用までのステップ

このクエリをジョブで稼働させるにあたり、自動でセッションをKILLすることになるので、リスクが伴います。
そのため、安全に稼働させるために段階的なリリース方法を以下の手順で考えてみました。

１．KILLしない版でジョブを稼働開始(5分に1回)

　　→検知したらメールを飛ばすようにしておく

２．メールが飛んで来たら手動で以下を確認

以下のクエリを実行し、AutoKilledSessionLogで「本稼働開始後であれば自動KILLされていたセッション」が、KILLされるべきだったものかを確認

select 'kill ' + cast(session_id as varchar) as command, session_id, status, cpu_time, memory_usage, reads, logical_reads, writes, last_request_start_time, last_request_end_time, 'dbcc inputbuffer(' + cast(session_id as varchar) + ')' as showquery_command, ib.*, client_interface_name, program_name
from sys.dm_exec_sessions
outer apply sys.dm_exec_input_buffer(session_id, null) as ib
where session_id in (
select distinct request_session_id from sys.dm_tran_locks with(nolock)
where request_session_id in
(
--5分以上前にトランザクション開始し、sleepingかつ、Sロック以外を取得しているプロセスリスト
select c.session_id from sys.dm_tran_active_transactions a join sys.dm_tran_session_transactions b on a.transaction_id = b.transaction_id
join sys.dm_exec_sessions c on c.session_id = b.session_id
where transaction_begin_time < dateadd(minute, -5, getdate())
and c.status = 'sleeping'
)
and request_mode <> 'S' and request_mode <> 'Sch-S'
)
order by session_id

３．3回連続でKILL対象が正しく選別されている場合は、KILLする版でジョブの稼働を開始する

まとめ

ブロッキングに関与する可能性のあるsleepingクエリを自動KILLする仕組みについて考えてみました。
自動検知＋自動KILLのジョブの作成と、それを安全に本番稼働させるための手順についてご紹介しました。
あまり同様の事象に遭遇したことがある方はいないかもしれませんが、どなたかのお役に立てば幸いです。