SE の雑記

SQL Server の情報をメインに Microsoft 製品の勉強内容を日々投稿

「待ち事象」を起点とした SQL Server のボトルネックの調査の基本 その 2

leave a comment

「待ち事象」を起点とした SQL Server のボトルネックの調査の基本 その 1 の続きになります。

前回の投稿では、待ち事象の説明や、待ち事象の情報の取得方法について触れてみました。
今回の投稿では、実際に情報を取得しながら、待ち事象を確認してみたいと思います。

ログデータとして取得を行う

パフォーマンスモニター / DMV の情報の共通的な考え方として、情報を「ログデータとして取得を行う」ということがあります。
ログとは「時系列の順序性のある履歴」というような見方をすることがあるかと思います。
待ち事象を確認するためには、「ログとして取得した情報」が必要となります。
パフォーマンスモニターによるログの取得
パフォーマンスモニターの情報は「リアルタイム」「ログ」の 2 種類の方法で取得することができます。
リアルタイムでは次のように「今のサーバーの状況」を確認することが可能です。
現状を確認するだけであれば、これで問題ないのですが、この情報では「過去にさかのぼってデータを確認」することはできません。
これは「ログとして情報を取得できていない」ということになります。
image
ログとして取得する場合には、パフォーマンスモニターの「データコレクターセット」の機能を使用することで実現可能です。
image
データコレクターセットでは、取得するカウンターの項目の洗濯と、サンプルの間隔 (取得期間) を選択することができます。
image
これにより、ログを取得することができるようになり、過去のデータも確認することができます。
また、パフォーマンスモニターのログは、時系列データとして確認することも可能ですので、時系列データを簡単に作りたい場合には手間がかからず良いのではないでしょうか。
DMV によるログの取得
DMV については、ログを取得するのは少し考慮が必要です。
というのも、「DMV は SQL を実行したタイミングのスナップショットの情報」ですので、断面的なデータとなります。
これをログに取得する場合、標準機能を使用する場合は データコレクションカスタムコレクション の機能の利用になるかと思いますが、データコレクションを設定していない環境の方が大半なので、この機能を使ってログを取得したことはありません。
SQL を定期的に実行して、テーブルやテキストファイルにログとして保存する方法を使用する機会の方が、実際には多いのではないでしょうか。
次のようなクエリを定期的に実行して、情報を出力しておくことで、ログの取得ができます。

SELECT GETDATE() AS collect_date, * FROM sys.dm_os_wait_stats

レコードの中に日付を入れておくことで、時系列データとして使いやすくなりますので、時系列が判断できる何らかの項目は入れておくと良いのではないでしょうか。
昔作った Simple Monitor というツールも、定期的にクエリを実行し結果をテキストに出力することで、時系列データを生成するというような方法をとっています。
 

待ち事象を調査してみよう

それでは、実際に待ち事象の情報を調査してみましょう。

今回は、ZOZOTOWNで最大級のトラフィックを記録する福袋発売イベントで実施した負荷対策 でも触れられているワーカースレッドを例として、実際に待ちを発生させていきます。
SQL Sever のワーカースレッドは「最大値が CPU コア数に応じて自動的に設定される」のが、デフォルトの設定となっています。
具体的には次のようなロジックにより最大値が設定されます。

プロセッサのコア

32 ビット

64 ビット

4 以下

256

512

8 以下

288

576

16 以下

352

704

32 以下

480

960

64 以下

1472

128 以下

4480

 
この自動的な最大値の設定は、「max worker threads」という設定が「0」に設定されている場合の動作となっており、0 以外の値を設定することで、手動で最大値を設定することも可能です。
次のクエリを実行することで「0」に設定している場合に、自動的に設定される最大値を確認することができますので、自分の環境でどのような値が設定されているかはここで確認するとよいかと。

SELECT max_workers_count FROM sys.dm_os_sys_info

x64 の SQL Server の場合、1 ワーカースレッドにつき 2MB を使用することになりますので、過度なワーカースレッドの割り当ては、消費するメモリの増加にもつながりますので、設定はバランスを考えて行う必要があります。

