log4netが遅い？処理を早くする方法は？

2020-12-13
log4net

log4netからログファイルを出力する場合、3つのLocking Modelが用意されています。
それぞれの違いと実行時間の違いをご紹介します。

目次

Locking Modelってそもそもどんなものが用意されているの？

以下の文章がlog4netの公式リファレンスに載っています。

There are three built in locking models, FileAppender.ExclusiveLock, FileAppender. MinimalLock and FileAppender. InterProcessLock . The first locks the file from the start of logging to the end, the second locks only for the minimal amount of time when logging each message and the last synchronizes processes using a named system wide Mutex.

log4net公式SDKリファレンス(サイトリンク)

この文章から『ExclusiveLock』と『MinimalLock』と『InterProcessLock』の3種類のLocking Modelが存在することが分かります。

Locking Modelの設定の仕方は？

<lockingModel type="log4net.Appender.FileAppender+MinimalLock" />

log4netのconfig中、appenderの下に上記のような表記を追加するだけです。
上の例は”FileAppender.MinimalLock”を指定した例。

ExclusiveLockとは

Open the file once for writing and hold it open until CloseFile() is called. Maintains an exclusive lock on the file during this time.

log4net公式SDKリファレンス(サイトリンク)

ExclusiveLockとは、c#から呼び出されて実行が終了するまで、ログファイルがファイルを占有するモードのこと。ファイルをいちいち閉じたり開いたりする必要がないのでその分ログ出力処理に時間がかかりません。
ファイルを占有しているので、その代わり同時に同じログファイルにログを出力する場合は適さないモードです。
log4netの初期値のモードはこちらのExclusiveLockです。なのでなにも気にしたことがない、という場合はこのモードになっています。

MinimalLockとは

Opens the file once for each AcquireLock()/ReleaseLock() cycle, thus holding the lock for the minimal amount of time. This method of locking is considerably slower than FileAppender. ExclusiveLock but allows other processes to move/delete the log file whilst logging continues.

log4net公式SDKリファレンス(サイトリンク)

MinimalLockとは、ログファイルに書き込む瞬間だけログファイルを開くモードのことです。このモードは他サイトでも結構紹介されているのを見かけます。ログ書き込む度にファイルの開閉を繰り返すのでその分処理は遅くなります。

InterProcessLockとは

InterProcessLockは公式リファレンスではあまり言及されていません。一番上の引用文から、複数プロセスから呼び出すのに適当なモードなことが分かります。

こちらの記事で実際にInterProcessLockを実際に使った場合の挙動を確認しています。

log4netを複数プロセスから叩いてスレッドセーフなのか確認する
log4netを複数プロセスから叩いてスレッドセーフなのか確認する
log4netを複数プロセスから叩きまくったらうまく動くのか検証していきます。Log4netは果たしてスレッドセーフにできるのか？
mikan-tech.info

実行時間を計測してみよう！

計測のために以下のようなソースを作成してみました。

using System;

namespace log4netSpeedMeasure
{
    class Program
    {
        private static log4net.ILog logger = log4net.LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

        static void Main(string[] args)
        {
            DateTime start = DateTime.Now;
            int kaisuu = 50000;
            for (int i=0;i< kaisuu; i++) {

                logger.Info("実行されたよ");
            }
            DateTime end = DateTime.Now;

            Console.WriteLine($"{kaisuu}件ログを出力しました。");
            Console.WriteLine($"実行開始時間：{start:yyyy/MM/dd HH:mm:ss.ffff}");
            Console.WriteLine($"実行終了時間：{end:yyyy/MM/dd HH:mm:ss.ffff}");
            TimeSpan syorijikan = end - start;
            Console.WriteLine($"処理時間(秒)：{syorijikan.TotalSeconds}");
            Console.WriteLine($"ログ1件あたりの処理時間(ミリ秒)：{syorijikan.TotalMilliseconds/ kaisuu}");
            Console.ReadLine();
        }
    }
}

ログを50000回出してコンソールに処理時間を出力するだけの簡単ソースです。
このソースはそのまま、log4netの設定ファイル中のLockingモデルを指定するの部分だけ変更して実行してみます。

ちなみに実行環境簡単に書いておくと論理プロセッサ8のメモリ16GBで実行しました。
ログの出力先はローカルのフォルダに。あまりないと思いますが、ログを出力するのにサーバを介したり特殊な状況の場合はもっと遅くなると思います。

ExclusiveLockの場合

MinimalLockの場合

InterProcessLockの場合

計測結果から

ログを1件出力するのにExclusiveLockは0.011ミリ秒、MinimalLockは0.30ミリ秒、そしてInterProcessLockは0.015ミリ秒かかることが分かりました。ExclusiveLockとInterProcessLockは出力時間の差は0.004ミリ秒の差なので誤差と言えそうです。この2つのモードであればどちらを使用しても5万件のログを出力するのに1秒かからないので、実行速度への影響は少ないのではないでしょうか。
対して、MinimalLockでログを1件出力するのにかかる時間はExclusiveLockの出力時間のおよそ30倍。1件1件ログを出力するのにファイルを開閉してるのでこの遅さは仕方がないとはいえますが、実装の場面は選びそうです。デバックログ埋め込んでみたら処理が全然終わらない…なんてことも。

参考記録:似たような感じにファイル出力してみてかかった時間

実行時間比較の参考のためにログによく似た文章をファイルに出力してみました。

using System;
using System.Reflection;
using System.IO;

namespace log4netSpeedMeasure
{
    class Program
    {
        static void Main(string[] args)
        {
            DateTime start = DateTime.Now;
            int kaisuu = 50000;

            using (StreamWriter writer = File.CreateText(Path.Combine(Path.GetDirectoryName(Assembly.GetExecutingAssembly().Location), @"logfile.log")))
            {
                for (int i = 0; i < kaisuu; i++)
                {
                    DateTime now = DateTime.Now;
                    writer.WriteLine($"{now.ToString("yyyy-MM-dd hh:mm:ss,fff")} [INFO ]  - 実行されたよ");
                }
            }

            DateTime end = DateTime.Now;

            Console.WriteLine($"{kaisuu}件ログを出力しました。");
            Console.WriteLine($"実行開始時間：{start:yyyy/MM/dd HH:mm:ss.ffff}");
            Console.WriteLine($"実行終了時間：{end:yyyy/MM/dd HH:mm:ss.ffff}");
            TimeSpan syorijikan = end - start;
            Console.WriteLine($"処理時間(秒)：{syorijikan.TotalSeconds}");
            Console.WriteLine($"ログ1件あたりの処理時間(ミリ秒)：{syorijikan.TotalMilliseconds / kaisuu}");
            Console.ReadLine();
        }
    }
}

ログ1件あたり0.002ミリ秒！！
やはり最低限の機能の分、処理時間は早いです。ExclusiveLockでもどうしても遅い、最低限の機能でいいから速度が欲しい、という方は自分で実装した方が満足のいく速度が実現できると思います。

まとめ

  • log4netには３つのファイル開閉処理が違うモードが存在する
  • (速い)ExclusiveLock > InterProcessLock >>> MinimalLock(遅い) となっている

以上、平和なお仕事ライフを！