先頭行に時刻出力をもつ TraceLister の完全なコード

前述のように、TraceListener の実装をすべて行ってもよいのだが、もっと簡単に DefaultTraceListener を継承してほんの数行で作成することができる。
現在時刻の取得は DateTime.Now を利用し、パフォーマンス面の品質管理の一時チェックに利用できる程度の簡易な実行時間計測機能を PerformanceCounter を利用して追加したクラスの全コードは次のようになった。

#region *** (C) El (K.Takaoka) ! el@moonlight.gr.jp

using System;
using System.Diagnostics;
using System.Text;
using System.Runtime.InteropServices;

#endregion

namespace Lady.BUG
{
  public class LogListener : DefaultTraceListener
  {
    #region メンバ変数

    private const           string DEFAULT_FORMAT = "{0,8:f3}";
    private static readonly double msec_pc;

    // このインスタンス固有の設定値
    private bool    logDate     = true;
    private bool    logCount    = false;
    private string  format      = DEFAULT_FORMAT;
    private long    prev_pc;

    #endregion

    static LogListener()
    {
      // １秒で増えるカウント数を取得する
      long secs_pc;
      if (!QueryPerformanceFrequency(out secs_pc)) secs_pc = 0;

      // １ミリ秒のカウント数を計算する
      msec_pc = secs_pc / 1000d;
    }

    public LogListener()
    {
      // 現在のカウンタで前回値を初期化しておく
      QueryPerformanceCounter(out this.prev_pc);
    }

    #region プロパティ

    /// <summary>
    /// ログに日付を追加するかどうか
    /// </summary>
    public bool LogDate
    {
      get
      {
        return this.logDate;
      }

      set
      {
        this.logDate = value;
      }
    }

    /// <summary>
    /// ログにパフォーマンスカウンタの差を追加するかどうか
    /// </summary>
    public bool LogCounter
    {
      get
      {
        return this.logCount && (msec_pc > 0);
      }

      set
      {
        this.logCount = value;
      }
    }

    /// <summary>
    /// ログに表示するカウンタの形式文字列
    /// </summary>
    public string CounterFormat
    {
      get
      {
        return this.format;
      }

      set
      {
        if ((value == null) || (value.Length < "{0}".Length))
          this.format = DEFAULT_FORMAT;
        else
          this.format = value;
      }
    }

    #endregion

    #region TraceListener メンバ

    protected override void WriteIndent()
    {
      this.NeedIndent = false;

      StringBuilder sb = new StringBuilder(32);

      if (this.LogDate)
      {
        // 現在時刻をログに記録する
        sb.Append("[");
        sb.Append(DateTime.Now.ToString("HH:mm:ss"));
        sb.Append("] ");
      }

      if (this.LogCounter)
      {
        // 現在カウンタと前回カウンタの差をミリ秒単位でログに記録する
        long cur_pc;
        QueryPerformanceCounter(out cur_pc);

        double d = (double) (cur_pc - this.prev_pc) / msec_pc;
        this.prev_pc = cur_pc;

        sb.Append("(");
        sb.AppendFormat(this.format, d);
        sb.Append(") ");
      }
      else
      {
        // カウンタだけは更新し続ける。
        QueryPerformanceCounter(out this.prev_pc);
      }

      // インデントの前に時刻およびカウンタを出力する
      this.Write(sb.ToString());

      // インデントを出力する
      base.WriteIndent();
    }

    #endregion

    #region PInvoke defines

    [DllImport("kernel32.dll", SetLastError=true)]
    private static extern bool QueryPerformanceCounter(out long lpPerformanceCount);

    [DllImport("kernel32.dll", SetLastError=true)]
    private static extern bool QueryPerformanceFrequency(out long lpPerformanceCount);

    #endregion
  }
}

このコードは、実際に使っている実装が独自の Switch を用いて app.config ファイルを参照するようになっているため、この日記専用に調整されたものである。

  private static void Main()
  {
    // LogListener を作成
    LogListener logger = new LogListener();

    logger.LogDate     = true;
    logger.LogCounter  = true;
    logger.LogFileName = "test.log";

    // ちょっと強引に設定
    Debug.Listeners.Clear();
    Debug.Listeners.Add(logger);

    // アプリケーション実行
    context = new ApplicationContext(
        new MethodLogger(new Form1()).GetTransparentProxy() as Form1);

    Application.Run(context);
  }

こんな具合に設定して

[20:16:45] ( 287.090) Enter add_HandleDestroyed(value={System.EventHandler})
[20:16:45] (  20.253) Leave add_HandleDestroyed
[20:16:45] (   9.026) Enter set_Visible(value={True})
[20:16:45] (  46.268)     Enter Invalidate()
[20:16:45] (   8.200)     Leave Invalidate
[20:16:45] (  10.566)     Enter Invalidate()
[20:16:45] (   8.773)     Leave Invalidate
[20:16:45] (  14.486)     Enter Open()
[20:16:47] (1708.895)     Leave Open
[20:16:47] (  15.250) Leave set_Visible
[20:17:17] (29985.142) Enter Open()
[20:17:17] (   5.857)     Enter get_IsHandleCreated()
[20:17:17] (   6.302)     Leave get_IsHandleCreated {false}
[20:17:17] (   7.566)     Enter get_Handle()
[20:17:17] (   6.870)     Leave get_Handle {System.IntPtr}
[20:17:17] (   8.804)     Enter get_IsHandleCreated()
[20:17:17] (   7.495)     Leave get_IsHandleCreated {true}
[20:17:17] (   6.273)     Enter CheckFileFormat(fname={"C:\test.txt"})
[20:17:17] (   7.153)         Enter IsCxpFile(str={System.IO.FileStream})
[20:17:17] (   8.107)         Leave IsCxpFile {false}
[20:17:17] (   8.788)         Enter IsCompressCxpFile(str={System.IO.FileStream})
[20:17:17] (   7.324)         Leave IsCompressCxpFile {false}
[20:17:17] (   7.902)     Leave CheckFileFormat {FileFormat.Plain}
    ：

こんなログが取れる、と。