読者です 読者をやめる 読者になる 読者になる

小物SEのメモ帳

IT関係の試したことや調べたことの備忘録

【PowerShell】【SQL Server】SQLの結果を条件にイベントログに書き込む

完全に自分用の備忘録です。
SQL Serverに対しストアドを作ることなく、SQLの戻り値を使ってイベントログに書き込みをするスクリプトです。

イベントログへの書き込み

事前にイベントログにソースを登録したことがなければNew-Eventlogにて作成しておきます。
今回はTemp_alertとしておきます。

New-Eventlog -LogName Application -Source "Temp_alert"

イベントログへの書き込みはWrite-Eventlogにて行います。

Write-Eventlog -Logname Application -Source Temp_alert -EntryType Information -EventId 9999 -Message "test"

f:id:utiowa:20170428002208p:plain

イベントログに書き込みができていることを確認します。
f:id:utiowa:20170427010715p:plain

PowerShellからのSQLの実行

PowerShellからSQLを実行するので、Invoke-Sqlcmdを使用します。

Invoke-Sqlcmd -ServerInstance $Server -Database $Database -Username $User -Password $Password -InputFile $Input_count 

その他詳しいオプションは下記を参照してください。
https://msdn.microsoft.com/ja-jp/library/cc281720.aspx

今回は単純に数をカウントするだけのSQLと詳細情報を参照する以下クエリを用意しました。

Sqlquery_count.sql

SET NOCOUNT ON

SELECT 
       COUNT([JOB_ID]) AS [Count]
  FROM [dbo].[JOBS]

Sqlquery_detail.sql

SET NOCOUNT ON

SELECT 
      [JOB_ID]
      ,[JOB_TITLE]
      ,[MIN_SALARY]
      ,[MAX_SALARY]
  FROM [dbo].[JOBS]

PowerShellからSQLを実行してイベントログへ書き込み

SQLでのカウントが0の場合は問題ないことをログに書き込み、0でない場合エラーとしてイベントログに書き込むサンプルです。

以下のようなフォルダ構成で実行します。
f:id:utiowa:20170428002334p:plain



$Server = "YUUSUKE-VAIO\INS_NISHI2016"
$Database = "sales"
$User = "sa"
$Password = "system"
$Basepath =  "C:\Users\yuusuke\Desktop\SQLserver\script_test\"
$Input_count = $Basepath + "scripts\Sqlquery_count.sql"
$Input_detail = $Basepath +  "scripts\Sqlquery_detail.sql"
$Output_detail = $Basepath + "output\Sqlquery_detail.log"

$Hostname = hostname
$Log_Level = "ERROR"

$us = New-Object system.globalization.cultureinfo("en-US")
$Date = (Get-date).ToString("yyyy MMM dd HH:mm:ss", $us)
$Message_header = "XXXXX"
$Message_body = "target_count is "

# 対象のカウント
$Resultset = Invoke-Sqlcmd -ServerInstance $Server -Database $Database -Username $User -Password $Password -InputFile $Input_count 

$Message = $Message_header + " " + $Date + " " + $Hostname + " " + $Log_Level + " " + $Message_body + [string]$Resultset['Count']

# 条件に応じてイベントログに出力
if ($Resultset['Count'] -eq 0 ){
  Write-Eventlog -Logname Application -Source Temp_alert -EntryType Information -EventId 9999 -Message $Message
}else{
  $Resultset = Invoke-Sqlcmd -ServerInstance $Server -Database $Database -Username $User -Password $Password -InputFile $Input_detail
  $Resultset | Out-File $Output_detail
  Foreach ($item in $Resultset){
    $items += ',' + $item['JOB_ID']
  }
$Message = $Message + $items
Write-Eventlog -Logname Application -Source Temp_alert -EntryType Warning -EventId 9999 -Message $Message
}

結果は以下のようにイベントログに書き込めていることがわかります。
f:id:utiowa:20170427011005p:plain

本番環境だと申請なしにストアドを作成するわけにもいかないこともありますのでストアドを使わない方法として一時しのぎに使おうかと。

【SQL Server】【Windows】セキュリティイベントログにログイン失敗のログを記録する

イベントログの「セキュリティ」にSQL Serverログインの失敗を記録する際の手順です。

以下参考のURLを実際に実行してみたものになります。
https://msdn.microsoft.com/ja-jp/library/cc645889.aspx


まず、auditpol.exeで成功・失敗の監査を有効にします。
ただし、上記URL記載のコマンドを実行してもエラーとなりますので、一部修正する必要があります。

auditpol.exe /set /subcategory:”Application Generated” /failure:enable /success:enable

f:id:utiowa:20170326001834p:plain


私の環境では、サブカテゴリ名が日本語になっており、コマンド内でも日本語にする必要がありました。

auditpol.exe /set /subcategory:”生成されたアプリケーション” /failure:enable /success:enable

f:id:utiowa:20170326001848p:plain


次に"セキュリティ監査の生成"権限をSQL Serverの起動ユーザに許可します。
「ファイル名を指定して実行」で"gpedit.msc"を入力します。
f:id:utiowa:20170326002046p:plain

ローカル セキュリティ ポリシー ツールで、 [セキュリティの設定]、 [ローカル ポリシー]の順に展開し、 [ユーザー権利の割り当て]をクリックして、右ペインに表示される[セキュリティ監査の生成]をダブルクリックします。
f:id:utiowa:20170326002240p:plain

[ローカル セキュリティの設定] タブの [ユーザーまたはグループの追加]をクリックします。
f:id:utiowa:20170326002306p:plain

追加するユーザアカウントとしてSQL Serverの起動ユーザを選択します。
f:id:utiowa:20170326002311p:plain

設定が完了したらSQL Serverに反映させるためにインスタンスを再起動します。


次にSQL Server側で監査を追加します。監査ログをイベントログのセキュリティに記録するようにします。
今回はSQL Serverインスタンス全体を監査対象とするサーバーレベルの監視を作成してみます。

オブジェクトエクスプローラインスタンス名配下のツリー直下にある「監査」を選択し、右クリック、「新しい監査」を選択します。
f:id:utiowa:20170326002521p:plain

「監査の出力先」をセキュリティログにします。
f:id:utiowa:20170326002533p:plain

尚、監査ログはイベントログのアプリケーション、もしくは別ファイルに記録することもできます。
f:id:utiowa:20170326002549p:plain

