SQL ServerのChange Tracking機能をプロダクション環境で運用した際に生じた問題と対応策

OGP

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

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

techblog.zozo.com

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

発生した問題

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

techblog.zozo.com

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

techblog.zozo.com

調査内容

ヘッドブロッカーの特定

ブロッキングが多発していることは事前に分かっていたため、拡張イベントおよび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が残っていたので、解決を試みました。

ブロッカーの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

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

エラー画面

そのため、インスタンスレベルのロックエスカレーション無効化を検討しました。インスタンスレベルでの無効化のためには、2種類のトレースフラグが用意されています。

トレースフラグ 引用元はこちら

メモリ負荷に基づくロックエスカレーションまで無効化するのは危険と判断し、トレースフラグ1224の設定に向けて現状のロックエスカレーション発生状況を確認しました。パフォーマンスモニタの「SQL Server:Access Methods\Table Lock Escalations/sec」で直近24時間のロックエスカレーション発生回数の推移を確認しましたが、ほとんど起きていませんでした。そのため、インスタンスレベルでロックエスカレーションを無効化しても影響は小さいと判断し、下記のクエリでトレースフラグを有効化しました。

DBCC TRACEON(1224, -1)

稼働中のシステムについては、本対応によってトレースフラグを有効化できますが、再起動時は無効になります。したがって、SQL Server構成マネージャーによる再起動時のトレースフラグの自動反映の設定も合わせて行っています。この対応によって、同様の原因によるエラー多発の抑制を期待しました。しかし、後日ブロッキングによるタイムアウトエラー多発が再発してしまい、改めて調査を実施しました。

再調査

トレースフラグ1224を有効化したことで、テーブルAのサイドテーブルに対するロックエスカレーションは発生していませんでした。しかし、同様のテーブルにページ単位で長時間のブロッキング発生が確認できました。しばらくは問題が起きていなかったため、実行プランの変化とブロッキング多発の関係性を疑いました。そこで、過去1週間のsys.dm_exec_query_statsから実行プランの変化を確認した結果、以下のことが分かりました。

  • クリーンアップ用のシステムストアドプロシージャは、「大半が並列処理で実行されるプラン」と「常にmaxdop=1で処理されるプラン」の2種類が存在していた
  • エラー多発時は「大半が並列処理で実行されるプラン」がmaxdop=1で実行されており、スロークエリ化していた
  • 「大半が並列処理で実行されるプラン」の方が、平均の実行時間は短い傾向にあるが、実行時間の最大値が顕著に長くなってしまう場合がありエラー多発につながっていた

以上の結果から、「常にmaxdop=1で処理されるプラン」に固定化してしまえば良いと考え、プランガイド設定の実現可能性について調査しました。その結果、システムストアドプロシージャに対してもプランガイドは設定可能であると分かりました。しかし、「何故実行プランが揺れるのか」可能な限り調査しておいた方が良いと考え、クエリを分析しました。該当のステートメントは以下の通りです。

(
 @csn BIGINT
 ,@batch_size INT
)

DELETE TOP (@batch_size)
FROM sys.[change_tracking_<object_id>]
WHERE sys_change_xdes_id IN (
    SELECT xdes_id
    FROM sys.syscommittab ssct
    WHERE ssct.commit_ts <= @csn
    )

このクエリに対して以下のように考察しました。

  • sys_change_xdes_idはクラスタ化インデックスの第1列目のキーである
  • したがって、sys.syscommittabのサブクエリの行数が十分に少なければnested loopによる結合が採用されmaxdop=1で実行されやすいはず
  • しかし、サブクエリの行数が多すぎるとオプティマイザが判断してhash matchによる結合を並列で実行することがある模様
  • sys.syscommittabには「commit_ts」「xdes_id」の順番でインデックスが作成されており、サブクエリもindex seekで問題なく処理できそう
  • しかし、基数推定で大量のレコードを返すと推定した場合にフルスキャンが選ばれている模様

以上の考察から、Change Trackingのサイドテーブルの行数がどの程度あるのか、保持期限過ぎのレコードは削除されているのか気になり確認しました。

select min(commit_time), max(commit_time), count(*) from sys.syscommittab with(nolock)
where xdes_id in (select sys_change_xdes_id from sys.[change_tracking_<object_id>] with(nolock))

上記クエリを実行した結果、データの保持期間は1日で設定しているものの、2か月前のデータまで残っておりレコード数は億単位になることが判明しました。原因としては、大量にデータ変更が行われている環境では、自動クリーンアップによるデータ削除が追い付かずに保持期間を超えたデータが保持されている等が考えられます。レコード数を本来のあるべき姿である1日分にまで削減できれば、基数推定でも自然と少ないレコード数を予測してくれそうです。その結果、index seek+nested loopな「常にmaxdop=1で処理されるプラン」に安定するだろうと考えました。

sys.syscommittabの手動クリーンアップ

