データ アクセスのトレース

ADO.NET 2.0 のトレース機能の概要

Bob Beauchemin
DevelopMentor

November 2004
日本語版最終更新日 2005 年 3 月 15 日

適用対象 :
   Microsoft ADO.NET 2.0
   Microsoft .NET Framework 2.0
   Microsoft SQL Server

概要 :

ADO.NET 2.0 のトレース機能を適用し、アプリケーションの不具合とボトルネックを見つける方法を学びます。

関連する 2005TracingExamples.exe コード サンプルをダウンロードしてください。

目次

はじめに
トレースの設定
トレースの実行
トレース出力の読み取り
トレースするアプリケーションの構成
トレースを使ったパラメータ バインディング問題のデバッグ
2 つの主要な診断シナリオ
データ トレースの内部
まとめ

はじめに

ODBC トレースの時代以来、データ アクセス用の優れた汎用組み込みトレース機能がないことを残念に思っていました。 OLE DB にはさまざまな種類のトレースがありました。よく覚えているのは、Visual Studio Analyzer 互換のインスツルメンテーションと ATLTRACE (ATL OLE DB テンプレート用のトレース マクロ) の 2 つです。 OLE DB と MDAC の問題は、トレースが実行できないことではなく、種類の異なるトレースがあまりにも多く、それぞれが異なる評価メカニズムに結び付けられていたことです。 データ アクセス スタックのさまざまなレイヤにアクセスして 1 つのトレース出力を取得するのは、不可能とは言わないまでも、きわめて困難でした。

ADO.NET 2.0 と SQL Native Client (新しい OLE DB/ODBC/ネットワーク ライブラリ機能) には、柔軟で多機能な組み込みデータ トレース機能が含まれています。 マイクロソフトは、4 つの .NET データ プロバイダ (SqlClient、OracleClient、OleDb ブリッジ、Odbc ブリッジ) のすべてと、ADO.NET の DataSet および関連物、SQL Native Client の OLE DB および ODBC のプロバイダまたはドライバ、さらには SQL Server 2005 のネットワーク ライブラリにこの機能を対応させています。 この記事の情報は、トレースの方法をわかりやすく説明し、トレース ファイルの簡単な分析方法を示し、トレースの簡単な使用例を紹介することを目的としています。 記事の最後には、異なるトレース テクノロジに拡張できるようにトレース レイヤを構築する方法を説明し、そのトレース レイヤを使用する方法をさらにいくつか提案します。

トレース ポイントは、.NET および SQL Native Client のライブラリで既にプログラムされています。 Reflector などの IL ディスアセンブラを使ったことのある人は、既に気づいているかもしれません。 最初の手順は、基本的な出力が得られるように設定を行うことです。

トレースを使用するための基本的な手順は次のとおりです。

  1. データ トレース DLL レジストリ エントリ、ETW プロバイダ、および WMI スキーマを設定します。
  2. トレース自体を構成して実行します。
  3. トレースの結果をカンマ区切り値ファイルとして収集します。

ETW や WMI といった頭字語がわからなくても気にしないでください。 まず手順を 1 つずつ実行し、その後で詳しい仕組みを見ていくことにしましょう。

メモ   設定の前にデータ トレースの仕組みについて理解したい場合は、この記事の最後の方にある「データ トレースの内部」を読んでください。

データ トレースの設定

トレース DLL レジストリ エントリの設定 : この手順では、レジストリ スクリプトを実行するか、またはレジストリを手動で実行して、Event Tracing for Windows (ETW) プロバイダにデータ トレースを結び付けます。 現時点では、これを行うにはレジストリを編集するしかありません。将来的にはコントロール パネルのアプリケーションか構成ファイルのメカニズムが使えるようになります。 このレジストリ キーについては後ほど詳しく説明します。ひとまずここでは、マシン上のすべてのデータ関連プロセスに対してトレースを有効にします。

  1. レジストリ キー HKLM\Software\Microsoft\BidInterface\Loader を見つけます。
  2. 新しい文字列値を (Loader キーの下に) 追加します。

名前 =":Path" 値 ="C:\WINDOWS\Microsoft.NET\Framework\v2.0.40607\AdoNetDiag.dll"

ここでは、.NET Framework 2.0 の Beta 1 バージョンがインストールされていて、システム ドライブが C:\ ドライブであると仮定しています。 Path の前のコロンは重要なので注意してください。 この記事に付属の setup_trace.reg ファイルを実行してもかまいません。

