ThreadPool監視のすゝめ

先日7月20日、@neueccさんがASP.NETでの定期的なモニタリング手法ということで、Webアプリケーションの状況把握のためにThreadPoolのスレッド数を監視をしていると書いておられました。社内システムとはいえリアルタイムアプリケーションでThreadPool使いまくりなので、その状態がどうなっているのかを知るということには大変興味が沸きました。まずまず、ThreadPoolの監視というのは考えたこともなかったです。

お試し実装

偶然にも翌日の21日が日曜休日出勤だったので、(内容が特に難しいわけでもないですし)お試しだと思って早速実装してみました。リアルタイムアプリケーションとは言っても所詮は社内システム。秒間5000クエリとかそんな目が飛び出るような恐ろしいアクセスはあるはずもないので、雰囲気以下のようなコードで気楽にやってみました。

public void WriteThreadPoolStatus()
{
    try
    {
        //--- ThreadPoolの利用状況を取得
        var now                            = DateTime.Now;
        int availableWorkerThreads         = 0;
        int availableCompletionPortThreads = 0;
        int maxWorkerThreads               = 0;
        int maxCompletionPortThreads       = 0;
        ThreadPool.GetAvailableThreads(out availableWorkerThreads, out availableCompletionPortThreads);
        ThreadPool.GetMaxThreads(out maxWorkerThreads, out maxCompletionPortThreads);

        //--- とりあえずTSV形式で蓄積型で記録 (良い子はDBに入れたりファイル名変えたりしましょうね！)
        var folder = Environment.GetFolderPath(Environment.SpecialFolder.DesktopDirectory);
        var file   = "ThreadPoolStatus.txt";
        var path   = Path.Combine(folder, file);
        using (var stream = new FileStream(path, FileMode.Append))
        using (var writer = new StreamWriter(stream))
        {
            writer.WriteLine(string.Join("\\t", new object[]
            {
                now,
                availableWorkerThreads,
                availableCompletionPortThreads,
                maxWorkerThreads,
                maxCompletionPortThreads,
            }));
            writer.Flush();
        }
    }
    catch
    {
        //--- 失敗しても、まぁいいや
    }
}

ちなみにこれを実装したのはWebアプリではなくWindowsサービスです。夜中にアクセスがあることはほとんどないので、必要なところだけでいいやという考えの下1分間隔のような定期的な記録ではなく、ユーザーからアクセスがあったタイミングでのみ記録するようにしました。

監視結果

記録したファイルはTSVなので、Excelにペタッと貼り付けてグラフにしてみました。そしたらこんな感じの結果が...。

TransitionOfThreads

謎社さんの真似してスレッドプールのスレッド数のログするコードを日曜日に書いてみた。結果、どーもスレッドが解放されずに溜まっていく一方の模様。どこでそんなことになってるんや…
— じんぐる (@xin9le) July 23, 2013

試験環境でこのペースで、実際にはあと数倍はアクセスがある算段なのでサービスを開始してから2日もしないうちに死んでしまうことに...。／(^o^)＼ｵﾜﾀ

原因はどこにあったのか

利用可能スレッドがみるみる減っているということは利用中のスレッドが蓄積されるということで、それはスレッドを解放できていないということです。つまりどこかでデッドロックしている、と。今回の場合は、大体次のようなコードで引っ掛かっていました。

public Task RunCommandAsync()
{
    var response = this.ResponseEventAsObservable()
                 .FirstOrDefaultAsync(x => x.CommandId == this.command.Id)
                 .ToTask();
    return this.command.Run().ContinueWith(_ =>
    {
        //--- コマンドを実行したら、しばらくののちに別の箇所から応答イベントが発生する算段
        var result = response.Result;
    });
}

コマンドを実行したまでは良かったけれど、特定の条件が満たされた場合に応答イベントが発生しないという悲しい結末。「付き合ってください」とメールを送ったのに、来ない返事を今か今かと待ち侘びるような心境。その人はすでに死んでいるのに...。ということで、「付き合ってください」メールは送るけど、その人が死んでいるのを検知したら「ダメだったよ」って返すようにしたというのが加えた修正でした。

正しく処理されている場合は決して継続的な右肩下がりにはならず、(定常的に利用しているスレッド数に違いはあるものの)ある程度横ばいになるはずです。

まとめ

今回、興味本位で入れた監視コードからスレッドのデッドロックに気付きました。原因の特定から修正まで2日かかるという苦しさもありました。もしスレッドをガシガシ使うようなアプリケーションを使うことがあれば、スレッド数の監視をすることをお勧めします。コードを入れるのが面倒だったり入れられない事情がある場合は、リソースモニターなどでスレッド数の変化を定期的に確認するのも良いかと思います。

ResourceMonitor