TraceListener into MongoDB

たまには週間たけはらブログ。
ASP.NETでTraceListener使ってますか？今まで結構仕込んでおいたんだけど、ファイルやイベントログだと扱いにくいなー、なんて思ってませんか。思ってました。融通効かないなー、と。大規模サイトなんかでSQLServerに入れちゃうと、大変なことにナチャウヨ。
そこでMongoDB。みんな大好きMongoDB。ドキュメントの日本語化も着実に進んでるので、英語なんてー、と気にすることもあんまりないでしょう。そーでもないですか？いろいろ可愛いやつですよ！ログデータの保持なんて、もう、得意中の得意です。保持する構造さえちゃんとしておけば、RDBじゃ処理しにくいものもお気楽に扱えます。用途と使い方次第デスけどね。
Home - Docs-Japanese - 10gen Confluence
MongoDBって何よ？っていうのは、いろいろ検索してね。
MongoDB と NoSQL を試す
MongoDB と NoSQL を試す (第 2 部)
MongoDB と NoSQL を試す (第 3 部)
開発環境で超簡単な使い方はコンソールでmongodを起動しておいて、mongoで中身を確認。

だんだんmongodをサービス起動しておきたくなりますが、最初は単なるプロセス起動。もちろん、内容確認をコンソールのmongoで行うのも、ハッカーみたいな雰囲気あっていいかもしれないけど、そんなの面倒なので実際はGUIのツールを使いましょう。
MongoVUE | Gui tools for MongoDB

他にもイロイロあるので、気に入ったのを選んで試してみましょう。
Admin UIs – MongoDB
このMongoDBにTraceListenerからmessageを保存するようにしちゃいましょー！
開発するならHTTPでのREST操作(MongoDBに最初からあります)よりも、Driverを使った開発のほうが楽チンぽんです。前までは、いろいろ使い勝手の問題もあったりとかしたけど、いまとなっては標準公開されてるもので十分です。
CSharp Language Center – MongoDB
CSharp Driver Tutorial - MongoDB
英語かよ！どんまい。
マニュアル - Docs-Japanese - 10gen Confluence
なんにせよNuGetで取得できるのが便利なところです。
Official MongoDB C# driver - 1.2 : NuGet gallery
TraceListenerって自分で用意したことなかったんだけど、TraceListenerクラス派生でいいってことなので、お手軽ですね。必須なoverrideも2個だけ。

public override void Write(string message)
{
  // ...
}

public override void WriteLine(string message)
{
  // ...
}

やれそうですね。
えいやっ！

using System.Configuration;
using System.Diagnostics;
using MongoDB.Bson;
using MongoDB.Driver;

namespace MongoListener
{
  public class MongoDbTraceListener : TraceListener
  {
    private readonly MongoServer _server;
    private readonly MongoDatabase _database;
    private readonly string _collectionName;

    public MongoDbTraceListener() : this("TraceData") { }
    public MongoDbTraceListener(string initializeData)
    {
      _collectionName = initializeData;
      var serverName = ConfigurationManager.AppSettings["MongoDb:Server"];
      var databaseName = ConfigurationManager.AppSettings["MongoDb:Database"];

      if (string.IsNullOrEmpty(serverName))
          serverName = "mongodb://localhost";

      if (string.IsNullOrEmpty(databaseName))
          databaseName = "TraceListener";

      _server = MongoServer.Create(serverName);
      _database = _server.GetDatabase(databaseName);
    }

    private void Insert(BsonDocument document)
    {
      var collection = _database.GetCollection(_collectionName);
      collection.Insert(document);
    }

    private void InternalWrite(string message)
    {
      var document = new BsonDocument {{"Message", message}};
      Insert(document);
    }

    private void InternalWriteObject(object o)
    {
      var document = new BsonDocument();
      
      var type = o.GetType();
      foreach(var prop in type.GetProperties())
      {
          document.Add(prop.Name, prop.GetValue(o,new object[]{}).ToString());
      }
      Insert(document);
    }

    public override void Write(string message)
    {
      InternalWrite(message);
    }

    public override void WriteLine(string message)
    {
      InternalWrite(message);
    }