データ トレース スキーマの登録 : 先ほど登録した AdoNetDiag.dll は、データ トレースに対応する任意のライブラリを Event Tracing for Windows プロバイダのように見せかけるアダプタ コンポーネントです。 これでプロバイダを利用できますが、パブリック プロバイダ リストや WMI ツールにプロバイダが表示されるようにするには、ETW プロバイダとその WMI スキーマを、AdoNetDiag.dll が公開するイベントに対して登録する必要があります。 それには、MOF ファイルという特殊なフォーマットのスキーマ ファイルと、mofcomp というユーティリティを使います。 ADO.NET 2.0 では、MOF ファイルは C:\WINDOWS\Microsoft.NET\Framework\v2.0.40607 ディレクトリで提供されています。しかしデータ トレースは開発途上のテクノロジなので、最良の結果を得るには、この記事に付属の MOF ファイルを使うようにしてください。 この記事に付属の Windows スクリプト register_mof.cmd を実行します。このスクリプトは登録コードを実行します。 このコマンドをコマンド ラインから手動で実行する場合は、次のようになります。

  1. mofcomp adonetdiag_beta1.mof

プロバイダが正しく登録されたことを確認するには、次のコマンドを使って ETW プロバイダを一覧表示します。



1> logman query providers
                

登録したプロバイダと、OS やその他の製品に付属している他のプロバイダが表示されるはずです。 各プロバイダが GUID で識別されていることに注目してください。 プロバイダの一覧は次のようになります。



Provider                       GUID
--------------------------------------------------------------------------
*System.Data.1                 {914ABDE2-171E-C600-3348-C514171DE148}
ACPI Driver Trace Provider     {dab01d4d-2d48-477d-b1c3-daad0ce6f06b}
Active Directory: Kerberos     {bba3add2-c229-4cdb-ae2b-57eb6966b0c4}
IIS: SSL Filter                {1fbecc45-c060-4e7c-8a0e-0dbd6116181b}
IIS: WWW Server                {3a2a4e84-4c21-4981-ae10-3fda0d9b0f83}
IIS: Active Server Pages (ASP) {06b94d9a-b15e-456e-a4ef-37c984a2cb4b}
MSSQLSERVER Trace              {2373A92B-1C1C-4E71-B494-5CA97F96AA19}
Local Security Authority (LSA) {cc85922f-db41-11d2-9244-006008269001}
*System.Data.SNI.B1            {C22CFA1B-A312-354C-33F7-ACACA46CE990}
*SQLNCLI.1                     {BA798F36-2325-EC5B-ECF8-76958A2AF9B5}
Windows Kernel Trace           {9e814aad-3204-11d2-9a82-006008a86939}
*System.Data.OracleClient.1    {DCD90923-4953-20C2-8708-01976FB15287}
*ADONETDIAG.ETW                {8B98D3F2-3CC6-0B9C-6651-9649CCE5C752}
ASP.NET Events                 {AFF081FE-0247-4275-9C4E-021F3DC1DA35}
NTLM Security Protocol         {C92CF544-91B3-4dc0-8E11-C580339A0BF8}
IIS: WWW Isapi Extension       {a1c2040e-8840-4c31-ba11-9871031a19ea}
HTTP Service Trace             {dd5ef90a-6398-47a4-ad34-4dcecdef795f}
Spooler Trace Control          {94a984ef-f525-4bf1-be3c-ef374056a592}

                

ここでは出力を若干変更し、話題とするプロバイダの横にアスタリスクを付けています。 また、WMI CIM Studio ツールを使うことにより、登録された WMI スキーマを確認することもできます。 WMI Administrative Tools はダウンロード可能です。 データ トレース用の WMI スキーマは非常に簡単です。これについては後ほど説明します。

トレースの実行

トレースを実行するには、logman (log manager) というユーティリティを使って、名前付きトレースを定義し、ETW コマンドを発行してそれらのトレースを使います。 トレースを開始するには、この記事に付属のスクリプト traceon.cmd を実行します。 Windows 2003 を実行していると仮定すると、このファイル内のコマンドは次のようになります。



@Logman start MyTrace -pf ctrl.guid.adonet.beta1 -ct perf -o Out.etl -ets
                