作成したら有効化しておきます。
f:id:utiowa:20170326002650p:plain

どのイベントを監査ログとして記録するかという仕様は、"サーバー監査の仕様"にて設定します。

オブジェクトエクスプローラインスタンス名配下のツリー直下にある「サーバー監査の仕様」を選択し、右クリック、「新しいサーバー監査の仕様」を選択します。
f:id:utiowa:20170326002932p:plain

ログイン失敗を監査するために、監査アクションの種類で「FAILED_LOGIN_GROUP」を選択します。f:id:utiowa:20170326003141p:plain

ここでは、他にも以下のように監査仕様を選べます。
f:id:utiowa:20170326003215p:plain

作成が完了したらこちらも有効にしておきます。


実際にログイン失敗が記録されているか確認をしてみます。
監査ログの表示は、SSMS上であれば作成した監査を右クリックして、「監査ログの表示」を選択します。
f:id:utiowa:20170326003457p:plain

ユーザIDの誤りによるログ
f:id:utiowa:20170326004122p:plain

パスワード誤りによるログ
f:id:utiowa:20170326004134p:plain


実際にイベントログを確認してみると次のように記録できていることがわかります。

ユーザIDの誤りによるログ
f:id:utiowa:20170326003645p:plain

パスワード誤りによるログ
f:id:utiowa:20170326003702p:plain


データベースレベルを監査対象とする監査仕様は別途こちらから設定できますので、個別DB毎の監査仕様はこちらで定義するとよいでしょう

f:id:utiowa:20170326002907p:plain

【SQL Server】bcpを使用したインポートとエクスポート

テストする際にテーブルのデータを一括でインポート・エクスポートする場合の方法の一つとしてbcpを使用することがありますが、オプションやフォーマットファイル出力のやり方をよく忘れるので覚書。
フォーマットファイルについては、bcpだけでなくBULK INSERTにも使えます。
bcpコマンドラインからの実行になるので、バッチなどを作っておいて、簡単なテーブルバックアップ用のスクリプトなども作っておくと便利かと思います。

フォーマットファイルの作成

エクスポートやインポートをする対象テーブルのフォーマットファイルを作成します。

Syntax :

bcp table_or_view format nul -c -x -f formatfile.xml -t, -S server_name\instance_name -U login_id -P password -d database_name

Option :

-f format_file
-S server_name [\instance_name]
-U login_id
-P password
-d database_name
-t field_term(default \t)

その他詳しいオプションは下記を参照してください。
https://msdn.microsoft.com/ja-jp/library/ms162802.aspx


実際に使う際は次のようにコマンドプロンプトで実行します。

bcp dbo.EMPLOYEES format nul -c -x -f formatfile.xml -t, -S YUUSUKE-VAIO\INS_NISHI2016 -U sa -P system -d sales

"-f"で指定するフォーマットファイルは、出力先パスとファイル名を記載してください。

f:id:utiowa:20170323192637p:plain

出力されたフォーマットファイルはxml形式となります。
f:id:utiowa:20170323192646p:plain


bcpによる一括エクスポート

先ほど作成したフォーマットファイルを使用してテーブルのデータを全てエクスポートします。

bcp dbo.EMPLOYEES out .\EMPLOYEES.csv -S YUUSUKE-VAIO\INS_NISHI2016 -U sa -P system -d sales -f .\formatfile.xml -t, -o .\EMPLOYEES_output.log

"-o"によって出力されるのは処理ログで、"out"によって指定されたパスにエクスポート結果が出力されます。
"-f"で指定するフォーマットファイルは格納先を指定してください。

処理ログ
f:id:utiowa:20170323192807p:plain

エクスポート結果(ヘッダーはつけられません)
f:id:utiowa:20170323192752p:plain

テーブルを指定するのではなく、SQLとqueryoutを使用して出力対象をいじることも可能です。
WHERE句を使って条件に合うデータのみ抽出する等に使えるかと。

bcp "SELECT TOP(10) * FROM dbo.EMPLOYEES" queryout .\EMPLOYEES_TOP10.csv -S YUUSUKE-VAIO\INS_NISHI2016 -U sa -P system -d sales -f .\formatfile.xml -t, -o .\EMPLOYEES_TOP10_output.log

f:id:utiowa:20170323192825p:plain

bcpによる一括インポート

作成したフォーマットファイルを使用して、データファイルをテーブルに全てインポートできます。
"-i"で指定するインポート用のデータファイルは、格納パスとファイル名を指定してください。

bcp dbo.EMPLOYEES in .\EMPLOYEES.csv -S YUUSUKE-VAIO\INS_NISHI2016 -U sa -P system -d sales -f .\formatfile.xml -t, -o .\EMPLOYEES_input.log

処理ログ
f:id:utiowa:20170323193651p:plain

【参考】
https://msdn.microsoft.com/ja-jp/library/aa337544.aspx

【SQL Server】クエリの実行プランとパフォーマンス情報の取得方法Part2

前回に引き続き実行プランとパフォーマンス情報の取得について説明します。今回はトレースとデータ蓄積による情報取得です。
前回記事はこちらを参照して下さい。
memorandom-nishi.hatenablog.jp

3.トレースして取得する

トレースを仕掛けて詳細情報を取得する方法は2つあります。
ただし後述するSQLプロファイラーは非常にトレース負荷が高く本番環境で使用することは皆無かと思います。
使用する場合は、ブラックボックスで内部でどのようなSQLが実行されているかわからないものを確認したり、そのSQL実行開始のコンパイルからロック状況など実行状況を一連の流れで確認するなどに使えますが、基本的には拡張イベントで事足りるでしょう。
拡張イベントもSQLプロファイラーに比べ軽量とはいえ、負荷がかかることに変わりはないため、使用の際は注意してください。

拡張イベント(XEvent)

拡張イベントを設定することで、3種類の実行プランをとることができます。特に下記③query_post_execution_showplanは、前回記事で説明したSET STATISTICS XML相当の実際の実行プランであるため、有益な情報になるかと思います。

設定手順は以下のとおりです。

オブジェクトエクスプローラーの「管理」-「拡張イベント」-「セッション」で右クリックを押下し、「新規セッションウィザード」を選択します。
f:id:utiowa:20170321011932p:plain