    public override void WriteLine(object o)
    {
      var type = o.GetType();
      if (type.Name.StartsWith("<>") && type.Name.Contains("AnonymousType"))
      {
          InternalWriteObject(o);
          return;
      }
      InternalWrite(o.ToString());
    }
  }
}

できたー。
後は、web.configに書いて使えるようにするだけですね！

  <appSettings>
    <add key="webpages:Version" value="1.0.0.0"/>
    <add key="ClientValidationEnabled" value="true"/>
    <add key="UnobtrusiveJavaScriptEnabled" value="true"/>
    
    <add key="MongoDb:Server" value="mongodb://localhost"/>
    <add key="MongoDb:Database" value="TraceListener"/>
  </appSettings>

<system.diagnostics>
  <trace autoflush="false" indentsize="4">
    <listeners>
      <add name="mongoListener" 
           type="MongoListner.MongoDbTraceListener, MongoListner"
           initializeData="MyTrace" />
      <remove name="Default" />
    </listeners>
  </trace>
</system.diagnostics>

  <system.web>
    <trace enabled="true"/>

あとはSystem.Diagnostics.Trace.Write/WriteLineです！すでにたくさん仕込んでいる場合にはコレでOK。
ASP.NET MVC3標準プロジェクトを作成して、MongoDbTraceListenerクラスを作成し、HomeControllerのIndexアクションにTraceを書いてみましょう。

わーお！素敵！！
MongoDBが違うマシンだったり(本番はそうしましょう)、Database名を変更したいときはappSettingsの値を変えてね。コレクション(テーブル相当)の名前を変えたかったらtrace/listnersのinitializeDataで指定してね。
ちなみに、これだけだとつまんないので、ここから少し拡張してパフォーマンス計測してみましょう。まずはIHttpModuleを実装して、リクエストの処理時間を計測するようにしてみます。
mvc-mini-profiler - A simple but effective mini-profiler for ASP.NET and WCF - Google Project Hosting
↑パフォーマンス計測ならこんな素敵なもの(NuGit.orgで実物見れますよ～)もありますが．．．。これから新規ならこっちのほうが．．．。いや、言うまい。

どりゃ！

using System;
using System.Collections.Generic;
using System.Diagnostics;
using System.Linq;
using System.Web;

namespace MongoListner
{
  public class PerformanceTraceModule : IHttpModule
  {
    private string ItemKey = "_mongoDbTraceStart";
    private readonly string _serverName = "";

    public PerformanceTraceModule()
    {
      _serverName = Environment.MachineName;
    }

    public void Init(HttpApplication context)
    {
      context.BeginRequest += new EventHandler(context_BeginRequest);
      context.EndRequest += new EventHandler(context_EndRequest);
    }

    void context_BeginRequest(object sender, EventArgs e)
    {
      var httpContext = (sender as HttpApplication).Context;
      var startTime = httpContext.Items[ItemKey] = DateTime.Now;
    }

    void context_EndRequest(object sender, EventArgs e)
    {
      var httpContext = (sender as HttpApplication).Context;
      var startTime = (DateTime)httpContext.Items[ItemKey];

      Trace.WriteLine(new
      {
        Server = _serverName,
        RequestAt = startTime,
        Method = httpContext.Request.HttpMethod,
        Status = httpContext.Response.StatusCode,
        RawUrl = httpContext.Request.Url.ToString(),
        Milliseconds = (DateTime.Now - startTime).Milliseconds
      });
    }

    public void Dispose()
    {
    }
  }
}

これを利用するためにsystem.webServer/modulesに登録します。

  <system.webServer>
    <validation validateIntegratedModeConfiguration="false"/>
    <modules runAllManagedModulesForAllRequests="true">
      <add name="mongoListener" 
           type="MongoListner.PerformanceTraceModule, MongoListner" 
           preCondition="integratedMode"/>
    </modules>
  </system.webServer>

実行してみます。

BeginRequestからEndRequestの間を計測するものですが490msって．．．。遅すぎ！

と、思ったらF5リロードの2回目は5ms。そーだろそーだろ。ん？よく見たらStatusとMillisecondsがstringになってるー。TraceListenerのInternalWriteObjectでToStringしてたね。失敬。そこは修正しましょう。書きながら作る、作りながら書く！