このコマンド ファイルでは、単一の名前付きトレース インスタンス (MyTrace) を定義し、登録したプロバイダをすべて指定しています。 プロバイダとプロバイダのオプションの一覧は、ctrl.guid.adonet.beta1 という別のファイルで指定されています。 このファイルの内容は次のとおりです。



{7ACDCAC8-8947-F88A-E51A-24018F5129EF} 0x00000000  0   ADONETDIAG.ETW
{914ABDE2-171E-C600-3348-C514171DE148} 0x00000000  0   System.Data.1
{C22CFA1B-A312-354C-33F7-ACACA46CE990} 0x00000000  0   System.Data.SNI.B1
{DCD90923-4953-20C2-8708-01976FB15287} 0x00000000  0   System.Data.OracleClient.1
{BA798F36-2325-EC5B-ECF8-76958A2AF9B5} 0x00000000  0   SQLNCLI.1

                

これらの行には、各プロバイダの GUID、プロバイダ オプション、およびプロバイダの名前が含まれています (行の折り返しに注意してください)。 プロバイダ オプションについては後ほど詳しく説明します。

この方法で logman を起動すると、すべてのイベントが簡潔なバイナリ フォーマットでイベント トレース ログ ファイルに書き込まれます。 これらのファイルには、慣例的に .etl という接尾辞が付きます。 トレースをオンにしたら、この記事のダウンロードに含まれているサンプル プログラム GetDataSet.exe を実行します。 トレースをオフにするには、スクリプト traceoff.cmd を実行します。これにより、次のコマンドが発行されます。



@Logman stop MyTrace -ets
                

コマンドを発行したディレクトリに、"out.etl" という名前の約 150 KB のファイルがあるはずです。 トレース プロバイダを各詳細レベル (ADO.NET プロバイダ、ネットワーク呼び出し、および SQL Server を同じマシンで実行している場合は SQL Server からの応答) でオンにしたため、出力は膨大な量になります。 出力をフィルタリングする方法については、後ほど説明します。 なお、Visual Studio 2005 を起動してテスト プログラムを実行すると、たとえばサーバー エクスプローラがデータ アクセス コードを実行するときなどに、余分なトレース イベントが生成されることがあります。

結果を CSV ファイルとして収集 :

バイナリを読むのが好きだという珍しい人は別として、out.etl ファイルは人間が読める形式にはなっていません。 ETW ユーティリティには、out.etl ファイルをカンマ区切り値ファイルに変換する tracerpt.exe という基本的な書式設定プログラムが含まれています。 CSV ファイルを取得するには、report.cmd を実行します。report.cmd は次のコマンドを発行します。



@TraceRPT /y Out.etl
                

このユーティリティは 2 つのファイルを生成します。 1 つは、セッションでキャプチャされたトレース イベントを要約した summary.txt ファイルです。もう 1 つは dumpfile.csv ファイルです。これらのファイルの名前は tracerpt によって出力されるデフォルトのファイル名であり、コマンドライン オプションを使って変更できます。 必要な情報を含んでいるファイルは dumpfile.csv です。 このファイルは、今の段階では Excel で閲覧できます。後でデータを SQL Server に読み込んで SQL で問い合わせるなどの後処理を実行することができます。 必要な作業は以上です。 これで初めてのトレースが得られました。 では出力を見てみましょう。

トレース出力の読み取り

データ トレース プロバイダは 3 種類の主要な情報を公開します。トレース ポイント情報とプロバイダの ID、イベントの種類、およびスレッドとタイミングの情報の 3 つです。 具体的には、情報の列は次のもので構成されます。

iイベント名?データ トレース イベント プロバイダの名前

イベントの種類?TextW または TextA

TID?スレッド ID

クロックタイム?イベントのタイムスタンプ

カーネル (ms)?カーネル モードのミリ秒数 (CPU 時間)

ユーザー (ms)?ユーザー モードのミリ秒数 (CPU 時間)

ユーザー データ?トレース ポイントに関する詳細情報

WMI プロバイダは複雑なスキーマを公開することが許されていますが、データ トレース プロバイダは TextW と TextA の 2 つの単純なイベントの種類のみを公開します。 TextW は Unicode 文字メッセージ用で、TextA はANSI 文字メッセージ用です。 データ トレース イベントの多くが "開始"と "終了" のペアで囲まれていることに注目してください。そのため、入れ子になった API 呼び出しを簡単にたどることができます。 たとえば、このトレースでは、ユーザー データ フィールドは次のようになっています。



