SQL Server のトラブルシューティングでは「特定の機能を有効化したことによる性能影響への調査」を実施することもあります。
今回は SQL Server 2016 で搭載された「クエリストア」の機能を例として、機能を有効にした場合の性能影響への調査のアプローチを考えてみましょう。
なお、今回の調査は本番環境ではなく、検証環境での調査を前提としています。
Contents
ドキュメントを確認して動作仕様の基本概念を把握し検証のためのワークロードを検討する
最初に実施することは「ドキュメントから機能の基本概念を把握する」ことです。
新規に搭載されたばかりの機能では、ドキュメントが少ない可能性もありますが、リリースされて数回のバージョンアップがされている機能であれば、ドキュメントはかなり充実しているはずですので、最初にドキュメントを確認しましょう。
Google で英語の情報を検索することで、機能検証を深いレベルで実施されている記事がかなりありますので、英語の記事を調べるのも一つの手段です。
(日本語の記事についてはあきらめましょう)
搭載されたばかりの機能でドキュメントが充実していない場合、自分が先駆者になるということで、ドキュメントだけで詳細な情報を得ることをあきらめる必要があることも（最初から詳細なドキュメントが公開されているケースもありますが)
クエリストアであれば、 クエリ ストアでデータを収集する方法 というドキュメントで、どのように情報の取得が行われているかが記載されています。
この中には、クエリストアが情報を取得するための仕組みについても解説が行われています。
クエリストアであれば、このような解説が行われています。
クエリストアはオーバーヘッドを最小限に抑えながら、クエリの情報の取得が行われますが、クエリの情報が取得されるタイミングは、次のようなタイミングであると記載されています。
- 新しいプランが作成されたタイミング (コンパイル時の初回作成 / 再コンパイル時の新規プラン作成)
- クエリが実行されたタイミング
この情報から、設定を有効にすることによる性能への影響については、どのようなワークロードを生成すればよいかを判断することができます。
今回のケースであれば、クエリのコンパイルの発生が情報取得のトリガーの一因となっており、
- コンパイル頻度が高いアドホックなクエリの実行とパラメーター化 (またはストアドプロシージャの実行) によって、影響が出る可能性がある
- 更新系のクエリだけでなく、検索系のクエリも対象となり、検索系のクエリを大量に実行することで、クエリの実行情報をトランザクションログに記録するという、通常の SELECT とは異なる I/O パターンを示す可能性がある
という思考につなげることができ、どのようなワークロードで検証をすれば以下の判断材料にすることができます。
ベースラインを策定するために取得する情報を検討する
性能影響を調査する場合、「機能を無効化した状態の性能情報」を「ベースライン」として取得を行います。
このベースラインの情報がないと設定を有効にしたことでどのような影響が発生したのかを判断することはできません。
感覚値として遅くなったという判断ではなく、数値として設定変更前後の比較ができるようにします。
(なんとなく遅くなったという判断はやめましょう)
Windows 版の SQL Server であれば、次の情報によりベースラインの取得を行います。
- パフォーマンスモニター
- クエリの処理時間
パフォーマンスモニター
パフォーマンスモニターには様々な項目があり、どのような項目を取得すればよいかは、使用するワークロードによって異なりますが、基本的には、
- CPU
- メモリ
- ディスク
- ネットワーク
に関して、情報を取得することになります。
SQL Server で確認すべき基本的な情報については、リソースの利用状況の監視 (システム モニター) に記載されています。
クエリストアの動作仕様から、
- 情報を取得するための CPU 負荷
- 情報をディスクに永続化するためのディスク負荷
- クエリの実行回数
- コンパイルの発生状況
あたりは、最低限抑えておくべき情報であると考えられますので、次の情報を取得します。
- Processor (_Total)\% Processor TIme
- CPU の負荷
- SQLServer:Databases (<DB 名>)\Log Bytes Flushed/sec
- トランザクションログの書き込みのディスクへのフラッシュによるディスクアクセス
- SQLServer:SQL Statistics\Batch Requests/sec
- SQLServer:SQL Statistics\SQL Compilations/sec
- SQLServer:SQL Statistics\SQL Re-Compilations/sec
パフォーマンスモニターの情報はバージョンが変更した際には新機能向けの項目が追加されることがあります。
クエリストアについては、この項目の追加に該当しており、クエリストア用のパフォーマンスモニターのカウンター が追加されています。
検証する機能に応じて、適したカウンターがある場合にはそれらのカウンターも追加しておきます。
最終的には、次のようなパフォーマンスモニターの情報の取得を行っています。
実際にパフォーマンスモニターの情報を取得する際には「データコレクターセット」に取得のための設定を行い、ログとして情報を取得するようにしましょう。
クエリの処理時間
クエリの処理時間については、何らかの方法で取得ができれば問題ないかと思います。
SSMS で取得を行ったり、「SET STATISTICS TIME ON」で取得を行ったり、プログラム側で取得したりと、様々な方法が考えられるかと。
どれが正解というものはありませんので、まずは、自分が取得しやすい方法で確認を行います。
動的管理ビュー (DMV) / 拡張イベント
「さらに事象を詳細に分析する」場合には、動的管理ビューと拡張イベントの活用を検討します。
動的管理ビューと拡張イベントは、SQL Server のバージョンや新規機能の搭載に合わせて、様々な情報が拡張されています。
これらの情報を分析することで、「何が起こっているか」をさらに詳細に分析することができます。
情報の取得と比較を行う
ここまででの検討で、
- 実行するワークロード
- 取得する情報
が定まりましたので、実際にワークロードを実行して、取得した情報と比較します。
今回は「クエリストアを無効にしていた状態」がベースラインとなりますので、まずはベースラインの情報を取得します。
ワークロードの実行方法ですが、自分が実行しやすい方法なら何でも構いません。
私の場合は SqlQueryStress を使用するか、シンプルなワークロードであれば PowerShell で適当にスクリプトを書いてしまっています。
$conString = "Server=xxxxxxxx;User=xxxxxx;Password=xxxxxxxxx;Database=TESTDB"
Measure-Command -Expression {
1..30 | ForEach-Object -ThrottleLimit 30 -Parallel {
$No = $_
$con = New-Object System.Data.SqlClient.SqlConnection($using:conString)
$con.Open()
$sw = [System.Diagnostics.Stopwatch]::StartNew()
1..10 | % {
$cmd = $con.CreateCommand()
$cmd.CommandText = ("SELECT TOP 1 '{0}',* FROM sys.objects" -f (New-Guid).ToString())
[void]$cmd.ExecuteNonQuery()
}
$sw.Stop()
Write-Host ("{0} : {1:00} : {2:#,##0} ms" -f (Get-Date), $No, $sw.ElapsedMilliseconds)
$con.Close()
$con.Dispose()
}
}
このスクリプトを実行している裏で、パフォーマンスモニターの情報の取得を行います。
スクリプトでは、実行時間を出力していますので、実行時間を確認することができます。
それでは、情報の比較を行ってみましょう。
クエリストアについてはいくつかの設定がありますが、全ての情報を取得するのであれば、次のようにキャプチャモードに ALL を指定しますし、
ALTER DATABASE [TESTDB] SET QUERY_STORE = ON GO ALTER DATABASE [TESTDB] SET QUERY_STORE (OPERATION_MODE = READ_WRITE, QUERY_CAPTURE_MODE = ALL) GO
実行頻度の低いものは取得しないようにするのであれば、AUTO を指定することができます。
ALTER DATABASE [TESTDB] SET QUERY_STORE = ON GO ALTER DATABASE [TESTDB] SET QUERY_STORE (OPERATION_MODE = READ_WRITE, QUERY_CAPTURE_MODE = AUTO) GO
それでは、実際に比較してみましょう。
処理時間の比較
左がクエリストアを無効にした状態 / 右が有効 (ALL) にした状態です。
数回実行して、結果を比較したのですが、すべてのクエリを取得しようとした場合は、実行時間に差が出るという傾向は変わりませんでした
それでは、クエリストアのキャプチャモードを ALL ではなく、AUTO にするとどうでしょうか。
こちらも右が無効 / 左が AUTO の状態です。
AUTO を使用した場合、実行時間に大きな差はなくなりましたね。
ドキュメントから、クエリストアでは「新しいプランが作成されたタイミング (コンパイル時の初回作成 / 再コンパイル時の新規プラン作成)」の情報が取得されるという仕様が記載されていました。
今回のスクリプトは GUID を使用したアドホックなクエリを実行するようにしています。
つまり、スクリプトを実行するたびに、毎回コンパイルが発生するようなクエリとして実行しているということになります。
クエリストアのモードを「ALL」にしていると、すべてのアドホッククエリの情報を取得しようとしますので、今回のように毎回コンパイルが発生しているようなワークロードでは、クエリストアに取り込まれる情報が多くなるということを示しています。
キャプチャモードに「AUTO」を設定した場合は、一度しか実行されないようなアドホックなクエリはクエリストアには格納しないような動作となります。
これにより、設定を無効にしている場合と同等の処理時間となっているということがわかってきます。
- ALL を設定している場合 : 1 回しか実行されないアドホッククエリが多い場合、処理時間に影響が出てくる可能性がある
- AUTO を設定している場合 : 1 開始か実行されないアドホッククエリが多い場合、処理時間への影響を抑えられる可能性がある
可能性が考えらます。
今回は事前にドキュメントを確認し、「クエリストアでは、どのようなトリガーで情報が取得されるのか？」ということを把握していましたので、毎回コンパイルが発生するワークロードの実行ということを考えることができました。
昨日の検証を行う際には、機能の設定と、特性を考慮してワークロードを作成することで、有益な情報を取得することにつながりますので、「昨日の特性を考慮したワークロードの実行」というのは、機能検証をする際に重要な要素の一つとなります。
まずは、処理時間への影響が数値として確認できました。
パフォーマンスモニターの比較
それでは次にパフォーマンスモニターを使用して、「リソースの使用状況の変化」を見ていきたいと思います。
CPU の使用状況については、差はないですね。
バッチやコンパイルの発生状況についても、同じワークロードを実行していますので大差はありませんでした。
一番の変化点としては、「トランザクションログの書き込み」に差があります。
今回は SELECT のみを実行しているワークロードですので、通常であれば、トランザクションログへの書き込みは発生しません。
しかし、クエリストアを有効にしている場合は、トランザクションログへの書き込みが発生しています。
これについてもドキュメントを確認していると説明がつきます。
クエリストアはプランキャッシュと異なり、メモリ上のみ存在している情報ではなく、ディスクに永続化され、後からクエリの情報を確認することができる機能となります。
このディスクに永続化する際には、通常のトランザクションと同じで、トランザクションログに書き込みを行ってからデータファイルに永続化を行います。
メモリ不足が発生した場合、
DATA_FLUSH_INTERVAL_SECONDSで定義されている時間より前に、ランタイム統計がディスクにフラッシュされる可能性があります。
クエリストアの情報は、メモリに書き込みを行ってから、非同期でディスクに書き込みを行う仕組みですので、ディスク負荷は抑えられるようになっていますが、「どこなのタイミングではディスクに書き込みが行われる」という仕様となっています。
そのため、SELECT しか実行されていないワークロードでも、メモリのデータを非同期でフラッシュするタイミングでは、トランザクションログの書き込み負荷が瞬間的に発生することになります。
そのため、このトランザクションログの書き込みについては多少のオーバーヘッドが発生する可能性があるということがパフォーマンスモニターの情報から確認することができました。
今回は、カウンターが上昇していなかったのでグラフは作成していませんが「SQLServer:Query Store(_Total)\Query Store CPU usage」という項目を確認することで、クエリストアで使用されている CPU の使用時間を確認することもできますので、CPU 使用率が上昇している場合は、このカウンターの情報を確認することで、クエリストアを有効にした際の CPU 使用率を確認することができます。
このパフォーマンスモニターの情報でトランザクションログの書き込みが増えたということが確認できました。
トランザクションログの書き込みは非同期で行われていますので、処理時間に直接影響を与える可能性は低いです。
さらに詳細に調査する場合は DMV の活用を考えていきます。
投稿が長くなってきましたので、DMV の活用は次の機会に書いていきたいと思います。