作成する拡張イベントのセッションに名前を付けます。今回はテンプレートなしで作成します。
f:id:utiowa:20170321012135p:plain
f:id:utiowa:20170321012138p:plain

取得したい実行プランのイベントを選択します。
f:id:utiowa:20170321012231p:plain
f:id:utiowa:20170321012317p:plain

選択したイベントでトレース対象をフィルタすることも可能です。
f:id:utiowa:20170321012410p:plain

作成が完了したら、オブジェクトエクスプローラーの「管理」-「セッション」に追加されていることを確認します。
f:id:utiowa:20170321012525p:plain

パフォーマンス情報によって取得するものを絞る場合は次のように追加でフィルタします。
f:id:utiowa:20170321012637p:plain
f:id:utiowa:20170321012643p:plain
f:id:utiowa:20170321012629p:plain
f:id:utiowa:20170321012632p:plain


準備ができたらセッションを開始します。
f:id:utiowa:20170321012714p:plain

今回はリアルタイムで監視したいため、「ライブデータの監視」を選択します。
f:id:utiowa:20170321012831p:plain

データが採取できたらセッションを停止します。
f:id:utiowa:20170321012925p:plain

結果以下のようにパフォーマンス情報と実行プランが取得できていることが確認できます。
f:id:utiowa:20170321013001p:plain


①クエリコンパイル後・クエリ実行前の推定の実行プラン(query_post_compilation_showplan)
f:id:utiowa:20170321013055p:plain

②クエリコンパイル後・クエリ最適化時(実行時)の推定の実行プラン(query_pre_execution_showplan)
f:id:utiowa:20170321013104p:plain

③クエリ実行後の実際の実行プラン(query_post_execution_showplan)
f:id:utiowa:20170321013113p:plain
f:id:utiowa:20170321013118p:plain


また、拡張イベントで取得できるイベントは、以下で確認できるので一度どのようなものが取得できるかざっと確認しておくとよいでしょう。

SELECT * FROM sys.dm_xe_objects
SQL Server Profiler

SQL Serverプロファイラーではプロファイラーを実行してから終了するまで指定したイベントをトレースできます。
非常に負荷が高いためあまり実用的ではありませんが、開発環境等で詳細情報を取得する場合等に使えないこともありません。

使い方としては以下のとおりです。

SQL Server Profilerを起動します。
f:id:utiowa:20170321013357p:plain

認証して、トレースのプロパティを開きます。
f:id:utiowa:20170321014853p:plain

「イベントの選択」タブで、「すべてのイベントを表示する」にチェックをいれます。
f:id:utiowa:20170321014914p:plain
f:id:utiowa:20170321014918p:plain


Events列のPerformanceをクリックします。
f:id:utiowa:20170321014935p:plain


取得する実行プランを選びます。
f:id:utiowa:20170321014945p:plain

「列フィルター」にてトレースする対象をフィルタすることができます。
f:id:utiowa:20170321014955p:plain
f:id:utiowa:20170321014956p:plain


実行すると対象のイベントについてトレースを開始します。
f:id:utiowa:20170321015016p:plain

以下のようにパフォーマンス情報と実行プランが取得できていることが確認できます。

クエリコンパイル後の推定の実行プラン(Showplan ALL For Query Cimpile、Showplan XML For Query Cimpile)
Showplan ALL For Query Cimpile
f:id:utiowa:20170321015031p:plain

Showplan XML For Query Cimpile
f:id:utiowa:20170321015042p:plain