(x86 の SQL Server の場合は、1 スレッドあたり、512 KB 使用されます)
なお、ワーカースレッドは、使用されていない状態が一定期間続くと、一度解放され、使用するタイミングで再度リソースの確保が行われますので、設定されている値のワーカースレッド数を起動時に確保するというものではなく、状況に応じて割り当てられていく方式となっています。
それでは、パフォーマンスモニターと DMV で調査してみましょう。
今回は、Go 言語を使用した、次のようなプログラムを実行しています。

  1. 最初に 15 秒間、特定のレコードにロックを取得した状態にする
  2. ロックが取得されている状態で、該当のレコードに対して更新を行うクエリを Goroutine により 300 処理並列で実行

「1.」で実行されているクエリがブロッカーとなり、この処理が完了するまで「2.」の処理が完了しないような状況を作り出しています。

この「2.」 のクエリは、「実行状態」のクエリとなりますのでワーカースレッドが使用されるクエリとなり、一時的に 300 のワーカースレッドが消費されるような状態となります。
今回の環境は、1 コアの仮想マシンとして起動していますので、デフォルトの設定では「512」まで、ワーカースレッドを作ることができます。
ワークロードとしては次の 2 種類を実行します。

  • 「max worker threads = 0」(512) の状態
  • 「max worker threads = 0」(200) の状態

 

パフォーマンスモニターを利用した待ち事象の調査

パフォーマンスモニターで待ち事象を取得したい場合、SQL Server: Wait Statistics の項目をログとして取得します。

今回は次のような設定でログの取得を行っています。
image
最初の状態では、待ち事象の「waits in progress」の状態は次のようになりました。

image
高い値を示しているのは「Lock waits」となっています。

今回のワークロードでは「ロックによる競合の発生回数が高い」ことが確認できたことになります。
ワーカースレッドについては「Wait for the workers」というカウンターになるのですが、ワーカースレッドが 512 の状態では、処理待ちはほとんど発生していないことが確認できます。

(平均 / 最大 の値から確認しています)
image
このことから、処理効率の改善を行うためには「ロック」に対してのアプローチが有効であると判断ができます。
それでは、ワーカースレッドの数を 200 に減らしてみると、どうなるでしょう。
赤の線はロックであり、処理のロジックは変更していないため先ほどと同様に、ロック競合が発生しています。

黒の線は「Wait for the worker」となりますが、先ほどと異なり波形が発生していることが確認できますね。
image
このことから「ワーカースレッドの枯渇が発生し、ワーカースレッド起因の待機が発生した」ということが確認できます。
この波形が確認できたことにより、「ワーカースレッドの設定の見直しの必要性の検討」がデータとして取得できたことになります。
今回はロックとワーカースレッドが顕著に波形を描いていますが、「ディスクアクセスの状況」についても確認することができます。

この情報と「インデックスの使用状況」「SQL Server のキャッシュメモリの使用状況」を組み合わせることで、

  • 大量データアクセスによるディスクアクセスの発生
  • データキャッシュの不足によるディスクアクセスの発生

というようなことを確認することもできますので、複数の情報を組み合わせることで様々な見方を行うことが可能です。
 

DMV を使用した待ち事象の調査

それでは、DMV を使用した調査も実施してみましょう。
DMV で確認する際の注意事項ですが「DMV の待ち事象の情報は、SQL Server のサービスを最後に起動してからの累計情報」となることです。
次のコマンドを実行することで、累積値を初期化することができます。

DBCC SQLPERF('sys.dm_os_wait_stats', CLEAR)

特定の時間帯を定めて調査を行うのであれば、時間の最初に上記のクエリを実行して初期化すると、解析がしやすくなります。
初期化ができない場合は「2 点で情報を取得し、各項目の差を出すことで、特定時間帯に発生した待ちを取得する」という方法をとってください。
今回は次のクエリでスレッドプールの情報のみを取得してしまいますが、実際には「全ての項目を取得し、特定の時間帯で発生した待ち事象について解析を行う」というアプローチを行います。

