[T2-302 follow-up (2)] WCF トレースの見方

こんにちは。

(1) で記載しました通り、本日できなかったデモのフォローアップを記載します。

本日のデモで、WCF サービスのパフォーマンスを早くする簡単なデモをおこないましたが、実際にどこか速くなったのでしょうか ?
ここではそれを WCF のトレースを使用して確認したいと思います。

まず本日のデモの復習ですが、以下のように Visual Studio がデフォルトで作成した wsHttpBinding を

<system.serviceModel>

途中省略 . . .

customBinding を使用して以下の通り変更したという簡単な内容で、5 - 10 倍のパフォーマンス向上となりました。

<system.serviceModel>

途中省略 . . .

</identity>

</endpoint>

</service>

</services>

</behavior>

</serviceBehaviors>

</behaviors>

</binding>

</customBinding>

</bindings>

</system.serviceModel>

さて、この設定でどのようなやりとりに変化したかを実際にみなさんと見ていきたかったのですが、セッションでは時間がなく、まったく説明できませんでしたので、以下にその内容をフォローしておきます。

まず、トレースの出力をおこなうため、サービス側の .config に以下のように Trace Source と Trace Listener の追加をおこなってみましょう。「トレースソースって何 ?」「リスナーって何 ?」という方は、トレースの基本について、IT Pro 道場自主トレシリーズ「アプリケーションの監視」に掲載していますので、まずはこちらで基本を理解してからご確認ください。
ポイントとしては、System.ServiceModel のトレースソースだけでなく、System.ServiceModel.Messaging のトレースソースも出力している点です。また、トレーススイッチとして、最低限 Information と ActivityTracing というスイッチを指定しておきましょう。(このサンプルでは All にしています)

<system.diagnostics>

<add name="traceListener"

type="System.Diagnostics.XmlWriterTraceListener"

initializeData="c:\tmp\Traces.svclog" />

</sharedListeners>

<source name="System.ServiceModel"

switchValue="All"

propagateActivity="true">

</listeners>

</source>

</listeners>

</source>

</sources>

</system.diagnostics>

<system.serviceModel>

途中省略 . . .

<messageLogging

logEntireMessage="true"

logMessagesAtTransportLevel="true"

logMessagesAtServiceLevel="true"

logMalformedMessages="true"/>

</diagnostics>

さて、以上で WCF のトレースが出力され、このトレースを解析することでさまざまな情報がわかるのですが、その見方を簡単にご説明しておきます。

WCF では、出力されるトレース情報として、アクティビティの Call の依存関係や、メッセージの中身などさまざまな情報が出力されます。上記の .config ではこれらを出力するように設定していたわけです。では、その中身をテキストを解析してみなければいけないかというと、こうした WCF 固有のトレース情報を解析するツールとして、svctraceviewer.exe というツールが SDK に付属しています。(Visual Studio コマンドプロンプトから起動できます。)
よって、このトレースビューアツールを起動して中身を確認します。

まず、wsHttpBinding (遅かったほう) を開いてみると、以下のようにトレース情報が出力されているのがわかります。

メッセージ1 ～メッセージ5 まで、随分とたくさんのメッセージがやりとりされているのがわかります。
同じトレース情報を customBinding (速かったほう) で確認すると以下になります。

非常にシンプルですね。

さて、System.ServiceModel.Messaging のトレースソースも出力していますので、メッセージの中身もみることができます。メッセージの中身は [Message] タブで確認できます。

以下は、customBinding でやりとりされているメッセージ 1 の中の情報を確認したものです。Method としてサービス側のメソッド (今日セッションで実装した GetData メソッド) が呼ばれたのがわかります。

wsHttpBinding のほうで同じメッセージをみてみると、実はやりとりされているメッセージの多くが、セキュリティトークンなどのメッセージ交換であることがわかります。(ちなみに、wsHttpBinding の初期設定では、メソッド本体の呼び出し部分は encript されているため、上図とは異なる文字列が送信されています。)

また、上記の .config の設定のように ActivityTrace を出力している場合、Graph タブをみると、どのような順番で内部の呼び出しがおこなわれたかをビジュアルに表示することができます。例えば wsHttpBinding の場合、以下のような Graph になっています。

上図に記載しているように各アイコンの意味をおぼえておくと役立ちます (MSDN に掲載されています)。上図の場合、メソッド本体の処理をおこなっている部分は一番右側になり、その前に、セキュリティ関連などの Environment 関連の処理が数多く処理されているのがわかります。
同じ Graph の内容を速かった customBinding のほうでみてみると、予想通り、Environment 関連の処理がほとんどおこなわれていない (実際のロジック部分の処理が主体) であるのがわかります。

他にもいくつかポイントがありますが、ブログではここまでとしておきましょう。

svctraceviewer ツールの使い方をおぼえておくとパフォーマンスが悪化している場合の原因究明などで非常に役立つことがおわかり頂けるでしょう。例えば、想定していないアクション (例: 設定したおぼえのないセキュリティの処理、など) が存在している場合、それをプロパティ設定などで除去するなどして、速い構成と比較しながら細かなチューニングをおこなうことができます。(上図のように、サービストレースビューアでは経過時間も表示されます。)