こんにちは、SRE部の廣瀬です。
弊社のシステムには、基幹DBであるSQL ServerからBigQueryへと低遅延でデータを同期する「リアルタイムデータ連携基盤」が存在します。詳しい仕組みについて以下の記事で紹介されているので、よろしければご覧ください。
ZOZOTOWNを支えるリアルタイムデータ連携基盤 - ZOZO TECH BLOG
上記の記事の中でも紹介されていますが、SQL Server側のテーブルの変更を検知するために「Change Trakcking」という機能を使用しています。本記事では、このChange Trackingをプロダクション環境に導入したあとに発生した問題と、どのように調査・対応していったのかを紹介します。
発生した問題
あるDBに対する全クエリの内、一部のクエリでタイムアウト多発が約10分間ほど継続した後、自然解消しました。同タイミングでDBのブロッキングが多発しているwarningもあがっていたため、DB観点での調査を実施しました。調査は以前紹介した障害調査フローに従って実施したので、併せてご覧ください。
SQL Serverの障害調査フローと事例のご紹介～原因不明な障害の調査から解決まで～ - ZOZO TECH BLOG
また、調査に使用するログは以下の仕組みを使って収集していますので、よろしければこちらも合わせてご覧ください。
トラブルの原因特定率を劇的に向上させるSQL Serverロギングの仕組み作り - ZOZO TECH BLOG
調査内容
ヘッドブロッカーの特定
ブロッキングが多発していることは事前に分かっていたため、拡張イベントおよび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しかし、システムテーブルのため以下のようなエラーが発生して設定を変更できませんでした。
続きはこちら
/assets/images/7661308/original/3a023d97-0ee4-488d-a826-b9ee662c0ee1?1632994701)
/assets/images/7661308/original/3a023d97-0ee4-488d-a826-b9ee662c0ee1?1632994701)
/assets/images/7661308/original/3a023d97-0ee4-488d-a826-b9ee662c0ee1?1632994701)