SELECT * FROM sys.dm_os_wait_stats WHERE wait_type = 'THREADPOOL'

 
DMV の項目の意味は次のようになります。

  • wait_type : 待ち事象のタイプ (理由)
  • waiting_tasks_count : 待ち事象の発生回数
  • wait_time_ms : 待ち事象の発生により待機した時間 (msec)
  • max_wait_time_ms : 待ち事象の発生により待機した最大時間 (msec)
  • signal_wait_time_ms : 待ち時間のうち、CPU 使用に遷移するのに必要だった時間 (ms)

昔作った資料の抜粋ですが、次のようなイメージですね。
image

気を付けておきたいのは、「max_wait_time_ms」でしょうか。

「DBCC SQLPERF」を実行して累積値の初期化を実行した場合は、特定期間内で発生した最大の待ち時間の取得を行うことができます。

しかし、初期化が実行できず、差分を算出した場合は、「過去に発生した最大待機時間」となる可能性があるため、最大値によるデータの分析ができない可能性があります。
それでは、処理を実行して DMV から、待ち事象の発生を確認してみましょう。

今回作成した Go 言語のプログラムでは、最初に DBCC SQLPERF で累積値を初期化し、最後に、THREADPOOL の待ち事象を確認することができる処理が実装してあります。
その結果をもとにしてデータを見ていきます。

最初はスレッドプールの最大値を 200 としたものです。
image
この設定の場合、スレッドプールの枯渇が発生しますので、「THREADPOOL」の待ち事象の発生が確認できます。

今回のケースでは「191 秒」実行に時間がかかったことが確認できますね。
ワーカースレッドの使用状況は、「sys.dm_os_schedulers」からも確認することができます。

今回は次のようなクエリの結果を出力しています。

select
	SUM(current_tasks_count) AS current_tasks_count,
	SUM(current_workers_count) AS current_workers_count ,
	SUM(active_workers_count) AS activeWorkersCount
from sys.dm_os_schedulers
where status = 'VISIBLE ONLINE'

 
この情報から、実際に使用しているタスクの数を確認すると 200 前後でリミットが来ていることも確認できますね。
ワーカースレッドの設定による最大値がわかっていれば、この情報と比較することで、上限に達しそうになっているかを確認することができます。
それでは、スレッドプールの設定を「0」にしてみます。
実行結果がこちらです。
image
実行時間は先ほどの「191 秒」に対して、今回は「83 秒」となっていることが確認できます。
1 回目の実行は、THREADPOOL の待ちが多く発生していますが、これは「現在、確保しているワーカースレッド数では不足したため拡張を行った」たまに発生した待ち事象となります。

先ほどの実行から継続して実行を行ったため、初期状態で割り当てられているワーカースレッドは「230 程度」となっています。

そこから「330 程度」まで、ワーカースレッドを確保する必要があったため、100 のワーカースレッドを生成するのにかかった時間が 1 回目に顕著に表れてきています。
一度確保したワーカースレッドは再利用することができ、一定期間、未使用の状態が継続するまでは解放されませんので、 連続して実行された 2 回目以降については、確保のオーバーヘッドが抑えられた状態になります。
DMV を使用するとこのように、現状と効果の確認を行うことができます。

数秒間隔で DMV の内容を取得し、その差分データを出すことで、Excel 等でグラフ化をすることもできますので「スナップショットの断面を複数組み合わせることによる時系列データの作成」というアプローチを行うこともできます。
 

最後に

このように、「どの待ち事象の発生が多いか」を調べることで「どのリソースに対してのアプローチを行えばよいか」の考察と、改善方法の検討を行うことができます。
他の情報と組み合わせることで、さらにその考察を補強することもでき、メトリクスの収集はかなり奥が深い領域だと思います。
ある程度、知識がついてくると「SQL Server のパフォーマンス監視製品ではどのような情報の取得を行っているのか」の推測もできるようになってきますし、Zaiba2 のような、簡易のメトリクス収集の仕組みを独自に作成することもできるようになります。

 
私の業務形態は、今はオンサイト支援が大半になっているのですが、そのオンサイト支援の中で、このようなメトリクス取得についてのスキルトランスファーを行うこともできますので、もし自社で実施したいというようなご希望がありましたら、お仕事の相談をご検討いただければ幸いです。

Share

Written by Masayuki.Ozawa

1月 5th, 2019 at 10:12 pm

Leave a Reply