こんにちは、SRE部の廣瀬です。

弊社のシステムには、基幹DBであるSQL ServerからBigQueryへと低遅延でデータを同期する「リアルタイムデータ連携基盤」が存在します。詳しい仕組みについて以下の記事で紹介されているので、よろしければご覧ください。

上記の記事の中でも紹介されていますが、SQL Server側のテーブルの変更を検知するために「Change Trakcking」という機能を使用しています。本記事では、このChange Trackingをプロダクション環境に導入したあとに発生した問題と、どのように調査・対応していったのかを紹介します。

発生した問題

あるDBに対する全クエリの内、一部のクエリでタイムアウト多発が約10分間ほど継続した後、自然解消しました。同タイミングでDBのブロッキングが多発しているwarningもあがっていたため、DB観点での調査を実施しました。調査は以前紹介した障害調査フローに従って実施したので、併せてご覧ください。

また、調査に使用するログは以下の仕組みを使って収集していますので、よろしければこちらも合わせてご覧ください。

調査内容

ヘッドブロッカーの特定

ブロッキングが多発していることは事前に分かっていたため、拡張イベントおよびDMVのダンプテーブルからブロッキング関連の情報を確認しました。

--拡張イベントのblocked_process_reportイベントを保存しているログテーブルに対してのクエリ
select top 1000 * from xevent_dump with(nolock)
where time_stamp between 'yyyy/mm/dd hh:mm' and 'yyyy/mm/dd hh:mm'
order by time_stamp, is_headblocker desc

その結果、大半が特定のObjectIDへのIXロック獲得を待っている状態であることが分かったため、このオブジェクトを解決すると以下のことが分かりました。

• ブロッキングは「change_tracking_<object_id>」というテーブル起因で発生していた
• このテーブルは<object_id>に紐づくテーブル（以下、テーブルAと呼ぶ）に関して、変更履歴を保存していくサイドテーブルだった
• このテーブルはChange Trackingを有効化した各テーブルごとに1つずつ作成される

Change Trackingのサイドテーブルに対してロックを獲得し、かつ自分自身は実行中である「ヘッドブロッカー」はsession_idが50より小さいシステムプロセスでした。拡張イベントに該当プロセスのexecutionStackが残っていたので、解決を試みました。

select * from sys.dm_exec_sql_text(0x0200000xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx)
select * from sys.dm_exec_sql_text(0x0400ff7xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx)
select * from sys.dm_exec_sql_text(0x0300ff7xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx)

その結果、ヘッドブロッカーのシステムプロセスでは、「sp_changetracking_remove_tran」というシステムストアドプロシージャを実行していたことが分かりました。定義は以下のようになっています。

CREATE PROCEDURE sys.sp_changetracking_remove_tran (
    @objid INT
    ,@csn BIGINT
    ,@batch_size INT
    ,@stat_value BIGINT OUTPUT
    )
AS
BEGIN
    SET NOCOUNT ON
 
    DECLARE @stmt NVARCHAR(1000)
 
    SELECT @stat_value = 0
 
    IF object_name(@objid) IS NOT NULL
        AND @csn IS NOT NULL
    BEGIN
        IF @csn IS NOT NULL
        BEGIN
            SELECT @stmt = N'delete top(@batch_size) from sys.' + quotename(object_name(@objid)) + ' where sys_change_xdes_id in       (select xdes_id from sys.syscommittab ssct where                   ssct.commit_ts <= @csn)'
 
            EXEC sp_executesql @stmt = @stmt
                ,@params = N'@csn bigint, @batch_size int'
                ,@csn = @csn
                ,@batch_size = @batch_size
 
            SELECT @stat_value = @@rowcount
        END
    END
END

パラメータ「@batch_size」で削除レコード数を指定してChange Trackingのサイドテーブルを削除しているようです。ブロックされているプロセスはテーブルへのIXロックの獲得待ちとなっていましたので、テーブル全体にロックをかけている、つまりロックエスカレーションが発生していた可能性が考えられます。ロックエスカレーションは、sys.dm_db_index_operational_statsの「index_lock_promotion_count」カラムで発生回数を確認できます。ロギングの仕組みにより1分ごとにこのテーブルのレコードを保存しているため「index_lock_promotion_count」の変化を確認しました。その結果、エラー多発のタイミングでロックエスカレーションが多発していることが確認できました。

そのため、エラー多発の原因としては、Change Trackingに関するサイドテーブルを自動クリーンアップするバックグラウンドプロセスが、テーブルAのサイドテーブルに対して排他ロックを長時間獲得していたため、と結論づけました。

Change Trackingについて

SQL ServerのChange Trackingは、テーブルの中で変更があった行を追跡できる機能です。テーブル単位で設定を有効化・無効化できます。この機能を有効化すると、以下の2種類のサイドテーブルにデータが溜まっていきます。どちらのサイドテーブルも、設定したデータ保持期間を過ぎると自動クリーンアッププロセスによってデータが削除されます。

sys.syscommittab

1DBあたり1つ作成されます。Change Trackingを設定しているテーブルに更新があった際、コミット日時やトランザクションの内部IDなどがINSERTされます。内部テーブルのためDACでないとSELECTできませんが、sys.dm_tran_commit_tableでラップしてあるので、そこからSELECT可能です。1トランザクションごとに1レコードINSERTされます。

sys.change_tracking_<object_id>

Change Trackingを有効化したテーブルごとに、対応するテーブルが作成されます。例えば、テーブルAのobject_idが「123456」なら、作成されるサイドテーブルは「sys.change_tracking_123456」という名前になります。元テーブルの更新時は、サイドテーブルに対しても変更データの投入が同期的に発生し、このタイミングでサイドテーブルに対してIXロック等のロックが獲得されます。そのため、クリーンアップ処理でサイドテーブルに対してロックエスカレーションが発生すると、ユーザープロセスが元テーブルのデータを更新しようとしてもサイドテーブルへのINSERTがブロックされます。それに伴い、元テーブルの更新処理もブロックされることになります。同じくDACでないと直接はSELECTできませんが、changetable()を経由してアクセスできます。

SELECT top (10) * FROM  CHANGETABLE(CHANGES <table_name>, 0) AS CT

対応策の検討と実施

まず、ロックエスカレーションをテーブル単位で無効化できないか確認しました。ユーザーテーブルであればテーブル単位でロックエスカレーションの発生有無を制御可能です。今回問題となったテーブルに対してロックエスカレーションを無効化するクエリは以下の通りです。

ALTER TABLE sys.change_tracking_<object_id> SET LOCK_ESCALATION = DISABLE

しかし、システムテーブルのため以下のようなエラーが発生して設定を変更できませんでした。

続きはこちら