HowTo: BID トレース - データアクセス アプリケーションのトレースを採取する
高橋理香
SQL Developer Support Escalation Engineer
SQL Server などのデータベースにアクセスする際に使用されるテクノロジーとして、ADO.NET や Windows DAC 等がありますが、今回はこのようなテクノロジーを使用したアプリケーションで問題が発生した場合に役立つ BID トレースについてご紹介します。今回は主に BID トレースの概要と採取の手順にフォーカスしてご説明します。
1. BID トレースの概要 |
1-1. BID トレースとは？
Windows OS で提供している、オーバーヘッドの少ないトレースを提供することを目的とした Event Tracing for Windows (ETW) システムを使用したトレース手法です。データアクセス テクノロジーで利用する場合には、Built-in Diagnostics (BID) アダプタが製品コードを ETW プロバイダのように見せかけることでトレース採取を実現しているために、主に BID トレースという名前で呼んでいます。
1-2. BID トレースを採取できるコンポーネントは？
BID トレースでは、主に以下のコンポーネントの処理をトレースすることができます。
- System.Data 名前空間の各クラス (*1)
- MDAC/Windows DAC に含まれる ADO、OLE DB、ODBC などの各種データアクセス テクノロジー (*2)
- SQL Native Client
- SQL Server (*3)
(*1) .NET Framework 2.0 以降で対応しています。
(*2) MDAC 2.8 SP1 以降で採取可能です。ただし、真に有効な情報が得られるのは Windows DAC からのみです。 (MDAC/Windows DAC に関する 参考情報: MDAC/Windows DAC を利用するアプリケーションの開発/動作環境) (*3) SQL Server 2005 以降で対応しています。
1-3. BID トレースから何がわかるか？
BID トレースでは、各種処理の開始時刻と終了時刻、ならびに、使用するクラスなどの各種オプション設定などの情報を採取できます。また、実行した処理で返されたデータアクセス関連のエラーの情報も記録されます。
例えば、SQL Server への接続でエラーが発生するケースがあった場合を考えます。通常はネットワークトレースを採取することで、接続処理のどの過程で時間を要したのかを把握することができます。しかしながら、ローカル接続の場合には一般的なネットワークモニタツールではトレースは採取できません。このような場合、BID トレースを採取することで、どこまで処理が進んだのか、内部処理においてどのようなエラーが返されたのかなどを把握することができます。
また、パフォーマンスの問題があるものの、SQL Server のトレースではSQL Server 上での処理に時間を要していないことが確認された場合などに、アプリケーション側のどの部分で時間を要したのかを確認するという目的で使用することもできます。
1-4. BID トレースに関する参考ページ
BID トレースについては、以下のページで採取の方法や読み取る方法を詳細に紹介しています。
Data Access Tracing in SQL Server 2008
https://msdn.microsoft.com/en-us/library/cc765421.aspx
SQL Server 2005 でのデータ アクセスのトレース
https://www.microsoft.com/japan/msdn/sqlserver/sql2005/data_access_tracing.aspx
データ アクセスのトレース
https://msdn.microsoft.com/ja-jp/library/ms971550.aspx
2. BID トレースを採取する |
2-1. BID トレース採取を準備する
2-1-1. BID トレースを採取するために必要となるファイルを入手する。
BID トレースを採取する際に必要となるいくつかのファイルをまとめたもの以下のサイトに用意してあります。
https://download.microsoft.com/download/D/2/0/D20E1C5F-72EA-4505-9F26-FEF9550EFD44/Setup.zip
Setup.zip には以下のよう 5つのにフォルダが含まれています。
2-1-2. 採取対象のアプリケーションが 32bit で動作するか 64bit で動作するかを確認する。
BID トレースを採取するためには、トレース DLL がレジストリに登録されている必要があります。また、このトレース DLL は 32bit 版と 64bit 版があり、アプリケーションがどちらのモードで動作しているかによって使用するトレース DLL が異なります。
そこで、最初にアプリケーションが 32bit で動作しているか 64bit で動作しているかを確認します。最も簡単な確認方法は、タスクマネージャを使用する方法です。
例えば WindowsFormsApplication1.exe という名前のプロセスで動作するアプリケーションがあるとします。これを x86 でビルドし、64bit 環境で動作させた場合、タスクマネージャでは、以下の通り、プロセス名に *32 という文字がついたイメージ名となります。
同じアプリケーションを x64 でビルドし、x64 環境で動作させた場合には以下の通りです。イメージ名に *32 はつきません。
2-1-3. アプリケーションがトレース DLL をロードするようレジストリを設定する。
アプリケーションが 32bit、64bit のどちらで動作しているかを確認できたら、アプリケーションが トレース DLL をロードするようレジストリを設定します。
!!! 注意事項 !!!
以下 A および B のいずれの場合も、”値の名前” の先頭についている記号のコロン (:) を忘れずに入力下さい。このコロンがない場合、正しくトレースが採取されません。
A: 32bit OS 環境で動作している場合、もしくは、64bit OS 環境で 64bit モードで動作している場合
レジストリキー [HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\BidInterface\Loader]
値の名前 :Path
値のデータ C:\WINDOWS\SYSTEM32\msdaDiag.dll
B: 64bit OS 環境で 32bit モードで動作している場合
レジストリキー [HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\BidInterface\Loader]
値の名前 :Path
値のデータ C:\WINDOWS\SysWOW64\msdaDiag.dll
※テキストエディタを使用して以下の内容で .reg ファイルを作成して実行するか、後述の 「手動設定手順」によって手動で設定ください。
Windows Registry Editor Version 5.00 [HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\BidInterface\Loader] ":Path"=C:\\WINDOWS\\SysWOW64\\MSDADIAG.dll |
手動設定手順
1) レジストリ エディタ (regedit.exe) を起動します。
2) レジストリ キーに [HKEY_LOCAL_MACHINE\SOFTWARE\Wow6432Node\Microsoft\BidInterface] に移動します。
3) レジストリキー Loader が存在しない場合、以下の通り、新規に作成します。
4) 文字列値を新規に作成します。
5) 値の名前に :Path を入力したら、ダブルクリックし、トレース DLL のパスとして C:\WINDOWS\SysWOW64\msdaDiag.dll を設定して完了です。
2-1-4. 各種トレースイベントの情報が適切に表示されるようトレーススキーマを登録する。
採取したトレースに、System.Data や ADODB などのコンポーネントの名前が適切に表示されるようにするためには、事前にManaged Object Format (MOF) ファイルという特殊なフォーマットのスキーマ ファイルを mofcomp.exe というユーティリティを使って登録しておく必要があります。
MOF ファイルは、事前にダウンロード、展開したフォルダ "MOF_Files" 内にあります。
スキーマを登録しておくことによる弊害はないため、データアクセスに関するスキーマをすべて含む all.mof を登録してみましょう。実行コマンドは以下の通りです。
mofcomp all.mof
※ここではコマンド プロンプトが 32bit もしくは 64bit であることを意識する必要はありません。
実行すると以下の通り、メッセージが表示されます。
2-1-5. トレース イベントを採取する対象の ETW プロバイダを決定し、構成ファイルを作成する。
トレースを採取するアプリケーションで使用されているコンポーネントに合わせて構成ファイルを作成します。
構成ファイルは、メモ帳などのテキストエディタで作成されるフラット テキスト ファイルです。ファイル名は任意です。
構成ファイルのサンプルは、事前にダウンロード、展開したフォルダ "Control_GUID_Files" にいくつか用意してありますので、用途に応じて選択ください。
例えば System.Data.SqlClient を使用して SQL Server にアクセスするアプリケーションの場合、次のような内容で構成ファイルを作成するとトレースを採取できます。
{7ACDCAC8-8947-F88A-E51A-24018F5129EF} 0x00000000 0 ADONETDIAG.ETW {914ABDE2-171E-C600-3348-C514171DE148} 0x00000000 0 System.Data.1 {C9996FA5-C06F-F20C-8A20-69B3BA392315} 0x00000000 0 System.Data.SNI.1 |
また、cscript.exe で動作させる VBScript のバッチファイルで、ADO と SQL Native Client 10.0 を使用して SQL Server 2008 にアクセスする際のトレースを採取する場合には、次のような構成ファイルを作成します。
{8B98D3F2-3CC6-0B9C-6651-9649CCE5C752} 0x00000000 0 MSDADIAG.ETW {04C8A86F-3369-12F8-4769-24E484A9E725} 0x00000000 0 ADODB.1 {0DD082C4-66F2-271F-74BA-2BF1F9F65C66} 0x00000000 0 OLEDB.1 {A9377239-477A-DD22-6E21-75912A95FD08} 0x00000000 0 SQLNCLI10.1 |
※上記の左から 2列目にある 0x00000000 は採取モードで、これを 0xFFFFFFFF にするとより詳細な情報を採取できます。
2-2. BID トレース採取を開始する
BID トレースは logman ユーティリティを使用して開始、停止を制御できます。
以下はトレース開始のコマンド実行例です。
logman start MyTrace -o Out.etl -pf providers.cfg -ets
※ここではコマンド プロンプトが 32bit もしくは 64bit であることを意識する必要はありません。
上記は MyTrace という名前のトレース採取を providers.cfg という構成ファイルを使用して開始し、出力ファイルは Out.etl という名前であることを示すコマンドです。
ここで使用する構成ファイルとは、2-1-5 で作成した構成ファイルです。
なお、採取したい現象の発生が不定期であるなど、長期間に渡っての情報採取が必要となる場合、出力ファイルが一定のサイズに到達した場合にロールオーバーするようトレース採取を実行することができます。以下は、20 MB 単位でファイル名に連番を付けてロールオーバーするためのコマンド例です。
logman start MyTrace -o Out%d.etl -mode NewFile -max 20 -pf providers.cfg -ets
!!! 注意事項 !!!
採取対象のプロセスを特定してのトレース採取はできません。
そのため、可能な場合には、不要なアプリケーション プロセスは停止した上で採取を開始することをお勧めします。
2-3. BID トレース採取を終了する
トレース開始時に指定した名前を使用してトレースを停止します。
上記 2-2-1 の例では MyTrace という名前を付けていますので、停止のコマンドは以下の通りです。
logman stop MyTrace -ets
※ここではコマンド プロンプトが 32bit もしくは 64bit であることを意識する必要はありません。
2-4. BID トレースを変換する
採取したファイルはバイナリ形式のファイルですので、tracerpt.exe という書式設定プログラムを使用して、ユーザーが読める形式に変換します。
tracerpt /y Out.etl
※ここではコマンド プロンプトが 32bit もしくは 64bit であることを意識する必要はありません。
上記コマンドでは、セッションでキャプチャされたトレースイベントを要約した summary.txt ファイルと、トレースを含む dumpfile.csv ファイルを生成します。変換先の形式は、Windows XP や Windows Server 2003 の場合には既定で CSV 形式です。Windows Vista 以降では既定で XML 形式です。Windows Vista 以降で CSV 形式にする場合には、-of オプションを使用します。また、日本語のメッセージが文字化けした状態で出力される可能性がありますが、その際には -en オプションで Unicode と指定してみましょう。
traceRpt Out.etl -of CSV -en Unicode -o dump.csv
以下は BID トレースの出力例です。Windows 7 上の System.Data.SqlClient で SQL Server にアクセスするアプリケーションで、存在しない SQL Server に接続しようとして接続エラーが発生した際、採取モード 0x00000000 で BID トレースを採取し、上記オプションで変換して出力しました。
Event Name, Type, Event ID, Version, Channel, Level, Opcode, Task, Keyword, PID, TID, Processor Number, Instance ID, Parent Instance ID, Activity ID, Related Activity ID, Clock-Time, Kernel(ms), User(ms), User Data EventTrace, Header, 0, 2, 0, 0, 0, 0, 0x0000000000000000, 0x00000A44, 0x00000698, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648776925040164, 45, 30, 8192, 83951878, 7600, 1, 129648777277383525, 156250, 0, 0x0, 2, 1, 8, 0, 2199, 0x2, 0x3, 129648688155000000, 3579545, 129648776925040164, 0x1, 0, "MyTrace", "C:\work\Out.etl" System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648776952519008, 330, 165, 2, "<prov.DbConnectionHelper.ConnectionString_Set|API> 1#, 'Data Source=tcp:Server01;Integrated Security=SSPI;' " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648776952824175, 330, 165, 2, "enter_01 <sc.SqlConnection.Open|API> 1# " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648776953637035, 375, 195, 2, "<sc.TdsParser.Connect|SEC> SSPI authentication " System.Data.SNI, TextA, 0, 0, 0, 0, 17, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648776953677440, 375, 195, 1, "ObtainIDa 1# <SNI_Conn::SNI_Conn|ID|SNI> 00000000000F7E40{.}" System.Data.SNI, TextA, 0, 0, 0, 0, 17, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648776953678423, 375, 195, 1, "ObtainIDa 2# <Tcp::Tcp|ID|SNI> 00000000000F8BC0{.} created by 1#{SNI_Conn}" System.Data.SNI, TextA, 0, 0, 0, 0, 17, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166006834, 375, 195, 1, "<Tcp::Open|ERR|SNI> ProviderNum: 7{ProviderNum}, SNIError: 0{SNIError}, NativeError: 10060{WINERR} " System.Data.SNI, TextA, 0, 0, 0, 0, 17, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166007010, 375, 195, 1, "RecycleIDa 2# <Tcp::~Tcp|ID|SNI> " System.Data.SNI, TextA, 0, 0, 0, 0, 17, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166007381, 375, 195, 1, "RecycleIDa 1# <SNI_Conn::~SNI_Conn|ID|SNI> " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166388159, 375, 195, 2, "<sc.SqlError.SqlError|ERR> infoNumber=10060, errorState=0, errorClass=20, errorMessage='SQL Server への接続を確立しているときにネットワーク関連またはインスタンス固有のエラーが発生しました。サーバーが見つからないかアクセスできません。インスタンス名が正しいこと、および SQL Server がリモート接続を許可するように構成されていることを確認してください。 (provider: TCP プロバイダ, error: 0 - 接続済みの呼び出し先が一定の時間を過ぎても正しく応答しなかったため、接続できませんでした。または接続済みのホストが応答しなかったため、確立された接続は失敗しました。)', procedure='None', lineNumber=0 " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166392408, 375, 195, 2, "<sc.TdsParser.Connect|ERR|SEC> Login failure " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166413441, 375, 195, 2, "<sc.SqlInternalConnectionTds.LoginFailure|RES|CPOOL> 4# " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166587475, 390, 195, 2, "" System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777166603161, 390, 195, 2, "leave_01 " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777184874500, 420, 510, 2, "enter_01 <sc.SqlConnection.Close|API> 1# " System.Data, TextW, 0, 0, 0, 0, 18, 0, 0x0000000000000000, 0x00000880, 0x00000920, 0, , , {00000000-0000-0000-0000-000000000000}, , 129648777184874791, 420, 510, 2, "leave_01 " |
上記からは以下のことがわかります。
- 接続文字列は Data Source=tcp:Server01;Integrated Security=SSPI であるため、TCP/IP で Server 01 に Windows 認証で接続しようとしていた。
- Tcp::Open という関数を実行した結果はエラーであり、そのエラーコードは 10060 であった。 ※エラー 10060 は Winsock のエラー WSAETIMEDOUT に該当します。
- 返されたエラーメッセージは以下の通りです。
SQL Server への接続を確立しているときにネットワーク関連またはインスタンス固有のエラーが発生しました。サーバーが見つからないかアクセスできません。インスタンス名が正しいこと、および SQL Server がリモート接続を許可するように構成されていることを確認してください。 (provider: TCP プロバイダ, error: 0 - 接続済みの呼び出し先が一定の時間を過ぎても正しく応答しなかったため、接続できませんでした。または接続済みのホストが応答しなかったため、確立された接続は失敗しました。
3. BID トレースを正しく採取できない場合のトラブルシューティング |
採取したトレースを変換しても、採取対象としたプロバイダのイベントが出力されていない場合、適切に情報採取の設定が行われていない可能性があります。主に設定の漏れや誤りがある場合に失敗するケースが多く報告されていますので、以下に要因と対処をご紹介します。もしも採取できていない場合には、以下を参考に再度正しく設定されているかをチェックしてください。
Case1: トレース DLL のレジストリ設定の値の名前が正しく設定されていない。
トレース DLL のパスの設定のために作成する "値の名前" には、記号のコロン (:) と "Path" という文字列で構成された名前を指定する必要があります。"値の名前" に、コロン (:) が抜けた "Path" のみが設定されている場合、トレース DLL は正しく読み込まれません。レジストリ エディタ (regedit.exe) で、トレース DLL のパス設定の "値の名前" にコロンの記述漏れがないかをご確認ください。もしもコロンが抜けていた場合には、いったん既存の値を削除してから新規に作成し、再度トレース採取をお試し下さい。
Case2: x64 環境でアプリケーションが WOW64 (32bit) で動作しているが、64bit の設定しか行われていない。
実行環境が 64bit 環境の場合には、アプリケーションが 64bit で動作しているか 32bit で動作しているかは BID トレースを採取する上で重要です。実行環境が 64bit 環境かどうかを確認する方法は様々ありますが、いずれの OS も共通で、[アクセサリ] - [システムツール] - [システム情報] から以下のように確認できます。
確認した結果が 64bit OS であった場合には、手順 2-1-2 の方法でアプリケーションが 32bit で動作しているかどうかをあらためて確認しましょう。また、その結果を基に 2-1-3 の手順で該当のレジストリにトレース DLL のパスを適切に設定してから再度トレース採取をお試し下さい。