"enter_01 <comm.DbDataAdapter.Fill|API> 1#  dataSet"
"enter_02 <comm.DbDataAdapter.Fill|API> 1#  dataSet  startRecord  
maxRecords  srcTable  command  behavior=16{ds.CommandBehavior}"
"<sc.SqlCommand.get_Connection|API> 1#"
"<sc.SqlCommand.get_Connection|API> 1#"
"enter_03 <sc.SqlConnection.Open|API> 1#"
"enter_04 <prov.DbConnectionBase.Open|API> 1#"
"enter_05 <SNIInitialize|API|SNI> pmo: 00000000{void}"
... many events deleted
"leave_05"
 "<sc.TdsParser.CreateSession|ADV> 1# created session 2"
 "<prov.DbConnectionFactory.CreatePooledConnection|RES|CPOOL> 1#  Pooled 
database connection created."
 "leave_04"
 "leave_03"
                

これを見ると、DataAdapter.Fill(DataSet) というユーザー プログラムが DataAdapter.Fill の別のオーバーロードを呼び出し、さらにそれが SqlConnection.Open を呼び出した、という流れが簡単にわかります。 各 enter_nn イベントには、対応する leave_nn イベントがあります。 この例では、基盤となる SNI (SQL Server ネットワーク インターフェイス) 低レベル プロトコル イベントまで呼び出しをトレースしています。 しかし、"主流の" トレーサーである System.Data.1 によって生成される、ユーザー データのこの奇妙なブラケット フォーマットはいったい何でしょうか?

ユーザー データと ADO.NET のトレース

名前からわかるように、ユーザー データ フィールドの内容とフォーマットは、ユーザー (この場合はトレース プロバイダ) の裁量に完全に委ねられています。 System.Data.dll と System.OracleClient.dll の呼び出しは、簡単にデコードできる特殊なフォーマットで表現されます。 例として、先ほどのトレース記録シーケンスのエントリを取り上げてみましょう。



"enter_04 <prov.DbConnectionBase.Open|API> 1#"
                

このエントリは次のようにデコードできます。



<namespace abbreviation.classname.methodname|keyword> parms
                

