ASP.NETでの定期的なモニタリング手法

cron的な定期実行といったら、タスクスケジューラ使え。完。なわけですが、それとは別にして、アプリケーションサーバー内部からしか分からない情報を定期的に吐き出したいようなシチュエーションにどうしましょうか？例えばスレッドプールの情報！かなり古いのですがHow To 情報: カスタム カウンタを使った ASP.NET スレッド プールの監視方法なんて、まずレジストリに登録して、そこから定期的に無限ループ＋Thread.Sleep（ダセぇ）で出力という、なんともトホホな感じ。いや、これトホホでしょう。というわけで、もっとモダンにいきましょう。

IHttpModuleとInit, Dispose

カスタム HTTP モジュールを作成および登録するということで、IHttpModuleを作成することで、ASP.NETパイプライン上での各イベント時に実行されるものを追加していくことができます。Global.asax.csに直書きでもいいですが、こっちのほうが分離されてる感はありますにぇ。さて、通常はapplication.BeginRequest+=とか、イベント登録するんですが、Application_Startイベントに相当するものは……ありません。はい。ただしかわりにInitメソッドがあります。普段はイベント登録しますが、ここでメソッド実行すれば、それApplication_Startに等しいよねー、と思っていた時もありました。

public class CountModule : IHttpModule
{
    public static int Count = 0;

    public void Init(HttpApplication context)
    {
        Interlocked.Increment(ref Count);
    }
}

これ、ブレークポイントを張って様子みたり、Countの値を表示して見たりするとわかりますが、何度も呼ばれます。何度も何度も。どーいうことかというと、Application_StartとInitは等しくないです。ASP.NET Runtimeは複数のアプリケーションプールを作り、それごとにInitは呼ばれてるんですね。じゃあ、どうするか、というと……

public class CallOnceModule : IHttpModule
{
    static int initializedModuleCount;

    public void Init(HttpApplication context)
    {
        var count = Interlocked.Increment(ref initializedModuleCount);
        if (count != 1) return;

        // ここに本体書く
    }

    public void Dispose()
    {
        var count = Interlocked.Decrement(ref initializedModuleCount);
        if (count == 0)
        {
            // ここに本体書く
        }
    }
}

Initが呼ばれた回数を取れば、正しく1回になります。ちなみに属性を張るだけで、Application_Startっぽく呼び出されるメソッドを作れるWebActivatorも、似たような感じの仕組みです。

Timer

IHttpModuleの話はこのぐらいにして、本体の話にいきましょう。定期的に、例えば1分間隔に、とかは、Timer使えばいいんですよ、Timer。あ、Timerは幾つかありますが、System.Threading.Timerのほうね。

/// <summary>
/// 1分間隔でThreadInfoをログ取りするモジュール
/// </summary>
public class ThreadInfoLoggingModule : IHttpModule
{
    static NLog.Logger logger = NLog.LogManager.GetLogger("ThreadInfo");
    static NLog.Logger classLogger = NLog.LogManager.GetCurrentClassLogger();
    static int initializedModuleCount;
    static Timer timer;

    public void Init(HttpApplication context)
    {
        var count = Interlocked.Increment(ref initializedModuleCount);
        if (count != 1) return;

        timer = new Timer(_ =>
        {
            try
            {
                var date = DateTime.Now;

                int availableWorkerThreads, availableCompletionPortThreads;
                ThreadPool.GetAvailableThreads(out availableWorkerThreads, out availableCompletionPortThreads);

                int maxWorkerThreads, maxCompletionPortThreads;
                ThreadPool.GetMaxThreads(out maxWorkerThreads, out maxCompletionPortThreads);

                using (var sw = new System.IO.StringWriter())
                using (var jw = new Newtonsoft.Json.JsonTextWriter(sw))
                {
                    jw.Formatting = Newtonsoft.Json.Formatting.None;

                    jw.WriteStartObject(); // {

                    jw.WritePropertyName("date");
                    jw.WriteValue(date);
                    jw.WritePropertyName("availableWorkerThreads");
                    jw.WriteValue(availableWorkerThreads);
                    jw.WritePropertyName("availableCompletionPortThreads");
                    jw.WriteValue(availableCompletionPortThreads);
                    jw.WritePropertyName("maxWorkerThreads");
                    jw.WriteValue(maxWorkerThreads);
                    jw.WritePropertyName("maxCompletionPortThreads");
                    jw.WriteValue(maxCompletionPortThreads);

                    jw.WriteEndObject(); // }

                    jw.Flush();

                    var message = sw.ToString();
                    logger.Trace(message);
                }
            }
            catch (Exception ex)
            {
                classLogger.ErrorException("ThreadInfoLogging encounts error", ex);
            }
        }, null, TimeSpan.FromMinutes(1), TimeSpan.FromMinutes(1));
    }