クエリコンパイル後、クエリ実行前の推定の実行プラン(Showplan ALL、Showplan TEXT、Showplan XML
Showplan XML
f:id:utiowa:20170321015052p:plain

実際の実行プラン(Showplan Statistics Profile、Showplan XML Statistics Profile)

Showplan Statistics Profile
f:id:utiowa:20170321015104p:plain

Showplan XML Statistics Profile
f:id:utiowa:20170321015116p:plain

4.データを蓄積して分析する

データを蓄積していくことで変化や傾向を分析する方法は、大きく分けてシステムデータコレクション(MDW)とクエリストアが有用かと思います。

システムデータコレクション(MDW)

システムデータコレクション(以下MDW)については過去記事で確認方法を説明していますので、こちらを参照してください。
MDWでは、クエリの実行プランやパフォーマンス情報に合わせて、当該クエリの待機イベントの状況やブロッキングの情報などが確認できるため、チューニングの際にボトルネックの発見がしやすくなります。OracleのStatspackに似ているかと思います。
memorandom-nishi.hatenablog.jp

クエリストア

こちらも過去記事でざっと説明していますので参照して頂ければと思います。
SQLServer2016からしか使用できませんが、クエリストアを使うことでクエリの急な遅延等のパフォーマンス変化時の分析に役立つかと思います。
memorandom-nishi.hatenablog.jp

【SQL Server】クエリの実行プランとパフォーマンス情報の取得方法Part1

クエリのパフォーマンス状態の分析において、必ずといってよいほど必要となる実行プランやCPU時間や実行時間、実行回数などの取得方法について、いくつか方法がありますのでまとめます。

大きく分けて以下のような方法で取得できます。

1.動的管理ビューで取得する

これは、実際に実行済みでかつキャッシュ上に残存している場合に取得できます。本番環境などで余計な負荷をかけずに取得できる方法かと思います。
ただし、キャッシュされていない実行プランはもちろん取得できないことになります。

クエリでDMV組み合わせて取得する

例として、CPU負荷が高いTOP100のSQLで、CPUtimeや実行時間、実行回数も同時に取得するクエリです。

USE master
GO
SET NOCOUNT ON
GO

SELECT TOP 100
        rank() over(order by total_worker_time desc,sql_handle,statement_start_offset) AS [row_no]
,       db_name(st.dbid) AS [database_name]
,       creation_time
,       last_execution_time
,       (total_worker_time+0.0)/1000 AS [total_worker_time(ms)]
,       (total_worker_time+0.0)/(execution_count*1000) AS [AvgCPUTime(ms)]
,       (total_elapsed_time+0.0)/1000 AS [total_elapsed_time(ms)]
,       (total_elapsed_time+0.0)/(execution_count*1000) AS [AvgElapsedTime(ms)]
,       total_logical_reads AS [LogicalReads(page)]
,       total_logical_writes AS [logicalWrites(page)]
,       total_logical_reads+total_logical_writes AS [AggIO(page)]
,       (total_logical_reads+total_logical_writes)/(execution_count + 0.0) AS [AvgIO(page)]
,       execution_count
,       total_rows
,       st.text AS [batch_query_text]
,   CASE 
            WHEN sql_handle IS NULL
            THEN ' '
            ELSE ( SUBSTRING(st.text,(qs.statement_start_offset+2)/2,(CASE 
                                                                          WHEN qs.statement_end_offset = -1        
                                                                          THEN LEN(CONVERT(NVARCHAR(MAX),st.text))*2      
                                                                          ELSE qs.statement_end_offset    
                                                                      END 
            - qs.statement_start_offset) /2  ) )
    END AS [statement_query_text] 
,       plan_generation_num
,       qp.query_plan
FROM sys.dm_exec_query_stats   AS [qs]
CROSS APPLY sys.dm_exec_sql_text(sql_handle) AS [st]
CROSS APPLY sys.dm_exec_query_plan(plan_handle) AS [qp]
WHERE total_worker_time > 0 
ORDER BY total_worker_time  DESC
OPTION (RECOMPILE)

f:id:utiowa:20170319040949p:plain
f:id:utiowa:20170319041329p:plain

また、実行プランなしでCPU時間や実行時間等が知りたい場合、上記クエリのほかにレポートに出力も可能ですので、下記記事をご確認ください。
memorandom-nishi.hatenablog.jp

利用状況モニターから取得する

実際に現在実行されているものや比較的負荷が高いものが対象にあります。DMVで取得するものを利用状況モニターから取得しているだけですので、こちらも過去記事をご確認いただければと思います。
f:id:utiowa:20170319035855p:plain
memorandom-nishi.hatenablog.jp

2.実行時にSET~を使用する

この場合、これから実行しようとするクエリの推定プラン(実行自体はしない)や実際の実行したクエリが取得できます。

推定の実行プランを取得する

SET SHOWPLAN_xx で取得する場合、クエリ自体は実行せずに推測の実行プランを確認することができます。
グラフィカルな実行プランで確認したい場合は次のように確認します。

SET SHOWPLAN_XML ON
GO
SELECT * 
	FROM		dbo.EMPLOYEES		AS [EMP]
	INNER JOIN 	dbo.DEPARTMENTS		AS [DEPA]
	ON		[EMP].MANAGER_ID = [DEPA].MANAGER_ID	
SET SHOWPLAN_XML OFF
GO

f:id:utiowa:20170319035918p:plain
f:id:utiowa:20170319035937p:plain

また、クエリ実行時にSSMSの「推定実行プランの表示」をクリックしても同様の結果が取得できます。
f:id:utiowa:20170319035932p:plain

グラフィカルな実行プランの場合、各アイコンやノードにマウスカーソルを合わせると詳細情報として、CPU・IOのコストや予測行数などを確認できます。
SSMSがインストールされている環境であれば視覚的に確認できてよいかと思います。
f:id:utiowa:20170319040005p:plain
f:id:utiowa:20170319040013p:plain


テキスト形式で実行プランを取得したい場合、実行プランのみ取得するものと、詳細情報も併せて取得するものの2パターンあります。

実行プランのみ取得する場合は次のように実行します。

SET SHOWPLAN_TEXT ON
GO

--実行プランを取得したいクエリ
SELECT * 
	FROM		dbo.EMPLOYEES	AS [EMP]
	INNER JOIN 	dbo.DEPARTMENTS	AS [DEPA]
	ON       [EMP].MANAGER_ID = [DEPA].MANAGER_ID	
GO

SET SHOWPLAN_TEXT OFF
GO

f:id:utiowa:20170319040120p:plain

実行プランと詳細情報の場合は次のように実行します。

SET SHOWPLAN_ALL ON
GO

--実行プランを取得したいクエリ
SELECT * 
	FROM		dbo.EMPLOYEES	AS [EMP]
	INNER JOIN 	dbo.DEPARTMENTS	AS [DEPA]
	ON       [EMP].MANAGER_ID = [DEPA].MANAGER_ID
GO

SET SHOWPLAN_ALL OFF
GO

f:id:utiowa:20170319040150p:plain

情報としては上記グラフィカルな実行プランではマウスカーソルにて確認できる情報がまとめて確認できるような形となります。テキスト形式で保存すれば、環境に依存せず他人と情報を共有できて便利かと思います。

実際の実行プランを取得する

SET STATISTICS xx で取得する場合、クエリ自体は実行して実際の実行プランを確認することができます。
クエリを実際に実行してしまうため、本番環境での使用は十分注意が必要ですが、その分予測行数と実際の行数など実行時の情報が確認できるため非常に有効な情報となります。

グラフィカルな実際の実行プランで確認したい場合は次のように確認します。

SET STATISTICS XML ON

--実行プランを取得したいクエリ
SELECT * 
	FROM		dbo.EMPLOYEES	AS [EMP]
	INNER JOIN 	dbo.DEPARTMENTS	AS [DEPA]
	ON       [EMP].MANAGER_ID = [DEPA].MANAGER_ID
GO

SET STATISTICS XML OFF

f:id:utiowa:20170319040224p:plain
f:id:utiowa:20170319040229p:plain

推定の実行プランと比較すると、各アイコンやノードにマウスカーソルを合わせた際に実際の行数や実行回数などが追加で取得できていることが確認できます。

f:id:utiowa:20170319040244p:plain
f:id:utiowa:20170319040248p:plain


テキスト形式で実際の実行プランで確認したい場合は次のように確認します。

SET STATISTICS PROFILE ON

--実行プランを取得したいクエリ
SELECT * 
	FROM		dbo.EMPLOYEES	AS [EMP]
	INNER JOIN 	dbo.DEPARTMENTS	AS [DEPA]
	ON       [EMP].MANAGER_ID = [DEPA].MANAGER_ID
GO

SET STATISTICS PROFILE OFF

f:id:utiowa:20170319040314p:plain
こちらも推定の実行プランに比べ、実際の行数や実行回数が追加されていることがわかるかと思います。


また、実行プランの取得ではありませんが、実行して分析する際には次のようにクエリがどのページを読み取ったかや構文解析時間、クエリ実行時間も合わせて取得しておくと解析時に便利かと思います。

SET STATISTICS IO ON
SET STATISTICS TIME ON

	--実行プランを取得したいクエリ
	SELECT * 
		FROM		dbo.EMPLOYEES		AS [EMP]
		INNER JOIN 	dbo.DEPARTMENTS		AS [DEPA]
		ON		[EMP].MANAGER_ID = [DEPA].MANAGER_ID	
	GO

SET STATISTICS TIME OFF
SET STATISTICS IO OFF

f:id:utiowa:20170321010011p:plain
f:id:utiowa:20170321010017p:plain


上記のほかにトレースして実行計画やパフォーマンス情報を確認する方法はありますが、それは次回記載します。

【SQL Server】CPU使用率、IO負荷の高いクエリレポート

クエリのパフォーマンス状況の確認方法として、DMVを組み合わせた「CPU使用率の高いクエリ」や「IO負荷の高いクエリ」を取得するクエリを事前に準備しているシステム管理者も多いかと思いますが、グラフィカルなレポートという形で取得するのも視覚的に確認できてよいかと思いますので、出力方法の説明です。
※デメリットとして、レポート出力ではSQLハンドルは出力できているものの、実行プランは別途取得する必要があります。

特に次のレポートは比較的利用価値が高いのではないでしょうか。
「パフォーマンス - バッチ実行の統計」
「パフォーマンス - 平均IO数ごとの上位のクエリ」
「パフォーマンス - IOの総数ごとの上位のクエリ」
「パフォーマンス - CPUの平均時間ごとの上位のクエリ」
「パフォーマンス - CPUの総時間ごとの上位のクエリ」

尚、これらのレポートは出力時に裏でSQLを実行し、動的管理ビューからデータ取得をしていますので、キャッシュ上に残存しているデータのみがレポート対象となります。

レポート出力の手順

左ペインの「オブジェクト エクスプローラー」のインスタンス名を選択し右クリック、「レポート(P)」-「標準レポート」を押下して、表示したいグラフをクリックします。
f:id:utiowa:20170314002607p:plain

レポート内容

①「パフォーマンス - バッチ実行の統計」
f:id:utiowa:20170314002619p:plain

これはバッチごとの平均・総CPU、論理読み取り数、論理書き込み数についてのレポートになります。

f:id:utiowa:20170314002630p:plain
平均はすべてデフォルト表示で、それぞれのプラス表示をクリックするとトータルの取得値が確認できます。

キャッシュ上に残存しているデータのうち、バッチ単位で高負荷なものを確認することができます。
またバッチ番号のプラス表示をクリックするとステートメント毎の情報が確認できます。

実際に裏でレポート表示に使われているクエリは次のようなものになります。

exec sp_executesql @stmt=N'begin try 
declare @dbid int; 
set @dbid = db_id(); 
declare @cnt int;  
declare @record_count int; 
declare @sql_handle varbinary(64);  
declare @sql_handle_string varchar(130); 
declare @grand_total_worker_time float ; 
declare @grand_total_IO float ; 
declare @sql_handle_convert_table table(
        row_id int identity 
,       t_sql_handle varbinary(64)
,       t_display_option varchar(140) collate database_default
,       t_display_optionIO varchar(140) collate database_default
,       t_sql_handle_text varchar(140) collate database_default
,       t_SPRank int
,   t_SPRank2 int
,       t_SQLStatement varchar(max) collate database_default
,       t_execution_count int 
,       t_plan_generation_num int
,       t_last_execution_time datetime
,       t_avg_worker_time float
,       t_total_worker_time bigint
,       t_last_worker_time bigint
,       t_min_worker_time bigint
,       t_max_worker_time bigint 
,       t_avg_logical_reads float
,       t_total_logical_reads bigint
,       t_last_logical_reads bigint
,       t_min_logical_reads bigint 
,       t_max_logical_reads bigint
,       t_avg_logical_writes float
,       t_total_logical_writes bigint
,       t_last_logical_writes bigint
,       t_min_logical_writes bigint
,       t_max_logical_writes bigint
,       t_avg_IO float
,       t_total_IO bigint
,       t_last_IO bigint
,       t_min_IO bigint
,       t_max_IO bigint
);
declare @objects table (
        obj_rank int
,       total_cpu bigint 
,       total_reads bigint
,       total_writes bigint
,       total_io bigint
,       avg_cpu bigint 
,       avg_reads bigint
,       avg_writes bigint
,       avg_io bigint
,       cpu_rank int
,       total_cpu_rank int
,       read_rank int
,       write_rank int
,       io_rank int
); 

insert into @sql_handle_convert_table 
Select  sql_handle
,       sql_handle as chart_display_option 
,       sql_handle as chart_display_optionIO 
,       master.dbo.fn_varbintohexstr(sql_handle)
,       dense_rank() over (order by s1.sql_handle) as SPRank 
,       dense_rank() over (partition by s1.sql_handle order by s1.statement_start_offset) as SPRank2
,       (select top 1 substring(text,(s1.statement_start_offset+2)/2, (case when s1.statement_end_offset = -1  then len(convert(nvarchar(max),text))*2 else s1.statement_end_offset end - s1.statement_start_offset) /2  ) from sys.dm_exec_sql_text(s1.sql_handle)) as [SQL Statement]
,       execution_count
,       plan_generation_num
,       last_execution_time
,       ((total_worker_time+0.0)/execution_count)/1000 as [avg_worker_time]
,       total_worker_time/1000
,       last_worker_time/1000
,       min_worker_time/1000
,       max_worker_time/1000
,       ((total_logical_reads+0.0)/execution_count) as [avg_logical_reads]
,       total_logical_reads
,       last_logical_reads
,       min_logical_reads
,       max_logical_reads
,       ((total_logical_writes+0.0)/execution_count) as [avg_logical_writes]
,       total_logical_writes
,       last_logical_writes
,       min_logical_writes
,       max_logical_writes
,       ((total_logical_writes+0.0)/execution_count + (total_logical_reads+0.0)/execution_count) as [avg_IO]
,       total_logical_writes + total_logical_reads
,       last_logical_writes +last_logical_reads
,       min_logical_writes +min_logical_reads
,       max_logical_writes + max_logical_reads  
from    sys.dm_exec_query_stats s1 
cross apply sys.dm_exec_sql_text(sql_handle) as  s2 
where s2.objectid is null
order by  s1.sql_handle; 

select @grand_total_worker_time = sum(t_total_worker_time) 
,       @grand_total_IO = sum(t_total_logical_reads + t_total_logical_writes)  
from @sql_handle_convert_table; 

select @grand_total_worker_time = case when @grand_total_worker_time > 0 then @grand_total_worker_time else 1.0 end  ; 
select @grand_total_IO = case when @grand_total_IO > 0 then @grand_total_IO else 1.0 end  ; 

Insert into @objects  
select t_SPRank
,       sum(t_total_worker_time)
,       sum(t_total_logical_reads)
,       sum(t_total_logical_writes)
,       sum(t_total_IO)
,       sum(t_avg_worker_time) as avg_cpu
,       sum(t_avg_logical_reads)
,       sum(t_avg_logical_writes)
,       sum(t_avg_IO)
,       rank() over(order by sum(t_avg_worker_time) desc)
,       row_number() over(order by sum(t_total_worker_time) desc)
,       row_number() over(order by sum(t_avg_logical_reads) desc)
,       row_number() over(order by sum(t_avg_logical_writes) desc)
,       row_number() over(order by sum(t_total_IO) desc) 
from @sql_handle_convert_table 
group by t_SPRank ; 

update @sql_handle_convert_table set t_display_option = ''show_total'' 
where t_SPRank in (select obj_rank from @objects where (total_cpu+0.0)/@grand_total_worker_time < 0.05) ; 

update @sql_handle_convert_table set t_display_option = t_sql_handle_text 
where t_SPRank in (select obj_rank from @objects where total_cpu_rank <= 5) ; 

update @sql_handle_convert_table set t_display_option = ''show_total'' 
where t_SPRank in (select obj_rank from @objects where (total_cpu+0.0)/@grand_total_worker_time < 0.005); 

update @sql_handle_convert_table set t_display_optionIO = ''show_total'' 
where t_SPRank in (select obj_rank from @objects where (total_io+0.0)/@grand_total_IO < 0.05); 

update @sql_handle_convert_table set t_display_optionIO = t_sql_handle_text 
where t_SPRank in (select obj_rank from @objects where io_rank <= 5) ; 

update @sql_handle_convert_table set t_display_optionIO = ''show_total''  
where t_SPRank in (select obj_rank from @objects where (total_io+0.0)/@grand_total_IO < 0.005); 

select (s.t_SPRank)%2 as l1
,       (dense_rank() over(order by s.t_SPRank,s.row_id))%2 as l2
,       s.*
,       ob.cpu_rank as t_CPURank 
,       ob.read_rank as t_ReadRank 
,       ob.write_rank as t_WriteRank  
from @sql_handle_convert_table  s join @objects ob on (s.t_SPRank = ob.obj_rank)
end try
begin catch
select -100 as l1
,       ERROR_NUMBER() as l2
,       ERROR_SEVERITY() as row_id
,       ERROR_STATE() as t_sql_handle
,       ERROR_MESSAGE() as t_display_option
,       1 as t_display_optionIO ,       1 as t_sql_handle_text ,        1 as t_SPRank ,     1 as t_SPRank2 ,    1 as t_SQLStatement ,           1 as t_execution_count  ,       1 as t_plan_generation_num ,    1 as t_last_execution_time ,            1 as t_avg_worker_time ,        1 as t_total_worker_time ,      1 as t_last_worker_time ,       1 as t_min_worker_time ,        1 as t_max_worker_time ,        1 as 
t_avg_logical_reads ,      1 as t_total_logical_reads ,    1 as t_last_logical_reads ,     1 as t_min_logical_reads ,      1 as t_max_logical_reads ,      1 as t_avg_logical_writes ,     1 as t_total_logical_writes ,   1 as t_last_logical_writes ,    1 as t_min_logical_writes ,     1 as t_max_logical_writes ,     1 as t_avg_IO , 1 as t_total_IO ,       1 as t_last_IO ,        1 as t_min_IO ,    1 as t_max_IO,    1 as t_CPURank,    1 as t_ReadRank,    1 as t_WriteRank
end catch',@params=N''


ちなみにSQLserverでは、複数ステートメントのまとまりをバッチと呼びます。(ステートメントは単一のクエリのことです。)

例えば、以下のようなものがあった場合は、

SELECT ~
UPDATE ~
GO

SELECT、UPDATEはそれぞれ1ステートメントで、SELECTからGOまでのひとかたまりが1バッチとなります。


②「パフォーマンス - 平均IO数ごとの上位のクエリ」
f:id:utiowa:20170314002710p:plain

これはキャッシュ上に残存するクエリのうち、1回あたりのIO数が多い上位クエリについてのレポートになります。
レポート上には同クエリについてそれぞれIOの総数で見た場合の負荷を同時に見ることができ便利です。
平均IO数が多いが、総IO数があまり多くない場合、全体への負荷は高くないが、単一クエリとしては高負荷である場合がありますので、非効率なクエリ(インデックスが不足しているなど)でないか注意が必要かと思います。

実際に裏でレポート表示に使われているクエリは次のようなものになります。

exec sp_executesql @stmt=N'begin try
select top 10 rank() over (order by (total_logical_reads+total_logical_writes)/(execution_count+0.0) desc,sql_handle,statement_start_offset ) as row_no
,       (rank() over (order by (total_logical_reads+total_logical_writes)/(execution_count+0.0) desc,sql_handle,statement_start_offset ))%2 as l1
,       creation_time
,       last_execution_time
,       (total_worker_time+0.0)/1000 as total_worker_time
,       (total_worker_time+0.0)/(execution_count*1000) as [AvgCPUTime]
,       total_logical_reads as [LogicalReads]
,       total_logical_writes as [LogicalWrites]
,       execution_count
,       total_logical_reads+total_logical_writes as [AggIO]
,       (total_logical_reads+total_logical_writes+0.0)/execution_count as [AvgIO]
,       case when sql_handle IS NULL
                then '' ''
                else ( substring(st.text,(qs.statement_start_offset+2)/2,(case when qs.statement_end_offset = -1        then len(convert(nvarchar(MAX),st.text))*2      else qs.statement_end_offset    end - qs.statement_start_offset) /2  ))
        end as query_text 
,       db_name(st.dbid) as database_name
,       st.objectid as object_id
from sys.dm_exec_query_stats  qs
cross apply sys.dm_exec_sql_text(sql_handle) st
where (total_logical_reads+total_logical_writes ) > 0
order by [AvgIO] desc
end try
begin catch
select -100 AS row_no
,       1 AS l1, 1 AS creation_time, 1 AS last_execution_time,  1 AS total_worker_time,  1 AS AvgCPUTime, 1 AS logicalReads,  1 AS LogicalWrites
,       ERROR_NUMBER() AS execution_count
,       ERROR_SEVERITY() AS AggIO
,       ERROR_STATE() AS AvgIO
,       ERROR_MESSAGE() AS query_text 
end catch',@params=N''


レポート形式ではなく、同様の情報と同時に実行プランも取得したい場合は次のとおり。

select top 10 rank() over (order by (total_logical_reads+total_logical_writes)/(execution_count+0.0) desc,sql_handle,statement_start_offset ) as row_no
,       (rank() over (order by (total_logical_reads+total_logical_writes)/(execution_count+0.0) desc,sql_handle,statement_start_offset ))%2 as l1
,       creation_time
,       last_execution_time
,       (total_worker_time+0.0)/1000 as total_worker_time
,       (total_worker_time+0.0)/(execution_count*1000) as [AvgCPUTime]
,       total_logical_reads as [LogicalReads]
,       total_logical_writes as [LogicalWrites]
,       execution_count
,       total_logical_reads+total_logical_writes as [AggIO]
,       (total_logical_reads+total_logical_writes+0.0)/execution_count as [AvgIO]
,       case when sql_handle IS NULL
                then ' '
                else ( substring(st.text,(qs.statement_start_offset+2)/2,(case when qs.statement_end_offset = -1        then len(convert(nvarchar(MAX),st.text))*2      else qs.statement_end_offset    end - qs.statement_start_offset) /2  ))
        end as query_text 
,       db_name(st.dbid) as database_name
,       st.objectid as object_id
,		qs.sql_handle
,		qp.query_plan
from sys.dm_exec_query_stats  qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle) st
CROSS APPLY sys.dm_exec_query_plan(plan_handle) qp
where (total_logical_reads+total_logical_writes ) > 0
order by [AvgIO] desc