したがってこの例は、System.Data.ProviderBase.DbConnectionBaseOpen メソッドに対する API 呼び出しがあることを示しています。 名前空間の短縮形を使う理由は、出力のサイズを小さくすることです。 パラメータ番号の後にあるポンド記号付きの番号 (1#) は、DbConnectionBase オブジェクトの特定のインスタンスを識別する役目を果たします。これは複雑なトレースで多くのインスタンスに注目するときに便利です。 ユーザー データをデコードするのに役立つ表を 2 つ示します。

表 1. .NET トレース ポイントで使用される名前空間の短縮形

説明短縮形名前空間
SqlClient マネージ プロバイダscSystem.Data.SqlClient
OleDb マネージ プロバイダoledbSystem.Data.OleDb
Odbc マネージ プロバイダodbcSystem.Data.Odbc
Oracle マネージ プロバイダoraSystem.Data.OracleClient
DataSet/DataTable/Data*dsSystem.Data
共通コードcomnSystem.Data.Common
プロバイダ基本実装クラスprovSystem.Data.ProviderBase

表 2. .NET トレース ポイントで使用されるカテゴリ

キーワード カテゴリ
APIパブリック API (メソッド、プロパティ) が呼び出されます
OLEDBコードが OLEDB コンポーネントを呼び出します
ODBCコードが ODBC API を呼び出します
SNIコードが SNI を呼び出します
ERRエラー
WARN警告
INFO情報
RET戻り値。通常は API|RET の形式
THROW 新しい例外がスローされています (再スローされている例外には当てはまりません)
CATCHコードが例外をキャッチします
CPOOL接続プールの活動
ADV高度なトレース ポイント

この情報を使ってトレース出力を後処理し、DataSet 関連のイベントだけを参照したり、OleDb マネージ イベントと OLE DB ネイティブ イベントのどちらかを選択したりすることができます。 または、イベントの関連付けのために情報をまとめて保持することもできます。 必要なのは、LIKE 演算子を使った簡単なクエリだけです。 ただし、データ トレースはまだ誕生したばかりですので、フォーマットや内容の詳細は将来変更される可能性があります。 機能の進化に合わせて、後処理のコードを再度テストするようにしてください。

トレースするアプリケーションの構成

この記事の冒頭で、Loader レジストリ キーの :Path 文字列値の構成について触れました。 手作業での構成が必要なのは、データ アクセス トレースがまだ誕生したばかりだからです。 具体的には、データ トレースを使用するプログラマは、将来のリリースではこのキーを手動で構成する必要はなくなる予定です。 このキーは、既に ACL (セキュリティ アクセス制御リスト) によって管理者のみがアップデートできるように保護されていますが、将来のリリースでは読み取り専用になる可能性があります。

それはさておき、:Path 値のみを構成すると、特定のマシンで実行されているすべてのアプリケーションでトレースが利用可能になります。 たとえば、プログラマが自分のマシンで SQL Server 2005 のインスタンスとデータ アクセス クライアントを実行している場合、SNI トレースをオンにすると、双方からの SNI 呼び出しがトレースされます。 この場合、出力は膨大な量になります。ただし一部のケースでは、そのような出力が必要なこともあります。 :Path 値が存在しない場合は、アプリケーションをトレース対象として構成できます。:Path 値が存在する場合は、アプリケーションをトレースから除外するように構成できます。

:Path 値が存在しない場合は、個別に構成されたアプリケーションだけがトレースされます。 アプリケーションを "トレース可能" として構成するには、プログラムのメインの実行可能ファイルへのフル パスを値の名前として、AdoNetDiag.dll へのフル パスを値としてそれぞれ使用し、REG_SZ エントリまたは REG_EXPAND_SZ エントリを指定します。 また、パス名と * ワイルドカードを使うことにより、ディレクトリ全体をトレース可能として構成することもできます。

:Path 値が存在する場合は、REG_SZ エントリまたは REG_EXPAND_SZ エントリと値 : (単一のコロン) を追加することにより、アプリケーションまたは特定のディレクトリ内のアプリケーションがトレースされないように制限することができます。 ディレクトリ名ではワイルドカードを使用できます。 たとえば、ディレクトリ名 (C:\Program Files\Microsoft SQL Server\MSSQL.1\MSSQL\Binn\*) と : 値を含む名前フィールドは、SQL Server の Binn ディレクトリ内のすべてのプログラム (SQL Server、SQL Trace など) がトレースに表示されないようにします。 アプリケーションと同じマシンで SQL Server を実行している場合は、この設定を最も頻繁に使うことになります。 なお、レジストリ エントリの構成では、データ トレース プロバイダ DLL (現時点では AdoNetDiag.dll しか選択できません) を指定するだけです。トレースをオンにするわけではありません。 これはきわめて便利な機能です。なぜなら、実行時間の長いプログラム (Web サーバーや Windows サービスなど) を実行する前に、データ トレースをオンにすることなく、データ トレースの構成と設定ができるからです。 こうすれば、プログラムの実行中に、プログラムに干渉することなく、logman を使ってトレースをオンにしたりオフにしたりすることができます。 トレースを使用していないとき、パフォーマンスへの影響はありません。 ネットワークの問題をトレースしている場合は、詳しい情報を得るために、特殊なトレース フラグを設定して SQL Server を実行する必要はありません。

また、どのプロバイダ情報をどのファイルにトレースするかを構成したり、何をある程度までトレースするかを制御したりすることも可能です。 traceon.cmd ファイルでやったように 4 つのプロバイダからの出力をすべて単一のファイルにトレースしたり、それらの出力をプロバイダごとのファイルに分けたりすることができます。 それには、logman ユーティリティを使って名前付きトレースを作成します。 4 つのトレースを作成する例を次に示します。



logman create trace test1 -p System.Data.1
logman create trace test2 -p System.Data.OracleClient.1 
logman create trace test3 -p SQLNCLI.1
logman create trace test4 -p System.Data.SNI.B1
                

コマンド ラインから logman を使うことに加えて、パフォーマンスのログと警告のスナップインを使ってトレースの構成、実行、停止を行うこともできます。 この MMC スナップインの使い方についての説明は、この記事の範疇を越えています。

logman の control.guid ファイルのビットを操作することにより、何をトレースするかをある程度制御できます。 先ほどの例で示したように、トレースごとに単一のプロバイダを使い、既定値をそのまま利用する場合は、control.guid ファイルは不要です。しかし traceon.cmd では control.guid ファイルを使いました。 記憶を呼び起こすため、control.guid の単一の行を次に示します。



{914ABDE2-171E-C600-3348-C514171DE148} 0x00000000  0   System.Data.1
                

この行の情報は次のもので構成されます。

プロバイダ ガイド?どの ETW プロバイダか

制御ビット?この場合は 0x00000000

制御値?この場合は 0

プロバイダ名?ETW で必要。ただし logman ユーティリティには無視されます

制御ビットフィールドと制御値フィールドでビットを設定することで、イベントの事前フィルタリングのためのマクロレベルのメカニズムが得られます。 有効な値は次のとおりです。

0x0002 通常のトレースポイント
0x0004 実行フロー (関数への侵入と退去)
0x0080 高度な出力

System.Data.1 にとってのみ特別な意味を持つビットもあります。

0x1000 接続プールに固有のトレース

もちろん、これらのビットは "OR" で結び付けることもできます。 0x00000000 を指定した場合は、0x00000006 が指定されているものと想定されます。

制御値で設定可能な既定値以外の値は 2 つあります。

128 - Unicode テキストを ASCII テキストに変換します (etl ファイルのサイズを減らします)

64  - このコンポーネントでのトレースを無効にします

制御ビットはビットマスクですが、制御値は数値として設定しなければなりません。 これらの制御ビットを設定するのは、個々のコンポーネントを細かく制御するためではありません。CSV ファイルを自分で後処理しなくても、イベントの種類を容易にフィルタリングできるようにするためです。

トレースを使ったパラメータ バインディング問題のデバッグ

トレースの概要を説明したところで、簡単な使用例を紹介することにします。 私はアプリケーションが内容の豊富なエラー メッセージを "侵食" し、丁寧ではありながらも "情報に欠けた" メッセージを生み出すときに、よく ODBC トレースを使って問題を判断していました。 そのようなアプリケーションのコードは次のようになっています。



string s = GetConnectionStringFromConfigFile();
using (SqlConnection conn = new SqlConnection(s))
using (SqlCommand cmd = new SqlCommand(
  "select * from authors where au_id = @auid", conn))
{
  // ここではエラーをハードコーディングしていますが、グラフィック ユーザー インターフェイスの
  // 好ましくない編集から生じることもあります
  cmd.Parameters.Add("@auid", SqlDbType.Int);
  cmd.Parameters[0].Value = 123456789;
  SqlDataReader rdr = null;
  try {
   // 失敗する可能性のあるコートがここに入ります
  conn.Open();
  rdr = cmd.ExecuteReader();
  while (rdr.Read())
     Console.WriteLine(rdr[0]);
  rdr.Close();
  }
  catch (Exception e) {
    MessageBox.Show("polite error message");
  }
}
                

この場合、エラーはパラメータの型の不一致によって生じますが、エラーを診断する人は、プログラムのソース コードにアクセスできない可能性があります。 トレースをオンにすると、次のような出力が得られます。



"enter_01 <sc.SqlCommand.ExecuteReader|API> 1#"
 "<sc.SqlCommand.get_Connection|API> 1#"
 "<sc.SqlCommand.get_Connection|API> 1#"
 "<sc.TdsParser.CreateSession|ADV> 1# created session 3"
 "<sc.TdsParserSessionPool.CreateSession|ADV> 1# adding session 3 to pool"
 "<sc.TdsParserSessionPool.GetSession|ADV> 1# using session 3"
 "<sc.TdsParser.GetSession|ADV> 1# getting session 3 from pool"
 "<sc.SqlCommand.ExecuteReader|INFO> 1#  Command executed as RPC."
 "<sc.SqlCommand.get_Connection|API> 1#"
 "leave_01"
 "enter_01 <sc.SqlDataReader.Read|API> 1#"
 "<sc.SqlError.SqlError|ERR> infoNumber=245  errorState=1  errorClass=16  
errorMessage='Syntax error converting the varchar value '172-32-1176' to a 
column of data type int.'  procedure=''  lineNumber=1"
 "leave_01"
                

これを見ると、パラメータの値の不一致があることがすぐにわかります。 このサンプルとトレース ファイルは、この記事のコードで提供されています。 なお、このトレース ファイルがきわめて簡潔になっているのは、System.Data.1 プロバイダのみを使ってトレースを行っているからです。

2 つの主要な診断シナリオ

場合によっては、データ トレースを使うことで、他の方法では見つけるのに数日から数週間もかかるような問題が明らかになることがあります。 例として、リソースの回収に関する問題の診断があります。 プログラム ロジックのエラーは、最終的に接続を使い果たしてしまったり、接続プールに過剰な負荷を強いるプログラムにつながることがあります。 たとえば、トランザクションを開始し、ロジック パスで COMMIT または ROLLBACK が呼び出されない場合は、トランザクションがタイム アウトになるまで、接続はトランザクションの接続プールに残ります。 これにより、アプリケーション プログラマ (および診断者) を悩ますような接続プールの奇妙な動作が生じることがあります。 同じように、接続を閉じるのを単純に怠り、プーラーとタイムアウトにその処理をやらせているケースもあります?これは控え目に言えば、接続を閉じるための "次善策" です。 後処理したトレースに対して SELECT ステートメントを実行することによって接続プールの活動を監視し、それをトランザクションの活動に関連付けると、こうした不可解な問題を解決するのに非常に役立ちます。 この場合は、トランザクション タイムアウトのトレース エントリと共に、"enter-leave" のペアが特に役立ちます。

もう 1 つのシナリオは、アプリケーションの接続時間が異常に長いときです。 ネットワーク ライブラリの構成方法により、SQL Server は、たとえば TCP/IP を介して接続を試行し、TCP/IP が失敗したときに、名前付きパイプまたはクライアント プロトコル リストのその他のプロトコルを使うことが可能です。 リストの最初のプロトコルがタイムアウトにより失敗した場合、接続が遅く見えたり、応答時間が遅く見えたりすることがあります。 データ トレースを使うと、これを詳しく観察することができます。これは、SqlClient とその他のマネージ .NET データ プロバイダのトレースが、アンマネージ スタックおよびネットワークからのトレースと統合されるからです。 イベントの進行全体を "enter-leave"ブロックで囲み、Open() の呼び出しが時間を費やしているところがわかるようにタイムスタンプを設定することも可能です。

ここでは、この複雑かつ強力な機能の用途をごく簡単に見てきたにすぎません。 自分で試してみるときは、次のことを考えてみてください。

  1. トレースを単体テストに統合する
  2. DataSet と DataReader の呼び出しを比較分析して、DataSet が時間を費やしている箇所を判断する
  3. データ トレースを ASP.NET およびその他の ETW プロバイダと組み合わせて使用する
  4. SQL Server ETW プロバイダを使ってデータ トレースと SQL Server トレースを組み合わせる
  5. ネットワーク プロトコルのその他の問題を診断する

データ トレースの内部

これでマイクロソフトのデータ アクセス スタック内でトレースを設定、実行、および解釈する方法はわかりました。 しかし、コマンド ライン スクリプトの発行以外に、実際に何が起きているのでしょうか。

データ トレースはプロバイダ モデル自体に基づいています。 ADO.NET データ プロバイダまたはその他のデータ アクセス コードでは、標準の API (それ自体が標準のトレース フックを使用します) を使用してトレース情報をモデルに提供します。将来的には、複数のデータ トレース プロバイダが構築される可能性があります。 現在利用できるのは AdoNetDiag だけですが、イベントの事前フィルタリングを詳細なレベルで提供したり、OutputDebugString などの異なるトレース出力システムを使用したり、検索やクエリの簡素化のために SQL Server に直接出力したりするデータ トレース コンシューマが考えられます。 データ トレースを .NET の System.Diagnostics.Trace にフックすることも可能です。

ADO.NET 2.0 と SQL Native Client には、Event Tracing for Windows (ETW) システムへのアダプタが付属しています。 マネージ スタックからアンマネージ スタックへ、およびアンマネージ スタックからマネージ スタックへの円滑なトレースが可能です。 ETW は、本来はデバイス ドライバの記述者のためのカーネルレベル トレースを実装するために導入された、高パフォーマンスなトレース システムです。 データ トレースを例にした ETW の高度な説明を次に示します。

ETW とは?

Event Tracing for Windows は、Windows パフォーマンス モニタに比べてオーバヘッドの少ないトレースを提供することを目的としています。 通常、ETW の CPU 利用率は 5 パーセント以下で、毎秒 20,000 イベントまでのログをとることができます。 これはリアル タイムでのトレースを可能にするのに十分な速さです。 ETW はプロバイダベースのモデルを使用します。この場合、プロバイダはイベント システムにイベントを送信するシステム コンポーネントまたはアプリケーション コンポーネントです。 イベント プロバイダの例としては、Active Directory、IIS、ASP.NET などがあります。 ADO.NET と SQL Native Client のデータ トレースは、5 つの ETW イベント プロバイダを登録します。

  1. System.Data.1?System.Data.dll 内の ADO.NET プロバイダおよびクラス
  2. System.Data.OracleClient.1?System.OracleClient.dll 内の OracleClient プロバイダ
  3. System.Data.SNI.B1?System.Data の SNI (.NET 2.0 Beta 2 で System.Data.SNI.1 に変更されます)
  4. SQLNCLI.1?SQL Native Client プロバイダと SQL Native Client の SNI
  5. ADONETDIAG.ETW?ETW アダプタ自体のイベントを提供

ETW プロバイダのログは、各イベントのタイムスタンプを生成します。 トレースを開始するときに、高分解能のタイムスタンプまたは低分解能のタイムスタンプを指定できます。 traceon.cmd ファイルでは、-ct perf オプションを使って高分解能のタイムスタンプを選択しました。 先ほどの "単一ファイル" スクリプトでは、既定の (低分解能) タイムスタンプを選択しました。 ETW は、使いやすさよりも高パフォーマンスを優先します。 tracerpt.exe で ETW トレースを書式設定すると、簡単なデコードが生成されます。 ETL ファイルのフォーマットは文書化され、個々のトレース プロバイダのスキーマは WMI に記録されています。したがってプログラマは独自の特殊な書式設定プログラムを構築できます。 ETW を使うことの利点は、作成するトレースを ASP.NET トレースと組み合わせて使用したり、低レベルの OS カーネル トレースと組み合わせて使用したりできることです。 すべてのイベントは、プロバイダ単位で単一のファイルに記録して関連付けたり、個別のファイルに記録したりすることができます。 Event Tracing for Windows に関する情報は、パターン & プラクティス サイトの「Performances Best Practices At A Glance」ページにあります。

ETW の出力はさまざまなツールで利用できます。目的に合ったツールが存在しない場合は、独自のツールを構築できます。 そうしたコンシューマ ツールの例として、logparser があります。 logparser は ETW の出力だけでなく、IIS のログ ファイルや Windows のイベント ログといったその他の出力も利用できます。 logparser では、SQL に似た構文を使ってイベントを問い合わせることができます。 logparser は IIS 6.0 Resource Kit Tools の一部として利用できます。

まとめ

ADO.NET 2.0 リリースでは、トレースはプロバイダ レベルとネットワーク プロトコル レベルで追加され、さらにADO.NET の DataSet など、データベース アクセスで使用される一部のコンポーネントにも追加されています。 このモデルは柔軟で、将来的には異なるトレース エンジンにも対応します。また API がわかりやすいため、プロバイダの記述者やユーザー アプリケーションの記述者は、自らの製品にトレースを追加できます。 現在の実装では、トレースで ETW を使い、公開されるトレース ポイントイベントを収集するための低レベルで干渉の少ない手段を提供します。 トレース データを後処理したり、実行時にトレースをフィルタリングしたりするための異なる方法により、社内のソフトウェア サポート診断者や Microsoft Product Support Services などのさまざまなグループがトレースを使うことが可能になります。

データ トレースと現在のトレース収集機能との統合、および将来のトレース収集機能への拡張性により、トラブルシューティング担当者や開発者は便利で長く使えるツールを得ることができます。 では楽しいトレースを!


Bob Beauchemin 氏は、DevelopMentor の教官、学習コースの作成者、およびデータベース カリキュラム コースの連絡係です。 データ中心の分散システムのアーキテクト、プログラマ、および管理者としての 25 年を超える経験を持っています。 Microsoft Systems Journal、SQL Server Magazine、およびその他のものに ADO.NET、OLE DB、SQL Server に関する記事を執筆したことがあり、『A First Look at SQL Server 2005 for Developers Non-MS link』と『Essential ADO.NET Non-MS link』の著者でもあります。


表示: