Roslyn C# Scriptingによる実行できるコンフィグの手法と実活用例
- 2015-12-13
Advent Calendar大遅刻組です。というわけでC# Advent Calendar 2015の10日目です！なんで遅刻したかというと、記事のネタのためのライブラリを作るのに思いの外時間がかかってしまったから…… コンセプトも固まってたしプロト実装も済んでたんですが、最終的な形に落としこむのが想定よりちょっと割と大変だった……。すびばせんすびばせん。
どうやらC# Advent Calendarは2011年から書いてるので5回目ですね、へぇー。過去を振り返るとModern C# Programming Style Guide、モダンつってもC# 4.0時代ですが、今ぱっと見直すと別にここで言ってることは今も変わらないですね、これに5.0, 6.0の話を足せばいいだけの話で。2012年はMemcachedTranscoder - C#のMemcached用シリアライザライブラリということで、このライブラリは別に私自身も使ってないので割とどうでもいー、んですが、まぁシリアライザにまつわる諸々についての知見が少しは入ってる模様。2013年の非同期時代のLINQはいい話だなー、これがC# 5.0のModern Styleの追記差分みたいなもので、実際、今現在においては超絶大事な部分。2014年はVS2015+RoslynによるCodeRefactoringProviderの作り方と活用法で、C# 6.0ではないですが、その世代ではAnalyzerは中心になってくるので、これがC# 6.0の差分といってもいいでしょう。多分きっと。
Roslyn C# Scripting
Roslyn、Compiler as a Serviceとか言ってましたが、やっぱスクリプティングが華形だと思うのです。が、しかし。が、しかし。今の今までRoslynに関する話題で、Scripting APIに関するお話はあまり上ってませんでした。理由は単純で、今の今まで未完成品だったから。先月末に出たVisual Studio 2015 Update 1でC# Interactiveが、そして同時にNuGetでもMicrosoft.CodeAnalysis.CSharp.Scriptingで、現在は1.1.1が配布されることにより（ところでこれのパッケージ名が中々定まらなくて実際これであってるのか不安だけどLast updatedが2015/12/3なのでこれでいいでしょう、まだDL数が405ですけど！）やっと全てのピースが揃った感じです。
Scriptingについてのドキュメントは、RoslynのWikiにある2つのページを見ておけば十分でしょう。Interactive-Windowには、csxの仕様っぽいもの、特殊なDirectiveの説明があります(#rとか#loadとか)。Scripting-API-Samplesにはプログラムから触った時のAPIとしてどんなものを持ってるか、どういう風に使えるかが書いてあります。かなりシンプルなので、そんな難しくなくすぐ使えます。
ちなみにC# Interactiveはまだまだ全然使えないって感じなので、期待するほどのものでもないですね。csxもエディタサポートが実質、シンタックスハイライトぐらいなので厳すぃ。黙ってLINQPad使いましょう、課金しましょう。
Roslyn時代のコンフィグ
最近というか数年前からずっと構造化ログにご執心で、EtwStream - ETW/EventSourceのRx化 + ビューアーとしてのLINQPad統合というのを作ってたんですが、今回はそれに、ファイル等への出力プラグイン(Sink)と外部サービス(EtwStream.Service)を作りました。アプリケーションから出力されるログは、ETWというWindows内部に流れてる高速なロギングストリーム機構を通して、別プロセスのEtwStream.Serviceで受け取ります。ログは特に最近ではファイル出力など比較的安定性が保証されているものだけでなく、ネットワークを通じて配信するケースも少なくありません。ログの扱いが別プロセスに別れることにより、アプリケーションに与える影響が少なくなるほか、アプリケーションの状態(アプリ自体の終了/デプロイでの入れ替わり等)に気を配る必要もなくなります。
というのが外部サービスであることの意義なのですが、問題はコンフィグです。コンフィグ。元々EtwStreamはObservableEventListenerという、IObservble<LogEvent>の形でログをストリームで受け取り、それをRxで自由にフィルタしたりグルーピングしたりマージしたりなんでも出来ますよね、という究極の自由度がウリでした。しかしコンフィグです、Rxのその柔軟性をコンフィグで実現するのは不可能です。物凄く機能を削った単純なSubscribeで我慢するか、あるいは超絶複雑なXMLでそれっぽいものを構築するか(log4netやNLogのXMLコンフィグが死ぬほど難解で複雑なのは、ログのルーティング自体が複雑で、それをコンフィグで表現することが困難だということなのです）になります。
せっかく、ログを現代的なReactive Extensionで表現することができたのに、外部サービスにした途端に破棄しなければならないのか。それでいいわけがなく、そこでC# Scriptingの出番になります。EtwStream.Serviceはコンフィグをconfiguration.csxとして、以下のように書きます。
// configuration.csx
// 5秒 or 1000件でバッファリング(ふつーのRxのBufferを利用)
// 出力フォーマットは普通にFunc<TraceEvent, string>で整形できる！
ObservableEventListener.FromTraceEvent("SampleEventSource")
.Buffer(TimeSpan.FromSeconds(5), 1000, EtwStreamService.TerminateToken)
.LogToFile("log.txt", x => $"[{DateTime.Now.ToString("yyyy/MM/dd hh:mm:ss")}][{x.Level}]{x.DumpPayload()}", Encoding.UTF8, autoFlush: false)
.AddTo(EtwStreamService.Container);
基本的に完全にC#そのものなので、全てのRxのメソッドが使えて自由に合成・ルーティングが可能です。これはIn-Processで書いてる際（普通のロガーとしてC#コードで埋め込む場合）もOut-Of-Process Serviceでコンフィグとして書く場合も（ほぼ）同じコードで表現できるということです。もちろんC#で書けるということは、 System.Configuration.ConfigurationManager.AppSettings から設定を引っ張ってきたり、ネットワーク通信して何か引っ張ってきたりとかも自由自在やりたいほーだいです。
例えばこれをNLogで表現すると
<targets>
<default-wrapper xsi:type="BufferingWrapper" bufferSize="1000" flushTimeout="5000" />
<target name="file" xsi:type="File" fileName="log.txt" keepFileOpen="true"
layout="[${date:format=yyyy/MM/dd hh\:mm\:ss}][${level}]${message}" />
</targets>
<rules>
<logger name="*" minlevel="Debug" writeTo="file" />
</rules>
になります。NLogの独自フォーマットルールに従って書く必要があるし、メッセージ書式も独自テンプレートになります。とはいえ、これはまだ単体なので遥かにマシで、色々複合的なことをやろうとするとすぐに膨れ上がって意味不明なことになるのは、みんな経験のあることなのではないでしょうか？
バイナリがEtwStream/releases/EtwStream.Serviceに転がってるので、是非ちょっとだけ遊んでみてくださいな。
仕組み
csxをEvaluateしてるだけです。基本的にcsxの実行は即座に終わります、ObservableEventListenerをSubscribeしているだけですから。しかし、csxが終了してもSubscribeは生き続けています！（言われてみると当たり前のようで、最初はそうなの？と違和感はありました）。それにより、流れてくるログは（別スレッド上の)ObservableEventListenerを流れて、csx上のRxを通りcsx上でのSubscribeにより処理され続けます。というわけで、EtwStream.Serviceのcsxは、ただのXMLコンフィグがcsxに変わっただけ、ではなく、このcsxはコンフィグのようでコンフィグじゃなく、実行コードそのものなのです！
終了処理に関しては、ホスト側から渡しているTerminateTokenと、AddToを通してSubscriptionを登録していることにより制御されています。csxの評価としての実行が終わっていても、裏で生き続けている限り同じ参照を持っているので、ホスト側から干渉することが可能です。なので、ServiceのStopイベント時にはTerminateTokenにCancel命令をホストが出すことにより、Rxの残ってるBufferが送り出され、AddToで受け取っているSubscriptionを待つことにより、溜まったログの処理が完了するまで待機するといった、安全な終了処理を可能にしています。この辺はRxをフル活用してパイプライン組んだ成果ということで。
再びエディタとしてのLINQPad
さて、csxで書けるところのイイトコロはC#なのでコンパイルエラーも検出できるしシンタックスハイライトもあるし、などなど、なのですが、エディタサポートは……。Visual Studio 2015のUpdate 1によって確かにシンタックスハイライトはついた、が、それだけ……。IntelliSenseもDLL読み込ませたり色々しなければなので実質使えないみたいなもので厳しい……。
そこで出てくるのがLINQPad。
EtwStream.LINQPadには、EtwStream.Serviceのcsxで渡されてくるEtwStreamServiceクラスのShim成分が入っているので、csxと互換性があって、LINQPadで実際にコンパイルできる/動かして確認した結果をcsxに持っていくことが可能です。（というようなことが出来るようにAPIを調整したんです……）。C# Interactiveが使い物にならならいなら使い物になるまで我慢する、のではなくて、一時凌ぎでもなんでも、他の現実的な解法を探すのが正すぃ。クソだクソだと文句だけ言ってても何も動きませんしね。必要なのは今この場でどうするか、それだけ。
Topshelf
Windowsサービスの実装にはTopshelfというライブラリを用いています。これは、最高に良いです。もはやこれなしでWindowsサービスを実装するのは考えられません！Visual Studioのテンプレートからふつーにサービスを作ると、なんかゴチャゴチャしたのが吐かれてよくわからない上に実行も面倒だし（いちいちinstallしたくないでしょ？）デバッグも困難だし、実にヤバい最低な開発環境。Topshelfで作るとコンソールアプリケーションと同じ感覚で作れます。また、成果物のexeは、そのまんまふつーにコンソールアプリケーションとしても動くので、EtwStream.Serviceの場合、ビューアーとしてLINQPadを要求していましたが、EtwStream.Service.exeを実行すれば普通にビューアーになります(csxで書き出し先をConsole(LogToConsole)にすれば色分けもしてくれる）。サービスとしてのインストールは「install」をつけて実行するだけ。素晴らしい。
日本語ではWindowsサービスを楽に開発～TopShelf～やTopShelf によるWindowsサービスの配置をDSCで自動化してみように説明ありますが、本当に簡単なので、サービスを作る機会がある人は是非使ってみてください。超お薦め。
ファイル出力時のロガーのパフォーマンス
今回ロガーを全部自作する都合上、さすがに単純なファイル書き出しと、ローテーションするファイル書き出しは用意しとかないとなぁ、ということで作ったんですが(FileSink, RollingFileSink)、作ってる上でなんとなく気づいたことなど。
そもそもファイルに吐くっていうこと自体がレガスィーで好きじゃないんですが、それはそれとしてもやはり重要なのは間違いありませんし、普通に使います。で、特にInProcessでのロギングの場合、これに気を配らないと普通にパフォーマンス上のボトルネックになってしまったりするわけですねー。さて、で、パフォーマンスは設定が全てです。とりあえず、バッファリングと非同期の二つのオプションを探しましょう。まず、ファイルに吐く場合のパフォーマンスはバッファするかしないかで全く変わるし、逆にバッファさえすればよほどタコな実装じゃない限りはそんな差はなくふつーに性能出ます（多分）。もう一点はasyncですね、これは別に大抵は非同期I/Oじゃなくて別スレッドで書くってだけのパターンなんですが、これが有効だとロガーの動作がアプリケーション自体に一切影響しなくなりますので。まぁバッファを有効にしてれば、例えば1000件に一回書く設定だったら1/1000回以外は書き込み処理に時間喰われることはなくなるので、ほぼ無視できてあってもなくても大差なくなるんですが、（起こるかもしれない）ちょっとしたスパイクは抑制できるかもしれません。また、あえてバッファはオフにしてasyncだけオン（+即時Flush)にすれば、ログが中々Flushされなくてリアルタイムで確認したいのにイライラ、というのがなくなって良いかもしれません。この辺は好みとか要件しだいで。
とりあえず言えるのはデフォの設定がどうなってるかはともかく、ノーバッファでノーエーシンクだと当然のように遅いです。更に設定によってはファイルストリームを都度閉じるか開きっぱがオプションになってるものもありますが、これは当然、開きっぱじゃないとゲロ遅いです。そういう項目がオプションにある場合は注意しましょう。デフォが都度閉じるだったりしてね……(NLogがそうです。NLogのデフォルトは安全寄りに倒し過ぎでパフォーマンスがヤヴァいことになってるので、NLog使う場合はそれなりに弄ったほうがいいでしょう。かといって他のロガーもそう変わりはなくて、大抵はそれなりに弄らないと遅いです）
かわりに、バッファや非同期ってのはログの消失の危険性があります。書いた瞬間には保存されてないってことですからね、アプリケーション終了への耐性が低くなります。気の利いたロガーは、可能な限り、終了を検知して(AppDomainが消える時のイベントとかをハンドリングして)、残ってるバッファを出力しに行ったり非同期の終了を待機しに行ってくれたりはしますが、パーフェクトではありません。例えばAppDomain.ProcessExitのタイムアウトは既定で2秒です。2秒以内にフラッシュが完了する保証はないわけで、そこで完了できなければログロストです。
それを避けるには、「パフォーマンス低下を承知してバッファや非同期オプションを使わない」というのも手ですが、EtwStreamは更に2つの選択肢を提供してます。一つは「Out-Of-Process Serviceでのログ収集」。ETWへのログ出力はほぼノーコストで即時に吐けるのでアプリケーションへの影響は一切無い上に、それを外部サービスで取り出せば、出力側の終了の影響を全く受けません。ただし当然、受け取る側の外部サービスが死んだらロストするという危険性はありますがね！そこに関しては知らんがなというかshoganaiというか精一杯堅牢性を高めますとしか言い様がないですにぇ。
もう一つは、プログラム的に終了が完全に待機できるSubscriptionシステム。もともとEtwStreamは設定をC#で、Rxで書く必要があるので、購読状態に関して100%コントロールできます。というわけでその辺に仕掛けを入れといて
static void Main()
{
// ApplicationStartの部分でこの2つを用意する
var cts = new CancellationTokenSource();
var container = new SubscriptionContainer();
// でログの設定する
ObservableEventListener.FromTraceEvent("SampleEventSource")
.Buffer(TimeSpan.FromSeconds(5), 1000, cts.Token)
.LogToFile("log.txt", x => $"[{DateTime.Now.ToString("yyyy/MM/dd hh:mm:ss")}][{x.Level}]{x.DumpPayload()}", Encoding.UTF8, autoFlush: false)
.AddTo(container);
// --- 実際にアプリが動いてる部分 --- //
// アプリが終了した時のイベントのところでハンドリングする(Form_ClosedでもApplication_Endでもなんでもいいですが)
cts.Cancel(); // CancellationTokenのCancelによりBufferの残りが吐き出される
container.Dispose(); // Subscriptionの完了を待機する
}
といった風にすれば、100%コントロールされて停止時のログ処理を完了させられます。csxでもEtwStreamService.TerminateTokenとか渡していたのと同じことをやればいいということで。
100%コントロールできる代わりに、逆にEtwStreamは自分でコントロールしないかぎりは、気の利いた終了の検知とか組み込んでないので、待たなければふつーにバッファは消えます。これに関しては、10年前はゴテゴテとブラックボックスの中で気の利いたことをしてくれるのが正義だったかもしれませんが、2015年の現代では仕組みはシンプルに、薄くしたうえで、自分でコントロールさせるのが正義だと思ってます。そういう流儀。どっちが正しいってこともないですが、まぁ、今風なんじゃないかな？
ついでに言えば、EtwStreamのFileSinkやRollingFileSinkのパフォーマンスはバッファしてる前提同士で比較しても、他のよりも高い性能を誇ります。理由は幾つかあって、そもそも性能を意識して書いてるから。というのと、.NET 4.6以外をサポートする気がないのでasync/awaitやTPL全開でコードを書いてるから。オプション自体も同期処理は一切なくて、書き出しは非同期I/Oのみに限定などの割り切り。そして、通常はログフォーマット整形などに独自テンプレート的なのを挟まなきゃいけないところを、csxのお陰でFuncで処理できるため、そもそもコードパスに一切のオーバーヘッドがない。C# Scriptingによるコンフィグはパフォーマンスにも寄与するわけです。
しかしまぁ、JavaではBlitz4jやlog4j2のAsynchronous Loggerなどのスピード競争があるのに、.NETの牧歌的なこと、といった感じは否めませんねぇ。そんなだから私のとりあえずの雑実装でもfastestになってしまうわけで……。
出力先
EtwStreamが提唱するのは構造化ログ(Structured/Semantic Log)ですし、テキストログが終着点ではありません！テキストログは無視して、構造化されたペイロードを、そのままAzure EventHubsやAmazon Kinesis、Google BigQueryのStreaming Insertに流して、ただたんに溜めるのではなくて、即座に分析可能な状態にするのが理想形です。特にお薦めなのは、というか弊社で使ってるのはGoogle BigQueryです。事例として株式会社グラニの Google Cloud Platform 導入事例: 「using CSharp;」という軸と BigQuery の活用で、先進性を求め続ける。を掲載してもらいました:)
今のとこEtwStream用のBigQuerySinkはないんですが（！）そのうち公開するかされるかするんじゃないでしょーか多分きっと。（本当はそれも作って持ってきたかったんですがもう完全に時間切れでして、すでに大遅刻だし……）。そういえばあとFromTraceEventでRegisteredTraceEventが取れるようになりました。これはつい数日前のTraceEventライブラリのアップデートでそうなったから、というだけなんですが、今まで取れてなかったんですよねー。これで大丈夫。というのと、SLABのOut-of-Process Serviceじゃダメな理由に.NET 4.6からEventSourceに追加されたself-describing events（超重要！）に対応してないとか色々あるんですが、そういった話はまたの機会にでも。
まとめ
ロガーの未来はこうあるべきだ、という構想自体は1年以上前からあったんですが、Roslyn C# Scripting APIが正式リリースされてやっと作れた！あと、基本的にはMicrosoft Patterns & PracticesのSemantic Logging Application Block(SLAB)の影響が濃くはあるんですが、更新されなすぎだし、v3はElastic Search + LogStash + Kibana on Azureとか言ってて、マジで終わってるなという感じでもはや見限るしかない……。P&Pは相変わらず本当にやっぱダメですねーという残念さ加減。なにがPatterns & Practicesだよっていう。
csxでコンフィグするライブラリとしてConfigRというのがあるんですが、XMLをcsxで置き換えるだけじゃ、あんま意味がないかな。必要なのは、コンフィグができることじゃなくて、それそのものが実行されて自走することだというのに気づいたので、使うことはなかったし、多分他のアプリケーションでもConfigRを使うことはないと思います。XMLはいうて設定ファイルとしては悪くないんですよねー、XSLTなんかもやり過ぎなければ良い機構ですし。逆にJSONを設定ファイルとして使うのは最低最悪なチョイス(なのでDNXへのやる気が0.1ミリも起きない)
何れにせよ、徐々にではあるでしょうが、csxの面白い活用例というのはどんどん出てくるのではないかと思います、と言いたいんですがfsxが別に対して面白い活用はされてないことを考えるとそんなに出てこないかもしれませんね、とも思いますが、いえいや面白い活用例はやっぱ出てくるかもしれません。batをcsxにしましたとかってだけだと別に面白くもないし意味もそんなにないですからねー、まぁあってもいいけど。もっと本質的に変わるような事例が増えてくれれば何よりです。