③「パフォーマンス - IOの総数ごとの上位のクエリ」
f:id:utiowa:20170314002954p:plain

これはキャッシュ上に残存するクエリのうち、IOの総数が多い上位クエリについてのレポートになります。
上記②と同様にそれぞれ平均IO数がどの程度か確認することができます。総IO数が多く、かつ平均IO数も多い場合は、チューニングすると全体に対し大きな効果が得られますので、ここからチューニング対象を見ていくとよいかと思います。

実際に裏でレポート表示に使われているクエリは次のようなものになります。
見ての通り、②のレポートで実行しているものを総IO数にてソートしたものと同様になります。

exec sp_executesql @stmt=N'begin try
select top 10 rank() over (order by total_logical_reads+total_logical_writes desc,sql_handle,statement_start_offset ) as row_no
,       (rank() over (order by total_logical_reads+total_logical_writes desc,sql_handle,statement_start_offset ))%2 as l1
,       creation_time
,       last_execution_time
,       (total_worker_time+0.0)/1000 as total_worker_time
,       (total_worker_time+0.0)/(execution_count*1000) as [AvgCPUTime]
,       total_logical_reads as [LogicalReads]
,       total_logical_writes as [LogicalWrites]
,       execution_count
,       total_logical_reads+total_logical_writes as [AggIO]
,       (total_logical_reads+total_logical_writes)/(execution_count+0.0) as [AvgIO]
,       case when sql_handle IS NULL
                then '' ''
                else ( substring(st.text,(qs.statement_start_offset+2)/2,(case when qs.statement_end_offset = -1        then len(convert(nvarchar(MAX),st.text))*2      else qs.statement_end_offset    end - qs.statement_start_offset) /2  ) )
        end as query_text 
