【C#】調査用の実行時間計測クラス

背景

レスポンスチューニングをする際に、
まず調査として各処理にどれくらいの実行時間がかかっているのか知りたいという場面がある。
その際に、ソースコードに簡単に仕込めて実行時間を計測できる仕組みがあればと思い作ってみました。

作ったものとその動作

とりあえず作ってみたものがこれ

コード

public class TimeMeasure
{
    //Property
    private Dictionary<string, TimeRecordItem> TimeRecordDic { get; set; }
    private string ClassName { get; set; }
    //Public Method
    public void Record(string key = null, string suffix = "")
    {
        if (key == null) key = new System.Diagnostics.StackFrame(1).GetMethod().Name;
        if (!string.IsNullOrEmpty(suffix)) key = string.Join("_", key, suffix);
        if (!TimeRecordDic.ContainsKey(key)) TimeRecordDic.Add(key, new TimeRecordItem(key, DateTime.Now));
        else if (TimeRecordDic[key].IsEnd) TimeRecordDic[key].AddTimeSets(DateTime.Now);
        else TimeRecordDic[key].TimeSets.Last().SetEndTime(DateTime.Now);
    }
    public void OutputDebugWriteLine()
    {
        foreach(var content in GetOutputContents())
        {
            System.Diagnostics.Debug.WriteLine(content);
        }
    }
    public void OutputConsoleWriteLine()
    {
        foreach(var content in GetOutputContents())
        {
            System.Console.WriteLine(content);
        }
    }
    //Private Method
    private IEnumerable<string> GetOutputContents()
    {
        var TimeSets = new List<TimeSet>();
        foreach (var item in TimeRecordDic.Values)
        {
            TimeSets.AddRange(item.TimeSets);
        }
        foreach (var r in TimeSets.OrderBy(rr => rr.StartTime))
        {
            yield return string.Join(",", ClassName, r.Key, r.StartTime.ToString(), r.EndTime.ToString(), r.ExecutionTime.ToString());
        }
    }
    //Constructor
    public TimeMeasure()
    {
        TimeRecordDic = new Dictionary<string, TimeRecordItem>();
        ClassName = new System.Diagnostics.StackFrame(1).GetMethod().ReflectedType.FullName;
    }
    //Private Class
    private class TimeRecordItem
    {
        //Property
        public string Key { get; private set; }
        public List<TimeSet> TimeSets { get; private set; }
        public bool IsEnd {  get { return TimeSets.Last().EndTime != null; } }
        //Public Method
        public void AddTimeSets(DateTime time)
        {
            TimeSets.Add(new TimeSet(Key, time));
        }
        //Constructor
        public TimeRecordItem(string key, DateTime time)
        {
            Key = key;
            TimeSets = new List<TimeSet> { new TimeSet(Key, time) };
        }
    }
    private class TimeSet
    {
        //Property
        public string Key { get; private set; }
        public DateTime StartTime { get; private set; }
        public DateTime? EndTime { get; private set; }
        public decimal? ExecutionTime
        {
            get
            {
                if (EndTime == null) return null;
                var diff = EndTime.Value - StartTime;
                return (decimal)diff.TotalMilliseconds / 1000;
            }
        }
        //Public Method
        public void SetEndTime(DateTime time)
        {
            EndTime = time;
        }
        //Constructor
        public TimeSet(string key, DateTime time)
        {
            Key = key;
            StartTime = time;
        }
    }
}

動作

以下のようなサンプルクラスで動作確認

public class Sample
{
    private TimeMeasure _timeMeasure = new TimeMeasure();

    public void Execute()
    {
        _timeMeasure.Record();
        TestMethod1();
        TestMethod2();
        TestMethod1();
        _timeMeasure.Record();
        _timeMeasure.OutputConsoleWriteLine();
    }
    private void TestMethod1()
    {
        _timeMeasure.Record();
        System.Threading.Thread.Sleep(1000);
        _timeMeasure.Record();
    }
    private void TestMethod2()
    {
        _timeMeasure.Record();
        _timeMeasure.Record(suffix: "処理1");
        System.Threading.Thread.Sleep(1000);
        _timeMeasure.Record(suffix: "処理1");
        System.Threading.Thread.Sleep(1000);
        _timeMeasure.Record();
    }
}

実行結果

ConsoleAppForDebug.Program+Sample,Execute,2021/01/17 1:14:04,2021/01/17 1:14:08,4.0148715
ConsoleAppForDebug.Program+Sample,TestMethod1,2021/01/17 1:14:04,2021/01/17 1:14:05,1.0005907
ConsoleAppForDebug.Program+Sample,TestMethod2,2021/01/17 1:14:05,2021/01/17 1:14:07,2.0018408
ConsoleAppForDebug.Program+Sample,TestMethod2_処理1,2021/01/17 1:14:05,2021/01/17 1:14:06,1.0007147
ConsoleAppForDebug.Program+Sample,TestMethod1,2021/01/17 1:14:07,2021/01/17 1:14:08,1.000481

どのクラスのどのメソッドで実行にどれくらいかかったかがちゃんと計測できてそう

説明

いくつかピックアップして説明します

簡単に仕込みたい！

調査なので時間をかけずに簡単に仕込めるようにしたかったです。
同じコードの貼り付けのみで仕込んでいけることを目指しました。

public TimeMeasure()
{
    TimeRecordDic = new Dictionary<string, TimeRecordItem>();
    ClassName = new System.Diagnostics.StackFrame(1).GetMethod().ReflectedType.FullName;
}

コンストラクタでStackFrameを用いて呼び出し元のクラスを取得します。

public void Record(string key = null, string suffix = "")
{
    if (key == null) key = new System.Diagnostics.StackFrame(1).GetMethod().Name;
    if (!string.IsNullOrEmpty(suffix)) key = string.Join("_", key, suffix);
    if (!TimeRecordDic.ContainsKey(key)) TimeRecordDic.Add(key, new TimeRecordItem(key, DateTime.Now));
    else if (TimeRecordDic[key].IsEnd) TimeRecordDic[key].AddTimeSets(DateTime.Now);
    else TimeRecordDic[key].TimeSets.Last().SetEndTime(DateTime.Now);
}

測定の開始・終了用のメソッドでもStackFrameを用いて呼び出し元のメソッド名を取得するようにしてます。
加えて、開始か終了の判断をTimeSetクラスで行うようにすることでRecord()を呼び出すだけでいいようにしてます。
結果サンプルコードのように_timeMeasure.Record();を計測したい部分に張り付けていくだけで仕込むことができます。

メソッド内の特定の処理を計測したい！

メソッド内の特定の部分の処理時間を計測したい場合もあるので、
Recordメソッドではsuffix引数を用意してます。
suffixが渡された場合は、呼び出し元メソッド名と渡された文字列を"_"で結合してkeyとして使用します。
※サンプルコードのTestMethod2の部分

private void TestMethod2()
{
    _timeMeasure.Record();
    _timeMeasure.Record(suffix: "処理1");
    System.Threading.Thread.Sleep(1000);
    _timeMeasure.Record(suffix: "処理1");
    System.Threading.Thread.Sleep(1000);
    _timeMeasure.Record();
}

ConsoleAppForDebug.Program+Sample,TestMethod2,2021/01/17 1:14:05,2021/01/17 1:14:07,2.0018408
ConsoleAppForDebug.Program+Sample,TestMethod2_処理1,2021/01/17 1:14:05,2021/01/17 1:14:06,1.0007147