private void InternalWriteObject(object o)
{
  var document = new BsonDocument();
  
  var type = o.GetType();
  foreach(var prop in type.GetProperties())
  {
    var value = BsonValue.Create(prop.GetValue(o,new object[]{}));
    document.Add(prop.Name, value);
  }
  Insert(document);
}

これでちゃんと型どおり。BsonValueにはいろいろあるのでドキュメント参照してみてください。
このHttpModuleがあればすべてのリクエストの処理時間が計測できますね！アクセスログのTimeTakenとダダカブリ。どんまい。
IIS 6.0 ログ ファイルの Time Taken フィールドは何を表し、何を意味していますか。 : IIS 6.0 についてよく寄せられる質問
ASP.NET MVCならActionFilter属性を使ってControllerでの処理時間とViewの処理時間をそれぞれ別で計測できてなお嬉しいはず。
そいやっ！

using System;
using System.Diagnostics;
using System.Web.Mvc;

namespace MongoListner
{
  public class PerformanceTraceAttribute : ActionFilterAttribute
  {
    private string ItemKey = "_mongoDbFilterTraceStart";
    private readonly string _serverName = "";

    public PerformanceTraceAttribute()
    {
      _serverName = Environment.MachineName;
    }

    public override void OnActionExecuting(ActionExecutingContext filterContext)
    {
      filterContext.HttpContext.Items[ItemKey] = DateTime.Now;

      base.OnActionExecuting(filterContext);
    }

    public override void OnActionExecuted(ActionExecutedContext filterContext)
    {
      var startTime = (DateTime)filterContext.HttpContext.Items[ItemKey];

      Trace.WriteLine(new
      {
          Server = _serverName,
          ProcessAt = DateTime.Now,
          RawUrl = filterContext.HttpContext.Request.Url.ToString(),
          Method = filterContext.HttpContext.Request.HttpMethod,
          Controller = filterContext.RouteData.GetRequiredString("controller"),
          Action = filterContext.RouteData.GetRequiredString("action"),
          Milliseconds = (DateTime.Now - startTime).Milliseconds
      });

      base.OnActionExecuted(filterContext);
    }

    public override void OnResultExecuting(ResultExecutingContext filterContext)
    {
      filterContext.HttpContext.Items[ItemKey] = DateTime.Now;

      base.OnResultExecuting(filterContext);
    }

    public override void OnResultExecuted(ResultExecutedContext filterContext)
    {
      var startTime = (DateTime)filterContext.HttpContext.Items[ItemKey];
      var viewName = (string) null;
      if (filterContext.Result is ViewResult)
      {
        viewName = (filterContext.Result as ViewResult).ViewName;
      }
      Trace.WriteLine(new
      {
        Server = _serverName,
        ProcessAt = DateTime.Now,
        RawUrl = filterContext.HttpContext.Request.Url.ToString(),
        Result = viewName ?? filterContext.Result.GetType().Name,
        Controller = filterContext.RouteData.GetRequiredString("controller"),
        Action = filterContext.RouteData.GetRequiredString("action"),
        Milliseconds = (DateTime.Now - startTime).Milliseconds
      });

      base.OnResultExecuted(filterContext);
    }
  }
}

これを有効にするためにGlobal Filterに追加しておきましょう。
あとは実行するだけ！

ズームして見てね。
Controllerでの実行時間が223ms、ActionResultの実行時間が180ms、HttpModuleでの計測時間が497ms。差が94msありますね。そんなもんでしょう。ちなみにコレが初回実行時の計測で、2回目は↓。

Controllerでの実行時間が0ms、ActionResultの実行時間が0ms、HttpModuleでの計測時間が10ms。差が10ms。これまた、そんなもんでしょう。

こんな感じです！楽しいですね！
途中、MongoDBに入れるDocumentのカラムを変更したりしてるけど、MongoDB側へは何も手を加える必要がないんです。ドキュメント単位(テーブルなら行単位)にカラム構成が変更されてもお構いなしです。ちなみにサーバーさえいればDatabaseもCollectionも初回アクセス時に勝手に作られるので準備は不要。この手軽さと、レスポンス性能の高さがMongoDBの魅力です。
今回のプロジェクト一式は↓こちら。ローカルにMongoDBさえ入っていればそのまま動くはず。

※ファイルを小さくするために、packages/mongocsharpdriver.1.2を消してます。