,       db_name(st.dbid) as database_name
,       st.objectid as object_id
from sys.dm_exec_query_stats  qs
cross apply sys.dm_exec_sql_text(sql_handle) st
where total_logical_reads+total_logical_writes > 0 
order by [AggIO]  desc
end try
begin catch
select -100 AS row_no
,       1 AS l1, 1 AS creation_time, 1 AS last_execution_time,  1 AS total_worker_time,  1 AS Avg_CPU_Time, 1 AS logicalReads,  1 AS LogicalWrites
,       ERROR_NUMBER() AS execution_count
,       ERROR_SEVERITY() AS AggIO
,       ERROR_STATE() AS AvgIO
,       ERROR_MESSAGE() AS query_text 
end catch',@params=N''

よって、レポート形式ではなく、同様の情報と同時に実行プランも取得したい場合は次のとおり。

select top 10 rank() over (order by total_logical_reads+total_logical_writes desc,sql_handle,statement_start_offset ) as row_no
,       (rank() over (order by total_logical_reads+total_logical_writes desc,sql_handle,statement_start_offset ))%2 as l1
,       creation_time
,       last_execution_time
,       (total_worker_time+0.0)/1000 as total_worker_time
,       (total_worker_time+0.0)/(execution_count*1000) as [AvgCPUTime]
,       total_logical_reads as [LogicalReads]
,       total_logical_writes as [LogicalWrites]
,       execution_count
,       total_logical_reads+total_logical_writes as [AggIO]
,       (total_logical_reads+total_logical_writes)/(execution_count+0.0) as [AvgIO]
,       case when sql_handle IS NULL
                then ' '
                else ( substring(st.text,(qs.statement_start_offset+2)/2,(case when qs.statement_end_offset = -1        then len(convert(nvarchar(MAX),st.text))*2      else qs.statement_end_offset    end - qs.statement_start_offset) /2  ) )
        end as query_text 
