トラブルシューティングから学ぶSQL Server統計情報の更新タイミング

f:id:vasilyjp:20180927112655j:plain

こんにちは。zozoバックエンド部の廣瀬です。

弊社のサービスではDBMSとしてMicrosoft社のSQL Serverを使用している箇所があります。 本記事では、過去に経験したSQL Server関連のトラブル及びその調査内容をご紹介し、最後にトラブルシューティングを通して策定した統計情報の更新に関する方針をまとめます。

トラブル発生

ある日突然、SQL Serverが稼働しているサーバーのCPU使用率が高騰し、100％に張り付く状態が一定期間続きました。

CPU使用率のグラフを見ただけでは、なぜ突然高騰したのか原因は分かりません。 そのため、原因を特定するための調査を実施しました。

トラブルシューティング

同一ホスト上で稼働している主要なプロセスはSQL Serverしか無かったため、SQL Server上でCPUリソースを多く消費するようなクエリが実行されていることを疑いました。

現在実行中のクエリのステータスを確認するため、動的管理ビュー（Dynamic Management Viewの略。以下DMVと呼ぶ）を使用したクエリを実行します。 ※実行にはVIEW SERVER STATE権限が必要です。

SELECT TOP 500 dest.TEXT AS [Command text]
  ,(
    SELECT TOP (1) lastwaittype
    FROM master.dbo.sysprocesses
    WHERE spid = der.session_id
    ) AS lastwaittype
  ,datediff(s, der.start_time, GETDATE()) AS time_sec
  ,datediff(s, der.start_time, GETDATE()) / 60.0 AS time_min
  ,DB_NAME(der.database_id) AS DatabaseName
  ,der.command
  ,des.login_time
  ,des.[host_name]
  ,des.[program_name]
  ,der.session_id
  ,SUBSTRING(dest.TEXT, der.statement_start_offset / 2, (
      CASE 
        WHEN der.statement_end_offset = - 1
          THEN LEN(CONVERT(NVARCHAR(MAX), dest.TEXT)) * 2
        ELSE der.statement_end_offset
        END - der.statement_start_offset
      ) / 2) AS current_running_stmt
  ,qp.* -- 実行プラン
FROM sys.dm_exec_requests der
INNER JOIN sys.dm_exec_connections DEC ON der.connection_id = DEC.connection_id
INNER 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 qp
WHERE des.is_user_process = 1
  AND datediff(s, der.start_time, GETDATE()) >= 1
ORDER BY datediff(s, der.start_time, GETDATE()) DESC

f:id:vasilyjp:20180524184648p:plain

実行結果の一部を抜粋します。クエリの内容は伏せさせていただきますが、同一のクエリが多数実行中で、かつ最長で20秒間も実行中の状態でした。

また、lastwaittypeカラムの多くがCPU高負荷の際に発生することが多いSOS_SCHEDULER_YIELDとなっており、突然のCPU使用率高騰との関連性が考えられます。

このクエリの平均のCPU使用時間を確認するため、さらに別のDMVを使ったクエリを実行します。

SELECT TOP 1000 [Average CPU used(ms)] = total_worker_time / qs.execution_count / 1000
  ,[Total CPU used(ms)] = total_worker_time / 1000
  ,[Execution count] = qs.execution_count
  ,[Individual Query] = SUBSTRING(qt.TEXT, qs.statement_start_offset / 2, (
      CASE 
        WHEN qs.statement_end_offset = - 1
          THEN LEN(CONVERT(NVARCHAR(MAX), qt.TEXT)) * 2
        ELSE qs.statement_end_offset
        END - qs.statement_start_offset
      ) / 2)
  ,[Parent Query] = qt.TEXT
  ,DatabaseName = DB_NAME(qt.dbid)
  ,last_execution_time
  ,creation_time
  ,[Total Duration(ms)] = total_elapsed_time / 1000
  ,[Average Duration(ms)] = total_elapsed_time / qs.execution_count / 1000
  ,qp.*
FROM sys.dm_exec_query_stats qs
OUTER APPLY sys.dm_exec_sql_text(qs.sql_handle) AS qt
OUTER APPLY sys.dm_exec_query_plan(plan_handle) AS qp
WHERE qt.TEXT LIKE '%ここにストアド名やクエリの一部を指定することで絞り込む%'
ORDER BY total_worker_time / qs.execution_count DESC

f:id:vasilyjp:20180524184651p:plain

平均のCPU使用時間が約5秒と非常に長いです。 このクエリの1分当たりのクエリ実行回数を計算してみたところ、他のクエリと比べて実行頻度が高いようです。 したがってこのクエリによってCPU高負荷となった可能性が非常に高いと判断しました。 該当のクエリは、かなり前から実行されているクエリだったため、突然実行プランが狂った可能性を疑います。

DMVを使ったクエリでは推定実行プランは取得できますが、実際の実行プランもみれると嬉しいです。 そのためSSMS (SQL Server Management Studio)上で[実際の実行プランを含める]にチェックをつけた状態で該当クエリを実行しました。 ※実際の実行プランを取得する方法として、他には拡張イベントを使用する方法があります。

f:id:vasilyjp:20180524184654p:plain

取得した実行プランの中で、キー参照を約50万回おこなっている箇所があり、ここがボトルネックのようです。

予測実行回数（6301.45）の約80倍も実行されていることが見て取れます。

ボトルネックが判明しましたが、今回はもともと十分な速さで実行されていたクエリが、突然遅くなったという事象です。 そのため、ボトルネックを改善するためのチューニング方法ではなく、なぜ突然CPU高負荷な実行プランが生成されてしまったかを考える必要があります。 原因として、統計情報が古くなっていたことを疑い、該当クエリで使用しているテーブルの統計情報を更新してみました。

--統計情報を更新するためのクエリ
update statistics <テーブル名>

その結果、下図のように問題ない速度で実行されるようになりました。

f:id:vasilyjp:20180524184657p:plain

※今回は統計情報の更新後にクエリがリコンパイルされることを期待し、期待通りリコンパイルされました。ただし、統計情報の更新＝必ずリコンパイル、というわけでもないようです。 https://www.brentozar.com/archive/2015/01/updating-statistics-cause-recompile-no-data-changed/

SQL Serverにおいて、統計情報は自動的に更新される仕組みも用意されています。ただしレコード数の20％が更新されたとき等、自動更新のためには条件を満たす必要があります。 今回のトラブルでは、自動更新が走る前に統計情報が古くなってしまったことで実行プランが狂ったと判断しました。そのため恒久的な対応策として1日1回、定期的に全テーブルの統計情報を更新するジョブを作成しました。

これで今回のトラブルシューティングは完了したはずでした。

トラブル再発

後日、またCPU高負荷な状態に陥ってしまいました。しかも犯人は同じクエリです。 何故だろうとクエリと再度にらめっこしていたところ、気づいたことがありました。それはレコード更新の性質がテーブルによって異なるということです。 クエリに登場するテーブルは開発時に使用した経験があり、各テーブルのレコード更新の性質についてたまたま熟知していました。

  • テーブルA : ユーザーの行動によって少しずつ自然に変化していく
  • テーブルB : バッチ処理で定期的に一定のレコード数が変化する

対応策として実施した1日1回の定期的な統計情報の更新は、テーブルAのような性質を持ったテーブルには効果的でしたが、テーブルBに対しては効果が薄いようです。

よく「統計情報が古い」から実行プランがおかしくなったという表現を使いますが、これは決して統計情報の最終更新日から時間が経過している、という意味では無いと思い知らされました。 正確には「統計情報が古い」とは、「統計が実際のデータ分布と大きく乖離している」状態を指します。 そのためたとえ1時間前に統計情報を更新したばかりでも、バッチ処理等で大量にデータ更新された後では、現在の統計情報は「古い」といえます。

上記考察を踏まえて、定期的な統計情報の更新に加えて、バッチ処理等でレコード数に大きな変化がある場合は処理完了直後に統計情報の更新を実施するようにしました。 その結果、CPU高負荷になることはなくなりました。

統計情報の更新に関する方針

今回のトラブルシューティングを通して学んだ、統計情報の更新に関する方針をまとめます。

下記2点の方針で統計情報を更新することで、「統計情報が古い」ことに起因する実行プランの変化とそれに伴う実行速度の低下および、CPU使用率の上昇を避けることが期待できます。

  1. ユーザーの行動等によって自然に少しずつレコード数が変化していく性質をもったテーブルは、1日1回等、定期的に統計情報を更新
  2. バッチ処理等で、大量にレコード削除/挿入/更新を行う場合は、処理完了直後に統計情報を更新

統計情報更新のためのクエリ

全DBの全テーブルの統計情報を更新するための具体的なクエリも紹介します。こちらをSQL Serverのジョブとして定期的に実行する、などの方法が考えられます。

尚、SQL Serverのメンテナンスプランにも統計情報更新の仕組みは用意されています。 ただしサンプル数を指定する際、全テーブル一律でフルスキャンまたは一定のサンプリングレートしか指定できないようです。

update statisticsを実行する際、サンプリングレート未指定の場合はテーブルのレコード数によって動的にサンプリングレートが決定されます。 この挙動を全テーブルに対する統計情報の更新処理で実現するために、自分でクエリを作成しました。

DECLARE
   @Database sysname
  ,@sql nvarchar(2000)

DECLARE
  CUpdateStatsDatabases CURSOR FAST_FORWARD FOR
    SELECT
      name
    FROM
      master.sys.databases WITH(NOLOCK)
    WHERE
    -- システムDBおよびディストリビューションDB除外、かつオンラインのDBに限定
      Cast(CASE WHEN name IN ('master', 'model', 'msdb', 'tempdb') THEN 1 ELSE is_distributor END As bit) = 0
    AND state = 0