    public void Dispose()
    {
        var count = Interlocked.Decrement(ref initializedModuleCount);
        if (count == 0)
        {
            var target = Interlocked.Exchange(ref timer, null);
            if (target != null)
            {
                target.Dispose();
            }
        }
    }
}

なにをやっているか。よーするに、Timerで1分置きにロガーでJSONを吐き出してます。ロガーは謎社ではNLogを使ってます。というかこのModuleでは謎社のプロダクション環境で動いてるものです。なお、JsonTextWriter使ってるところは、別に普通にSerializeで構いませんですよ、なんとなく手書きしちゃっただけなので。

というわけで、これでThreadPoolの情報が取れました。やったね！あとはJSONなので好きな様にゴリゴリすればいいんですが、賢く解析したいなら、とりあえず謎社ではSumo Logicを使っています。Next Generation Log Management & Analyticsということで、集計ツールと解析ウェブアプリをワンセットで提供してくれてます。

独自のクエリ言語でガッと解析してグラフ化できてる、ってのは伝わるでしょうか？ふいんきね。便利そう、とか思ってもらえれば。クエリと可視化、更に閾値による通知など、色々できちゃいます。こいつぁイイね？←ちなみに、私はまだ全然クエリ書けないので、これは謎社の誇るPowerShellマスターが用意してくれました。

（ここではparseが手書きチックですが、実際にJSONをSumoでパースする際はJsonコマンドが用意されているので、それを使えばもっと綺麗にparseできます）

BookSleeveのMonitor

ついでに、謎社ではRedisを多用しているんですが、RedisライブラリであるBookSleeveは、GetCountersというメソッドで、それぞれのRedisConnectionの情報を吐き出すことができます。これを1分置きに、ThreadInfoと同様に吐き出すようにしてます。

/// <summary>
/// 1分間隔でRedis(BookSleeve)のCounterをログ取りするモジュール
/// </summary>
public class RedisCounterLoggingModule : IHttpModule
{
    static NLog.Logger logger = NLog.LogManager.GetLogger("RedisCounter");
    static NLog.Logger classLogger = NLog.LogManager.GetCurrentClassLogger();
    static int initializedModuleCount;
    static Timer timer;