,       db_name(st.dbid) as database_name
,       st.objectid as object_id
,		qs.sql_handle
,		qp.query_plan
from sys.dm_exec_query_stats  qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle) st
CROSS APPLY sys.dm_exec_query_plan(plan_handle) qp
where total_logical_reads+total_logical_writes > 0 
order by [AggIO]  desc


④「パフォーマンス - CPUの平均時間ごとの上位のクエリ」
f:id:utiowa:20170314002744p:plain

これはキャッシュ上に残存するクエリのうち、1回あたりのCPU使用量が多い上位クエリについてのレポートになります。
レポート上には同クエリについてそれぞれCPU使用量の総時間で見た場合の負荷を同時に見ることができます。
②と同様に、平均使用時間に比べて総時間が多くない場合は、単一クエリとしてはCPUに対し高負荷である場合がありますので、非効率なクエリでないか注意が必要かと思います。

実際に裏でレポート表示に使われているクエリは②のレポートで実行しているものを平均CPU時間にてソートしたものと同様になります。
よって、レポート形式ではなく、同様の情報と同時に実行プランも取得したい場合は次のとおり。

select top 10 rank() over(order by (total_worker_time+0.0)/execution_count desc,sql_handle,statement_start_offset ) as row_no
,       (rank() over(order by (total_worker_time+0.0)/execution_count desc,sql_handle,statement_start_offset ))%2 as l1
,       creation_time
,       last_execution_time 
,       (total_worker_time+0.0)/1000 as total_worker_time
,       (total_worker_time+0.0)/(execution_count*1000) as [AvgCPUTime]
,       total_logical_reads as [LogicalReads]
,       total_logical_writes as [LogicalWrites]
,       execution_count
,       total_logical_reads+total_logical_writes as [AggIO]
,       (total_logical_reads+total_logical_writes)/(execution_count+0.0) as [AvgIO]
,       case when sql_handle IS NULL
                then ' '
                else ( substring(st.text,(qs.statement_start_offset+2)/2,       (case when qs.statement_end_offset = -1         then len(convert(nvarchar(MAX),st.text))*2      else qs.statement_end_offset    end - qs.statement_start_offset) /2  ) )
        end as query_text 
