EtwStream - ETW/EventSourceのRx化 + ビューアーとしてのLINQPad統合

EtwStreamというのをリリースしました。ETW(Event Tracing for Windows) + EventSourceが.NETで構造化ログをやる際の決定版というか、ETWの最強度が高すぎてそれ以外考えられないレベルなんですが、しかし、がETWは最強な反面ビューアーがありませんでした。ETWというブラックホールにログを投げ込むのはいいんですが、それが自分自身ですら容易に見れないのは不便すぎる！PerfViewとか骨董品みたいなゴミUIを操ってなんとかして見るのは、無理ゲーなわけで、カジュアルにDumpしたいだけなんだよ！テキストのようなログビューアーが欲しいだけなんだよ！に対する答えです。いや、ほんと自分自身が死ぬほど欲しかったのが、これ。

インストールはLINQPadのNuGetで「EtwStream.LinqPad」。だけ。デフォルトにでも登録しとけばLINQPadを立ち上げるだけですぐにビューアーに！

EtwStreamが提供するのは、ETWをIObsevable[TraceEvent]に変換することです。Logs are streamsですから、そしてストリームといったらRxですから。あとは、LINQPadのDumpをそのまま流用して、色付けとか加えてあげただけです。フィルタリングしたい？グルーピングしたい？色々混ぜたい？そんなの全部Rxなんだから、ちょっとクエリ書けばいいだけなのです。最強の柔軟性がある。

Observable.Merge(
    ObservableEventListener.FromTraceEvent("LoggerEventSource"),
    ObservableEventListener.FromTraceEvent("MyCompanyEvent"),
    ObservableEventListener.FromTraceEvent("PhotonWire")
)
.DumpWithColor(withProviderName: true);

EventSourceの提供する構造化ログ(Structured Logging)に関してはC#における構造化ログの手法、そしてデータ可視化のためのDomoの薦めで書いたのでそっちを見てくださいな。そうしてEventSourceに移行した場合の最大の懸念であるビューアーがなさすぎ問題を、このEtwStreamが解決します。た。

ちなみについでにTailっぽくファイルもIObservable[string]に変換するObservableEventListener.FromFileTailもオマケとして入れといたので、そっちもそっちでログビューアー的に使うならきっとベンリ。

もしEventSourceを使ったロギングをやっていなくても、.NET標準組み込みの、例えばTplEventSourceあたりを眺めてみると、色々な挙動が見えて面白かったりします。あとFromClrTraceEventではGCやThraedPoolの挙動が見れたり、FromKernelTraceEventで普段絶対気にしないカーネルイベントが凄まじい勢いで流れて行ったりが簡単に観測できて、普通に勉強になります。オモチャとしてかなり良いと思いますねー。

最初のEventSource

EventSourceって何のことだかさっぱりわからん！という人におすすめなのがLogging What You Mean: Using the Semantic Logging Application BlockというMSDNに転がってるSLABのドキュメントです。これはさすがにひじょーによく書けてるしいいですね。あと、EtwStreamが提供してるのはObservableEventListenerだけで、ロガー的なファイル書き出しとかは一切ないので、そういうのやりたい人は普通にSLAB「も」使いましょう。という感じです。

さて、EventSourceですが、いきなり構造化ログってのもかなりダルいので、まずは非構造化ログをEventSourceで実現するところから初めてみましょう。いや実際それに、こういういのがちょっとあるとそれはそれでベンリでもありますし。

[EventSource(Name = "LoggerEventSource")]
public class LoggerEventSource : EventSource
{
    public static readonly LoggerEventSource Log = new LoggerEventSource();

    public class Keywords
    {
        public const EventKeywords Logging = (EventKeywords)1;
    }

    string FormatPath(string filePath)
    {
        if (filePath == null) return "";

        var xs = filePath.Split('\\');
        var len = xs.Length;
        if (len >= 3)
        {
            return xs[len - 3] + "/" + xs[len - 2] + "/" + xs[len - 1];
        }
        else if (len == 2)
        {
            return xs[len - 2] + "/" + xs[len - 1];
        }
        else if (len == 1)
        {
            return xs[len - 1];
        }
        else
        {
            return "";
        }
    }

    [Event(1, Level = EventLevel.LogAlways, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void LogAlways(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(1, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(2, Level = EventLevel.Critical, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Critical(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(2, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(3, Level = EventLevel.Error, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Error(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(3, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(4, Level = EventLevel.Warning, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Warning(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(4, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(5, Level = EventLevel.Informational, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Informational(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(5, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(6, Level = EventLevel.Verbose, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Verbose(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(6, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(7, Level = EventLevel.Error, Keywords = Keywords.Logging, Version = 1)]
    public void Exception(string type, string stackTrace, string message)
    {
        WriteEvent(7, type ?? "", stackTrace ?? "", message ?? "");
    }

    [Conditional("DEBUG")]
    [Event(8, Level = EventLevel.Verbose, Keywords = Keywords.Logging, Message = "[{2}:{3}][{1}]{0}")]
    public void Debug(string message, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        WriteEvent(8, message ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [NonEvent]
    public IDisposable MeasureExecution(string label, [CallerMemberName] string memberName = "", [CallerFilePath] string filePath = "", [CallerLineNumber] int line = 0)
    {
        return new StopwatchMonitor(this, label ?? "", memberName ?? "", FormatPath(filePath) ?? "", line);
    }

    [Event(9, Level = EventLevel.Informational, Keywords = Keywords.Logging, Message = "[{0}][{2}:{3}][{1}]{4}ms")]
    void MeasureExecution(string label, string memberName, string filePath, int line, double duration)
    {
        WriteEvent(9, label ?? "", memberName ?? "", FormatPath(filePath) ?? "", line, duration);
    }

    class StopwatchMonitor : IDisposable
    {
        readonly LoggerEventSource logger;
        readonly string label;
        readonly string memberName;
        readonly string filePath;
        readonly int line;
        Stopwatch stopwatch;

        public StopwatchMonitor(LoggerEventSource logger, string label, string memberName, string filePath, int line)
        {
            this.logger = logger;
            this.label = label;
            this.memberName = memberName;
            this.filePath = filePath;
            this.line = line;
            stopwatch = Stopwatch.StartNew();
        }

        public void Dispose()
        {
            if (stopwatch != null)
            {
                stopwatch.Stop();
                logger.MeasureExecution(label, memberName, filePath, line, stopwatch.Elapsed.TotalMilliseconds);
                stopwatch = null;
            }
        }
    }
}

ちょっと長いですが、これで

LoggerEventSource.Log.Debug("ほげほげ!");

とか書いていくだけです。それを書いたアプリを、LINQPadでは

ObservableEventListener.FromTraceEvent("LoggerEventSource").DumpWithColor();

で、ファイルとかを通さずそのままストリームで外から観測できます。

Logs are event streams

脱ファイル。ちなみにETWで流したのは最終的にBigQueryに流すのが超おすすめですね！そしてLINQ to BigQuery + LINQPadで解析する。完璧！これがC#の次世代ログのあるべき姿だ！と、オモイマス。というか逆にもう以前には戻れないかなあ、やっぱり世代が一つ変わった感あります、便利度が全然違うので。