    public void Init(HttpApplication context)
    {
        var count = Interlocked.Increment(ref initializedModuleCount);
        if (count != 1) return;

        timer = new Timer(_ =>
        {
            try
            {
                var date = DateTime.Now;

                // ここは謎社Internalな部分なのでテキトーにスルーしてくださいな 
                var query = Grani.Core.GlobalConfig.RedisGroupDictionary
                    .SelectMany(x => x.Value.Settings, (x, settings) => new { x.Value.GroupName, settings });
                foreach (var item in query)
                {
                    var connection = item.settings.GetConnection();
                    var counters = connection.GetCounters();

                    using (var sw = new System.IO.StringWriter())
                    using (var jw = new Newtonsoft.Json.JsonTextWriter(sw))
                    {
                        jw.Formatting = Newtonsoft.Json.Formatting.None;

                        jw.WriteStartObject(); // {

                        jw.WritePropertyName("date");
                        jw.WriteValue(date);

                        jw.WritePropertyName("GroupName");
                        jw.WriteValue(item.GroupName);
                        jw.WritePropertyName("Host");
                        jw.WriteValue(item.settings.Host + ":" + item.settings.Port);
                        jw.WritePropertyName("Db");
                        jw.WriteValue(item.settings.Db);

                        jw.WritePropertyName("MessagesSent");
                        jw.WriteValue(counters.MessagesSent);
                        jw.WritePropertyName("MessagesReceived");
                        jw.WriteValue(counters.MessagesReceived);
                        jw.WritePropertyName("MessagesCancelled");
                        jw.WriteValue(counters.MessagesCancelled);
                        jw.WritePropertyName("Timeouts");
                        jw.WriteValue(counters.Timeouts);
                        jw.WritePropertyName("QueueJumpers");
                        jw.WriteValue(counters.QueueJumpers);
                        jw.WritePropertyName("Ping");
                        jw.WriteValue(counters.Ping);
                        jw.WritePropertyName("SentQueue");
                        jw.WriteValue(counters.SentQueue);
                        jw.WritePropertyName("UnsentQueue");
                        jw.WriteValue(counters.UnsentQueue);
                        jw.WritePropertyName("ErrorMessages");
                        jw.WriteValue(counters.ErrorMessages);
                        jw.WritePropertyName("SyncCallbacks");
                        jw.WriteValue(counters.SyncCallbacks);
                        jw.WritePropertyName("AsyncCallbacks");
                        jw.WriteValue(counters.AsyncCallbacks);
                        jw.WritePropertyName("SyncCallbacksInProgress");
                        jw.WriteValue(counters.SyncCallbacksInProgress);
                        jw.WritePropertyName("AsyncCallbacksInProgress");
                        jw.WriteValue(counters.AsyncCallbacksInProgress);
                        jw.WritePropertyName("LastSentMillisecondsAgo");
                        jw.WriteValue(counters.LastSentMillisecondsAgo);
                        jw.WritePropertyName("LastKeepAliveMillisecondsAgo");
                        jw.WriteValue(counters.LastKeepAliveMillisecondsAgo);
                        jw.WritePropertyName("KeepAliveSeconds");
                        jw.WriteValue(counters.KeepAliveSeconds);
                        jw.WritePropertyName("State");
                        jw.WriteValue(counters.State.ToString());

                        jw.WriteEndObject(); // }

                        jw.Flush();

                        var message = sw.ToString();
                        logger.Trace(message);
                    }
                }
            }
            catch (Exception ex)
            {
                classLogger.ErrorException("RedisCounterLogging encounts error", ex);
            }
        }, null, TimeSpan.FromMinutes(1), TimeSpan.FromMinutes(1));
    }

    public void Dispose()
    {
        var count = Interlocked.Decrement(ref initializedModuleCount);
        if (count == 0)
        {
            var target = Interlocked.Exchange(ref timer, null);
            if (target != null)
            {
                target.Dispose();
            }
        }
    }
}

RedisGroupとかコネクション管理はBookSleeveの上に被せてるCloudStructuresによるものです（プロダクション環境でヘヴィに使ってますよ！）。CloudStructuresの使い方とかもまたそのうち。

まとめ

とまぁ、そんなふうにして色々データ取ってます。改善の基本はデータ取りから。色々なところからデータ取ってチェック取れるような体制を整えています。次回は、SQLやHttp、Redisの実行時間をどう取得するかについてお話しましょふ。たぶんね。きっと。

ところで、プロダクション環境下で――と書いているように、謎社のアプリケーションは完全にC#に移行しました。結果ですが、最先端環境で練り上げたC#によるウェブアプリケーションは、超絶速い。しかも、完全にAWSクラウドに乗っけての話ですからね、オンプレミスでのスペシャルなマシンやFusion-ioなDBでやってるわけじゃなく、成果出せてる。

Sumo LogicやNew Relicなど外部サービスの活用やRedisの使い倒しかた、非同期処理の塊、などなど、次世代のC#ウェブアプリケーションのスタンダードというものを示せたのではないかな、と思っています。詳しい話はそのうちまたどこかで発表したいとは思うので待っててください。

Profile

Yoshifumi Kawai

Cysharp, Inc
CEO/CTO

Microsoft MVP for Developer Technologies(C#)
April 2011
|
July 2024

Twitter:@neuecc GitHub:neuecc

Archive