C# Tips
−トレースとQueryPerformanceCounter−

QueryPerformanceCounter

ログを書いたりするときになるべく細かい時間まで書いておくと処理にかかってる時間なんかもわかって何かと便利です。 もちろん、処理にかかってる時間と言ったって、他のスレッドやプロセスも同時に動いてるので厳密に計れるわけではありませんが、目安にはなります。 ただ、DateTime.Nowなんかの時間は10msくらいの精度しかありません（と思います）。 これは、そもそもパソコンに内蔵されている時計がその程度の精度しかないからです。 けど、Win32 APIにはQueryPerformanceCounter、QueryPerformanceFrequencyというかなりの精度を持ったタイマーがあります （確か、CPUのクロックを使って計ってるとか、そんなもんだったと思います）。 C#でこれを使うクラスを作ってみました。

using System;
using System.Runtime.InteropServices;

public class TraceTime {
    [DllImport("kernel32.dll")]
    extern static short QueryPerformanceCounter(ref long x);
    
    [DllImport("kernel32.dll")]
    extern static short QueryPerformanceFrequency(ref long x);
    
    public static string Now {
        get {
            long cnt = 0;
            long frq = 0;
            QueryPerformanceCounter(ref cnt);
            QueryPerformanceFrequency(ref frq);
            double c = (double)cnt / (double)frq;
            return DateTime.Now.ToString("yyyy/MM/dd HH:mm:ss.fff") + " [" + c.ToString("#0.0000000000") + "] ";
        }
    }
}

こんなクラスを用意しておいて、

Console.WriteLine(TraceTime.Now + "テスト1");
Console.WriteLine(TraceTime.Now + "テスト2");
Console.WriteLine(TraceTime.Now + "テスト3");

なんてすると

2002/03/17 16:42:58.884 [25987.4906841512] テスト1
2002/03/17 16:42:58.884 [25987.4914375989] テスト2
2002/03/17 16:42:58.884 [25987.4919759355] テスト3

標準出力にこんな風に出力されます。
頭から日付と時間（1/1000秒まで）とQueryPerformanceCounterを使って取った正確な時間です（見りゃわかると思いますが）。 QueryPerformanceCounterの時間は1秒のところに小数点を打ってます。 こんな風にQueryPerformanceCounterの時間は（たぶん）パソコンが起動したときをゼロとして計った時間なので値自体にはあまり意味はありません。 前後と差し引きすれば「その間にどれだけ時間がかかったか」がわかるものです。

トレース

C#（というか.NET Framework）には、System.Diagnostics.Traceクラスがあります。
せっかくあるんだから使ってみましょう。

using System;
using System.Diagnostics;

public class Test {
    public static void Main(string[] args) {
        Trace.WriteLine(TraceTime.Now + "テスト1");
        Trace.WriteLine(TraceTime.Now + "テスト2");
        Trace.WriteLine(TraceTime.Now + "テスト3");
    }
}

こんだけです（上のTraceTimeクラスを使ってます）。 ただし、リファレンスにも書いてありますが、コンパイルするときに

csc /d:TRACE Test.cs

という風に/d:TRACEオプションをつけないとトレースが無効になります。 これは、トレースが必要なくなったら/d:TRACEをはずしてコンパイルするだけでOKなようになってるわけです。 ちなみに、「ログを書かなくなる」というレベルではありません。Traceの呼び出し自体がきれいさっぱり無かったことになります。 ildasmで見てみればそうなってるのがわかります。 こういう風にする方法については条件付きコンパイル（ConditionalAttribute）に書いてます。

さて、これで実行してもコマンドプロンプトには何も表示されません。 実は、標準ではOutputDebugString APIを使って出力されます。 これは、DBMon.exeというツールを使うと表示できます。 DBMon.exeはPlatform SDKに含まれてるので探してみてください。

トレースの出力先はTraceListenerによって管理されています。 上記のようにOutputDebugString APIに出力するのは、System.Diagnostics.DefaultTraceListenerクラスです。 名前のとおり、何もしないとこのクラスが使われます。 他にSystem.Diagnostics.TextWriterTraceListenerクラスとSystem.Diagnostics.EventLogTraceListenerクラスが用意されています。

using System;
using System.Diagnostics;

public class Test {
    public static void Main(string[] args) {
        Trace.Listeners.Add(new TextWriterTraceListener("c:\\test.log"));
        
        Trace.WriteLine(TraceTime.Now + "テスト1");
        Trace.WriteLine(TraceTime.Now + "テスト2");
        Trace.WriteLine(TraceTime.Now + "テスト3");
    }
}

こんな風にMainの頭で登録してやればOKです。 TraceListenerは、いくつでも登録できます（実際、上のサンプルだとDefaultTraceListenerとTextWriterTraceListenerの2つが登録されてることになります）。 必要に応じて好きなだけ登録してください。
もちろん、自分好みのTraceListenerを作ることもできます（まだ、作ったことありませんが）。

って、実はコードを書かなくてもアプリケーション構成ファイルに書いとくだけで同じことができたりします。

アプリケーション構成ファイル

アプリケーション構成ファイルを用意すれば、TraceListenerの追加が簡単にできます。 アプリケーション構成ファイルっていうのは、アプリケーション名＋".config"という名前（たとえば"test.exe.config"）のXMLファイルのことです。 もちろん、exeと同じディレクトリになくちゃダメです。
アプリケーション構成ファイルのスキーマ（タグの規則）はリファレンスに載ってます。 TraceListenerを追加するには、

<?xml version="1.0" encoding="Shift_JIS" ?>
<configuration>
    <system.diagnostics>
        <trace autoflush="true" indentsize="4">
            <listeners>
                <add name="myListener" type="System.Diagnostics.TextWriterTraceListener" initializeData="c:\test.log" />
                <remove type="System.Diagnostics.DefaultTraceListener"/>
            </listeners>
        </trace>
    </system.diagnostics>
</configuration>

こんな感じです。 この例では、TextWriterTraceListenerを追加してDefaultTraceListenerを削除しています。 これを用意しておくだけで、

    public static void Main(string[] args) {
        Trace.Listeners.Add(new TextWriterTraceListener("c:\\test.log"));

この太字のところを.NET Frameworkが自動的にやってくれます（なので、自分でやる必要はありません）。

注意
サンプルなんかでは<trace autoflush="false" ...>としてる例が多いですが、autoflush="true"としとかないとうまくログに書けないときがあるようです。
同じくサンプルなんかでは<add ... type="System.Diagnostics.TextWriterTraceListener,System" ...>としてる例が多いですが、type="System.Diagnostics.TextWriterTraceListener"としてやらないと例外が出てしまいます。 ただ、ここは「完全限定型名」を書かなくちゃいけないんで、本当は"System.Diagnostics.TextWriterTraceListener,System"が正しいと思うんですが。なぜ、アセンブリ名を書くと例外が出るのかはよくわかりません。
TextWriterTraceListenerで書かれたログはUTF-8になってます。なので、UTF-8に対応したエディタなどで見ないと日本語が化け化けになるので注意してください。

Switchとか

他にもトレースを制御するSystem.Diagnostics.BooleanSwitchクラスやSystem.Diagnostics.TraceSwitchなんかもあります。 この辺は、リファレンスを見てみてください。