LoginSignup
2
3

More than 5 years have passed since last update.

@naitnak(T Nak)

[C#Tips.ログ]Disposable-usingを使った簡単計測ログ出力方法

Last updated at Posted at 2019-02-09

動機

ログ

みなさんログは出してますか？自分は割と出しています。だってお客さんからクレーム来た時に何が起きたか、証言だけじゃ理解できないし、人間の記憶なんて適当ですもんね。ということでこのボタン押したとかコンボボックスを選択したとかの操作ログはうまいこと仕組み作って自動的にログに出るようにしてます。

計測ログ

で、今回は操作ログではなくて計測系ログの話。開発末期に「（他人の書いたコードの）パフォーマンスの最適化」という名の汚れ仕事を任されたりするんですが、そういう時にどこの処理が重いかを見極めるために自分がまず行うのが、原始的ですが計測ログを仕込んでいくこと。プロファイラだとノイズが多すぎて見極めにくいので。。（いつもプロファイラを使う→うーんわからん→ログ仕込むという流れになってます。。XAMLの最適化の場合はVS標準のプロファイラは必須だけどそれはまた別の話）。

ということでどんな感じで実装しているかを紹介してみたいと思います。

Log using using (usingを使ったログ出力)

ポイント：計測前ログを出力し、計測終了ログをIDisposableで返し、usingを使うことにより、usingブロック抜けたときに計測終了ログが出力される

ご存知の通りC#にはusing({Disposable})構文があり、usingブロックを抜けたときにDisposeが実行されるという特性を使います。アイデアはReactive Extensionsのイベント購読関数Subscribeの戻り値がIDisposableになっていて、それをDisposeするとイベントが解除されるというところから。ということでコード例。

ActionからDisposeを生成するクラス

まず下準備としてSystem.ReactiveをNugetからインポートする、もしくは以下のようなクラスを作ります。
要はActionを渡せばDispose時に実行してくれるクラスです。


    /// <summary>Disposableで実行するアクションをラップ</summary>
    /// <seealso cref="System.IDisposable" />
    public class DisposableAction : IDisposable
    {
        /// <summary>空オブジェクト</summary>
        public static readonly DisposableAction Empty = new DisposableAction(() => { });

        /// <summary>Disposeで実行する処理</summary>
        private readonly Action _disposableAction;

        /// <summary>Initializes a new instance of the <see cref="DisposableAction"/> class.</summary>
        /// <param name="disposableAction">TDisposeで実行する処理</param>
        /// <exception cref="ArgumentNullException">disposableAction</exception>
        public DisposableAction(Action disposableAction)
        {
            _disposableAction = disposableAction ?? throw new ArgumentNullException(nameof(disposableAction));
        }

        public void Dispose() => _disposableAction.Invoke();
    }

シンプルな例：コンソール出力でメソッドの処理時間計測

さて、Disposableができたら以下のようなメソッドを定義してみます。

  • 機能

    • 渡されたメソッド名をコンソール出力する
    • 戻り値のIDisposableをDisposeすると、メソッド名と経過時間をコンソール出力する
        /// <summary>指定文字列をコンソール出力</summary>
        /// <param name="methodName">Name of the method.</param>
        /// <returns>指定文字と経過時間をコンソール出力するDisposable</returns>
        public static IDisposable WriteLineMeasureTimeAsDisposable([CallerMemberName]string methodName = "")
        {
            Console.WriteLine($"Start [{methodName}]");

            // ここで開始時間を保存しておく
            var startDateTime = DateTime.Now;
            return new DisposableAction(() =>
            {
                // ここで経過時間を求める
                var collapsedTime = DateTime.Now - startDateTime;
                Console.WriteLine($"End [{methodName}] took {collapsedTime.TotalMilliseconds:F2}ms");
            });
        }

※ System.Reactiveを参照している場合、Disposableを生成する方法が以下のようにDiposable.Create(Action)となります。これ以降この記事ではnew DisposableActionの方を使います。

        /// <summary>指定文字列をコンソール出力</summary>
        /// <param name="methodName">Name of the method.</param>
        /// <returns>指定文字と経過時間をコンソール出力するDisposable</returns>
        public static IDisposable WriteLineMeasureTimeAsDisposable([CallerMemberName]string methodName = "")
        {
            Console.WriteLine($"Start [{methodName}]");
            var startDateTime = DateTime.Now;
            return Disposable.Create(() =>
            {
                var collapsedTime = DateTime.Now - startDateTime;
                Console.WriteLine($"End [{methodName}] took {collapsedTime.TotalMilliseconds:F2}ms");
            });
        }

上記関数は以下のように使います。


    [TestClass]
    public class SimpleDisposableLogDemo
    {
        [TestMethod]
        public async Task SomeHeavyMethodDemo()
        {
            await this.SomeHeavyMethod();
        }

        private async Task SomeHeavyMethod()
        {
            // ここで先ほどの計測関数を実装
            using (WriteLineMeasureTimeAsDisposable())
            {
                await Task.Delay(2000);
            }
        }
    // ・・・・

↓コンソール出力

Start [SomeHeavyMethod]
End [SomeHeavyMethod] took 2013.49ms

というようにメソッドをusingを使って計測ログ関数で包むことにより、その間の経過時間が計測できます。CallerMemeberNameを使用することにより、呼び出し元のメソッド名が自動的に入るので、多くの場合引数を渡す必要も無い！

実践的な例

上記例ではアイデアの肝を示すためにシンプルな機能しかありませんが、実際に自分がどんな感じのメソッドを定義して使っているかを紹介します。

まず下準備としてロガーインターフェースがあって、例としてコンソール出力するロガーを実装してみます。


    /// <summary>ロガーインターフェース</summary>
    public interface ILogger
    {
        /// <summary>デバッグログ出力</summary>
        /// <param name="log">ログ</param>
        void Debug(string log);

        /// <summary>情報ログ出力</summary>
        /// <param name="log">ログ</param>
        void Info(string log);

        /// <summary>警告ログ出力</summary>
        /// <param name="log">ログ</param>
        /// <param name="ex">例外情報</param>
        void Warn(string log, Exception ex = null);

        /// <summary>エラーログ出力</summary>
        /// <param name="log">ログ</param>
        /// <param name="ex">例外情報</param>
        void Error(string log, Exception ex = null);

        /// <summary>致命ログ出力</summary>
        /// <param name="log">ログ</param>
        /// <param name="ex">例外情報</param>
        void Fatal(string log, Exception ex = null);
    }

    /// <summary>コンソール出力するロガー</summary>
    /// <seealso cref="TNakUtility.Logger.ILogger" />
    public class ConsoleLogger : ILogger
    {
        public void Debug(string log) => System.Diagnostics.Debug.WriteLine(CreateLogString(log));

        public void Info(string log) => ConsoleWriteLine(log);

        public void Warn(string log, Exception ex = null) => ConsoleWriteLine(log, ex);

        public void Error(string log, Exception ex = null) => ConsoleWriteLine(log, ex);

        public void Fatal(string log, Exception ex = null) => ConsoleWriteLine(log, ex);

        private void ConsoleWriteLine(string log, Exception ex = null, [CallerMemberName] string header = "")
        {
            // ログ出力
            Console.WriteLine(CreateLogString(log, header));
            if (ex != null)
            {
                // 例外情報出力
                Console.WriteLine(CreateLogString(ex.ToString(), header));
            }
        }

        /// <summary>ログに時間、ヘッダ(メソッド名)を付与</summary>
        /// <param name="log">The log.</param>
        /// <param name="header">The header.</param>
        /// <returns>[{時間}][{メソッド名}]{ログ}</returns>
        private static string CreateLogString(string log, [CallerMemberName] string header = "") =>
            $"[{DateTime.Now:G}][{header}]{log}";
    }

このロガーインターフェースに拡張クラスとして計測ログ出力関数を実装します。
キモはWriteLogAsDisposable関数で、この第一引数に文字列を引数に取ってログ出力する関数を渡せば使いまわせるようになっています。
以下のような機能を追加しています。

  • 引数無しの場合、クラス名（ファイル名の末尾）、メソッド名が自動で出力される。
  • 引数にパラメータ情報を渡したり、結果を取得する関数を渡したりすることでパラメータ情報、処理結果情報も出力される
  • ネストしてログ出力されている場合vや^の数でネストのレベルがわかる
    public static class ILoggerExtensions
    {
        /// <summary>計測ログ出力（デバッグ）</summary>
        /// <param name="self">ロガー</param>
        /// <param name="processName">処理名(メソッド名)</param>
        /// <param name="categoryName">カテゴリ名(ファイル名)</param>
        /// <param name="parameterName">パラメータ情報文字列</param>
        /// <param name="getResult">結果を取得する関数</param>
        /// <returns>計測終了ログ出力</returns>
        /// <exception cref="ArgumentNullException">self</exception>
        public static IDisposable DebugMeasureTimeAsDisposable(this ILogger self,
                                                               [CallerMemberName] string processName = "",
                                                               [CallerFilePath] string categoryName = "",
                                                               string parameterName = null,
                                                               Func<object> getResult = null)
        {
            if (self == null)
            {
                throw new ArgumentNullException(nameof(self));
            }

            return WriteLogAsDisposable(self.Debug, processName, categoryName, parameterName, getResult);
        }

        /// <summary>計測ログ出力（Info）</summary>
        /// <param name="self">ロガー</param>
        /// <param name="processName">処理名(メソッド名)</param>
        /// <param name="categoryName">カテゴリ名(ファイル名)</param>
        /// <param name="parameterName">パラメータ情報文字列</param>
        /// <param name="getResult">結果を取得する関数</param>
        /// <returns>計測終了ログ出力</returns>
        /// <exception cref="ArgumentNullException">self</exception>
        public static IDisposable InfoMeasureTimeAsDisposable(this ILogger self,
                                                              [CallerMemberName] string processName = "",
                                                              [CallerFilePath] string categoryName = "",
                                                              string parameterName = null,
                                                              Func<object> getResult = null)
        {
            if (self == null)
            {
                throw new ArgumentNullException(nameof(self));
            }

            return WriteLogAsDisposable(self.Info, processName, categoryName, parameterName, getResult);
        }

        private static int NestLevelCounter = 0;

        /// <summary>計測ログ出力</summary>
        /// <param name="writeLogAction">ログ書き込み処理</param>
        /// <param name="processName">処理名(メソッド名)</param>
        /// <param name="categoryName">カテゴリ名(ファイル名)</param>
        /// <param name="parameterName">パラメータ情報文字列</param>
        /// <param name="getResult">結果を取得する関数</param>
        /// <returns>計測終了ログ出力</returns>
        /// <exception cref="ArgumentNullException">writeLogAction</exception>
        private static IDisposable WriteLogAsDisposable(Action<string> writeLogAction,
                                                        [CallerMemberName] string processName = "",
                                                        [CallerFilePath] string categoryName = "",
                                                        string parameterName = null,
                                                        Func<object> getResult = null)
        {
            if (writeLogAction == null)
            {
                throw new ArgumentNullException(nameof(writeLogAction));
            }

            var parameterNameString = string.IsNullOrWhiteSpace(parameterName) ? string.Empty : $"_param:{parameterName}";
            var processNameString =
                $"[{Path.GetFileName(categoryName)}]({processName}{parameterNameString})";
            var startTime = DateTime.Now;
            var tempNestLevel = ++NestLevelCounter;
            var startArrowString = new string('v', tempNestLevel);
            writeLogAction.Invoke($"{startArrowString}Start {processNameString}");
            return new DisposableAction(() =>
            {
                var endArrowString = new string('^', tempNestLevel);
                --NestLevelCounter;
                var collapsedTime = DateTime.Now - startTime;
                var resultString = getResult != null ? $"=> Result:[{getResult()}]" : string.Empty;
                writeLogAction(
                    $"{endArrowString}End   {processNameString} took {collapsedTime.TotalMilliseconds:f2}ms {resultString}");
            });
        }
    }

実際の使用例は以下のような感じ


    [TestClass]
    public class LoggerDemo
    {
        private ILogger _logger;

        [TestInitialize]
        public void Initialize()
        {
            _logger = new ConsoleLogger();
        }

        /// <summary>この関数が起点</summary>
        /// <returns></returns>
        [TestMethod]
        public async Task TestMethod1()
        {
            await HeavyMethodMain();
        }

        /// <summary>計測メソッドの起点</summary>
        /// <returns></returns>
        private async Task HeavyMethodMain()
        {
            using (_logger.InfoMeasureTimeAsDisposable())
            {
                await this.Multiply(6, 4);
                await this.HeavyMethodSub2();
            }
        }

        /// <summary>掛け算：名称、パラメータ、結果指定の例</summary>
        /// <param name="v1">The v1.</param>
        /// <param name="v2">The v2.</param>
        /// <returns></returns>
        private async Task<decimal> Multiply(decimal v1, decimal v2)
        {
            var ret = 0m;
            using (_logger.InfoMeasureTimeAsDisposable(
                processName: "MultiplyProcessName",
                categoryName: "MultiplyCategoryName",
                parameterName: $"(v1:{v1}, v2:{v2})",
                getResult: () => ret))
            {
                await Task.Delay(millisecondsDelay: 120);
                return ret = v1 * v2;
            }
        }

        /// <summary>引数無しの例</summary>
        /// <returns></returns>
        private async Task HeavyMethodSub2()
        {
            using (_logger.InfoMeasureTimeAsDisposable())
            {
                await Task.Delay(160);
            }
        }
    }

このTestMethod1を実行すると、以下のようにコンソール出力されます。

[2019/02/09 15:05:55][Info]vStart [LoggerDemo.cs](HeavyMethodMain)
[2019/02/09 15:05:55][Info]vvStart [MultiplyCategoryName](MultiplyProcessName_param:(v1:6, v2:4))
[2019/02/09 15:05:55][Info]^^End   [MultiplyCategoryName](MultiplyProcessName_param:(v1:6, v2:4)) took 132.46ms => Result:[24]
[2019/02/09 15:05:55][Info]vvStart [LoggerDemo.cs](HeavyMethodSub2)
[2019/02/09 15:05:56][Info]^^End   [LoggerDemo.cs](HeavyMethodSub2) took 160.93ms 
[2019/02/09 15:05:56][Info]^End   [LoggerDemo.cs](HeavyMethodMain) took 296.96ms
  • 引数を指定していないHeabyMethodMain、HeavyMethodSub2関数ではファイル名とメソッド名が自動的に出力されている
  • Multiply関数では引数や結果が出力される
  • ネストレベルはvや^の数で示される。 => マルチスレッド未対応。。。まだ必要になったことが無いので。。

まとめ

こんな感じの仕組みを作っておいて計測ログを基本デバッグログとして仕込んでいき、必要な部分は情報ログとして出力するようにしています。
書式は好みなので自由にすればいいと思います。キモはあくまでDisposable-usingを使うこと、あとはCallerMemberName等使って引数無しでもある程度使えるようになっていること。
なおログを仕込むときはResharperのサラウンドテンプレートを使えば楽ちん。
(TODO:ファイルテンプレート、サラウンドテンプレートの使い方、作り方のチュートリアル作成。)

それでは良いプログラミングライフをﾉｼ

2
3
0

Register as a new user and use Qiita more conveniently

  1. You get articles that match your needs
  2. You can efficiently read back useful information
  3. You can use dark theme
What you can do with signing up
Sign upLogin
2
3