sys.syscommittabの手動削除には「sys.sp_flush_commit_table_on_demand」というシステムストアドプロシージャを使用しました。こちらの記事で言及されているように、タイミングによっては削除対象のレコードが存在するのに1件も削除できない場合がありました。対応策としては、記事中に記載されている通り「何度もリトライ」するために以下クエリを実行しました。

set nocount on
set lock_timeout 1000
SET DEADLOCK_PRIORITY LOW

declare @rows bigint

select top (1) @rows = rows from sys.partitions with(nolock)
where object_id = object_id('sys.syscommittab')
and index_id = 1

while (@rows > 100000000)
begin
  exec sys.sp_flush_commit_table_on_demand 1000000

  waitfor delay '00:00:01'

  select top (1) @rows = rows from sys.partitions with(nolock)
  where object_id = object_id('sys.syscommittab')
  and index_id = 1
end

こちらの方法で、サイドテーブルのレコードを大量に削除できましたが、削除すべきレコードを全て削除できませんでした。原因としては、各テーブルに対応するサイドテーブル「sys.change_tracking_<object_id>」に紐づくコミット日時の最小値に紐づくデータまでしか、sys.syscommittabの削除ができないようです。したがって、sys.change_tracking_<object_id>も手動で削除すべきということが分かりました。自動クリーンアッププロセスにおいても、sys.syscommittabのDELETEは動いているものの、where句で指定される最小コミット日時が更新されないため1件も削除できない事態に陥っていました。一方で、sys.change_tracking_<object_id>はレコードの削除自体は少しずつ行えているものの、大量のデータ更新が行われたことで期限切れデータが溜まり続けているようでした。

sys.change_tracking_<object_id>の手動削除はこちらで紹介されている「sp_flush_CT_internal_table_on_demand」を使うことで実現できるようです。しかし、バージョンやSPで一定の条件があり、当時の環境ではこのストアドプロシージャは使用できないことが分かりました。

Change Trackingの全サイドテーブルの手動クリーンアップ

そこで、Microsoftのサポートサービスを利用して解決策を問い合わせたところ、Change Trackingの全サイドテーブルを手動削除するためのストアドプロシージャを共有いただきました。実装のイメージとしては、こちらの記事で紹介されているプロシージャが参考になると思います。実行時は以下のようにパラメータを指定して実行します。

EXEC sp_ManualChangeTrackingMetaDataCleanupProc
  @NoOfRowsToDeletePerIteration = 10000, --1イテレーションあたりの削除対象行数
  @NoOfIterations = 1000; --繰り返し回数

注意点としては、SSMSで実行する場合は「ツール」「オプション」から「実行後に結果を破棄する」にチェックいれておかないと、結果が多すぎると途中でエラーになることがあります。

SSMSのオプション

このストアドプロシージャを使い、削除可能なサイドテーブルのレコードを手動で全て削除しました。そのあと、以下の手順で恒久対策を完了としました。

  1. sp_ManualChangeTrackingMetaDataCleanupProcを使って定期的にサイドテーブルを一定数削除するジョブを作成
  2. 削除レコード数が不十分で期限切れデータが溜まり続ける予兆を検知するための検知ジョブを別途作成

sp_ManualChangeTrackingMetaDataCleanupProcの実行にはDAC接続が必須となっています。DAC接続をSQL Serverエージェントジョブで実現するには、例えばジョブの種類を「オペレーティングシステム(CmdExec)」に指定して以下のように「-A」オプションを付ける方法が考えられます。

sqlcmd.exe -S "xxx" -A -E -d xxx -Q "EXEC sp_ManualChangeTrackingMetaDataCleanupProc @NoOfRowsToDeletePerIteration = 10000, @NoOfIterations = 1000"

また、検知ジョブのためのクエリは以下のようなイメージです。

declare @diff_days int
select @diff_days = datediff(day, min(commit_time), max(commit_time)) from sys.syscommittab with(nolock)

if @diff_days > 3 --この場合の閾値は3日
begin
  --msdb.dbo.sp_send_dbmailなどで通知
end

まとめ

本記事では、SQL ServerのChange Trackingを有効にした環境で発生した問題と、その原因調査から対応策の実施までの流れを紹介しました。期限切れデータが溜まり続けることで、自動クリーンアップ処理が遅延しやすくなり、ブロッキングの多発につながることがあります。ロックエスカレーションを無効化するにはインスタンスレベルで実施する必要がありますが、無効化したとしてもブロッキングの発生を抑制できないケースに遭遇しました。自動クリーンアップ処理とは別に、自前で作成したクリーンアップ処理をジョブ化して定期実行することでサイドテーブルのレコード数の不要な増加を抑制できます。

本対応実施により、自動クリーンアップ処理の中でブロッキングの原因となっていたステートメントの実行速度が大幅に改善されました。以前は最大で60秒かかることもありましたが、今では直近1週間で最大でも1.5秒で完了するようになっています。同様の事象で困っている方の参考になれば幸いです。

最後に

ZOZOでは、一緒にサービスを作り上げてくれる方を募集中です。ご興味のある方は、以下のリンクからぜひご応募ください!

corp.zozo.com

カテゴリー