OPEN CUpdateStatsDatabases
FETCH NEXT FROM CUpdatestatsDatabases INTO
  @Database

-- DB単位のループ
WHILE @@fetch_status = 0
BEGIN

  set @sql = ''
                      -- useを使う必要があるが、use単体でexecuteすると実行後にコンテキストが現在のDBに戻ってしまう。そのため丸ごと動的SQLで実行する
  set @sql = @sql + ' USE ' + CAST(@Database AS NVARCHAR(100)) + ';'
  set @sql = @sql + ' DECLARE @sql_update nvarchar(500) '
  set @sql = @sql + '      ,@Table sysname '
  set @sql = @sql + '      ,@Schema sysname '
  set @sql = @sql + ' DECLARE '
  set @sql = @sql + '   CUpdateStatsTables_' + CAST(@Database AS NVARCHAR(100)) + ' CURSOR FAST_FORWARD FOR '
  set @sql = @sql + '     SELECT '
  set @sql = @sql + '       SCHEMA_NAME(schema_id) '
  set @sql = @sql + '       ,name '
  set @sql = @sql + '     FROM '
  set @sql = @sql + '       sys.tables WITH(NOLOCK) '
  set @sql = @sql + ' '
  set @sql = @sql + ' OPEN CUpdateStatsTables_' + CAST(@Database AS NVARCHAR(100)) + ' '
  set @sql = @sql + ' FETCH NEXT FROM CUpdateStatsTables_' + CAST(@Database AS NVARCHAR(100)) + ' INTO '
  set @sql = @sql + '   @Schema, @Table '
  set @sql = @sql + ' '
                      -- テーブル単位のループ '
  set @sql = @sql + ' WHILE @@fetch_status = 0 '
  set @sql = @sql + ' BEGIN '
  set @sql = @sql + ' '
  set @sql = @sql + '   set @sql_update = ''update statistics '' + CAST(@Schema AS VARCHAR(100)) + ''.'' + CAST(@Table AS VARCHAR(500)) '
  set @sql = @sql + '   execute sp_executesql @sql_update '
  set @sql = @sql + '   select @sql_update '
  set @sql = @sql + ' '
  set @sql = @sql + ' FETCH NEXT FROM CUpdateStatsTables_' + CAST(@Database AS NVARCHAR(100)) + ' INTO '
  set @sql = @sql + '   @Schema, @Table '
  set @sql = @sql + ' END '
  set @sql = @sql + ' '
  set @sql = @sql + ' CLOSE CUpdateStatsTables_' + CAST(@Database AS NVARCHAR(100)) + ' '
  set @sql = @sql + ' DEALLOCATE CUpdateStatsTables_' + CAST(@Database AS NVARCHAR(100)) + ' '

  execute sp_executesql @sql

FETCH NEXT FROM CUpdatestatsDatabases INTO
  @Database
END

CLOSE CUpdateStatsDatabases
DEALLOCATE CUpdateStatsDatabases

それでも残る再発の可能性

仮に統計情報をサンプリングレート100％でフルスキャンし、かつ定期的な更新で最新の状態に保ち続けたとしても、クエリが突然遅くなる可能性はまだあります。

ストアドプロシージャやパラメータ化クエリの場合、SQL Serverはコンパイル時に渡されたパラメータを考慮して、最適な実行プランを生成します（パラメータスニッフィングと呼ばれています）。 この時に渡されたパラメータがたまたま非典型パラメータの場合、それ以外の典型的なパラメータにとっては遅い実行プランになってしまう恐れがあります。

Microsoftのブログの中で、ストアドプロシージャであればwith recompileを指定するなど、実行時に強制的に毎回コンパイルさせることで非典型パラメータに関する問題を回避させる案が紹介されています。 こちらは効果的ですが、毎回コンパイルの分だけ実行時間とCPU使用時間が増大してしまい、ユーザーおよびサーバーにとってマイナスの側面もあります。そのためできる限り使用は避けるべきと考えています。

その他の対策としてはOPTIMIZE FOR UNKNOWNというクエリヒントを使用する方法もあります。 こちらはクエリのコンパイルおよび最適化の際に、その時渡されたパラメータ値ではなく、統計データを使用するよう指定するヒントです。

まとめ

本記事では、実際に経験したSQL Serverに関するトラブルから学んだ統計情報の更新に関する方針について紹介しました。

本記事に出てくる技術的な内容や調査用のクエリはほとんどWeb上で既出の内容かと思います。 しかしながら個々の知識を組み合わせて実際に起きたトラブルを調査し、解決まで至ったというプロセスを紹介する記事はあまり無いように思います。 本記事がトラブルシューティングの実例として参考になれば幸いです。

スタートトゥディテクノロジーズでは、一緒にサービスを作り上げてくれるエンジニアを大募集中しています。

ご興味のある方は、こちらからご応募ください！

https://www.starttoday-tech.com/recruit/

カテゴリー