,       db_name(st.dbid) as db_name
,       st.objectid as object_id
,		qs.sql_handle
,		qp.query_plan
from sys.dm_exec_query_stats  qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle) st
CROSS APPLY sys.dm_exec_query_plan(plan_handle) qp
where total_worker_time  > 0 
order by [AvgCPUTime] desc

⑤「パフォーマンス - CPUの総時間ごとの上位のクエリ」
f:id:utiowa:20170314002800p:plain

これはキャッシュ上に残存するクエリのうち、総CPU使用量が多い上位クエリについてのレポートになります。
レポート上には同クエリについてそれぞれ平均CPU使用時間で見た場合の負荷を同時に見ることができます。
③と同様に、総時間が長く、かつ平均使用時間も長い場合、チューニングすると全体のCPU使用効率に対し大きな効果が得られますので、チューニング可否を検討するとよいかと思います。

実際に裏でレポート表示に使われているクエリは②のレポートで実行しているものを総CPU時間にてソートしたものと同様になります。
よって、レポート形式ではなく、同様の情報と同時に実行プランも取得したい場合は次のとおり。

select top 10 rank() over(order by total_worker_time desc,sql_handle,statement_start_offset) as row_no
,       (rank() over(order by total_worker_time desc,sql_handle,statement_start_offset))%2 as l1
,       creation_time
,       last_execution_time
,       (total_worker_time+0.0)/1000 as total_worker_time
,       (total_worker_time+0.0)/(execution_count*1000) as [AvgCPUTime]
,       total_logical_reads as [LogicalReads]
,       total_logical_writes as [logicalWrites]
,       execution_count
,       total_logical_reads+total_logical_writes as [AggIO]
,       (total_logical_reads+total_logical_writes)/(execution_count + 0.0) as [AvgIO]
,   case when sql_handle IS NULL
                then ' '
                else ( substring(st.text,(qs.statement_start_offset+2)/2,(case when qs.statement_end_offset = -1        then len(convert(nvarchar(MAX),st.text))*2      else qs.statement_end_offset    end - qs.statement_start_offset) /2  ) )
        end as query_text 
,       db_name(st.dbid) as database_name
,       st.objectid as object_id
,		qs.sql_handle
,		qp.query_plan
from sys.dm_exec_query_stats  qs
CROSS APPLY sys.dm_exec_sql_text(sql_handle) st
CROSS APPLY sys.dm_exec_query_plan(plan_handle) qp
where total_worker_time > 0 
order by total_worker_time  desc


これらのレポートは表示後に右クリックでPDF出力も可能であるため、他人に見せる際にも活用できますので、一度使ってみるとよいと思います。

【SQL Server】WHERE句で正規表現的な検索をする

検索をする際に、SQLServerでは正規表現を使うことはできません。
使い勝手は正規表現ほどではありませんが、似たようなものがありますので検証してみました。

まずは、テーブルを作成します。

CREATE TABLE TEXT_TEST (
	[id] INT,
	[text] NVARCHAR(255)
)


今回検証に使うテストデータは以下となります。

INSERT INTO TEXT_TEST VALUES 
(1, N'123'),
(2, N'abc'),
(3, N'aBc'),
(4, N'a c'),
(5, N'A C'),
(6, N'123'),
(7, N'漢字a')
(8, N'1bc')


照合順序に左右されたくないため、ここではCOLLATE句でJapanese_BIN2を指定しています。

半角英数字以外を含むレコードを抽出

SELECT * FROM TEXT_TEST
	WHERE [text] LIKE '%[^-a-zA-Z0-9 ]%'
	COLLATE Japanese_BIN2

f:id:utiowa:20170309013017p:plain

半角英数字を含むレコードを抽出

SELECT * FROM TEXT_TEST
	WHERE [text] LIKE '%[a-zA-Z0-9ア-ン ]%'
	COLLATE Japanese_BIN2

f:id:utiowa:20170309013026p:plain

数字を含むレコードを抽出

SELECT * FROM TEXT_TEST
	WHERE [text] LIKE '%[0-9]%'
	COLLATE Japanese_BIN2

f:id:utiowa:20170309013032p:plain


尚、照合順序についてはJapanese_CS_AS_KS_WSなどがありますが、意味としては以下のような形になります。

CS 大文字、小文字を区別する
CI 大文字、小文字を区別しない
AS アクセントを区別する
AI アクセントを区別しない
KS ひらがな、カタカナを区別する
KI ひらがな、カタカナを区別しない
WS 全角、半角を区別する
WI 全角、半角を区別しない
BIN2 バイナリで区別する


細かい指定や繰り返しの表現は出来ませんが、無いよりはマシですので頭の片隅に入れておくと役立つかも知れません。

【参考】
・パターン
https://technet.microsoft.com/ja-jp/library/ms187489(v=sql.105).aspx
・照合順序
https://msdn.microsoft.com/ja-jp/library/ms143726.aspx
https://blogs.msdn.microsoft.com/jpsql/2016/07/26/1-3/