В стремительно развивающемся, большом и сложном продукте поиск узких мест, в плане производительности, становится не тривиальной задачей. Конечно есть инструменты для решения таких задач, например, BenchmarkDotNet. Бесспорно, это полезный и нужный инструмент, но при этом не всегда удобный. Это можно обнаружить, например, когда необходимо померить не публичный метод полностью, установив соответствующий атрибут, а некоторый кусок кода внутри приватного метода. Здесь я ни в коем случае не критикую обозначенный инструмент, а лишь хочу указать на потребность в несколько ином способе сбора метрик фрагментов кода. Встречаются весьма сложные, запутанные методы, с ветвлением, с циклами, обработкой исключительных ситуаций, а проблемное место может быть где-то внутри. Чтобы его найти нужно обильно обложить код измерителями, при этом есть очевидное желание не трогать и не перерабатывать существующую логику.

Для измерения времени выполнения участков кода можно использовать класс StopWatch.

Что-то вроде этого:

var sw = new Stopwatch();
sw.Start();
// Измеряемый код
sw.Stop();
Console.WriteLine(sw.Elapsed); // Здесь логируем

Чтобы каждый раз не расставлять StopWatch по коду можно унифицировать процедуру измерения через функцию высшего порядка, например, так:

static void LambdaMeter(string label, Action act) {
  var sw = new Stopwatch();
  sw.Start();
  act();
  sw.Stop();
  Console.WriteLine($"{label} : {sw.Elapsed}"); // Здесь логируем
}

И использовать таким образом:

LambdaMeter("foo", () => {
  // TODO something
});

Можно вывернуть вызов наизнанку через расширение:

public static class TimeInspector {
  public static void Meter(this Action act, string label) {
      var sw = new Stopwatch();
      sw.Start();
      act();
      sw.Stop();
      Console.WriteLine($"{label} : {sw.Elapsed}"); // Здесь логируем
    }
}

И использовать так:

new Action(() => {
  // TODO something
}).Meter("foo");

Вроде как проблема кажется решенной, но все же такой прием крайне ограничен. Дело в том, что в измеряемом коде могут быть выходы return, в поэтому в Action его не завернуть. Даже использование Func не решит проблему. Ниже я хочу описать прием, который не раз использовал, он с наименьшими изменениями в коде позволят решить проблему измерения произвольных участков кода. Мы построим простой и компактный логер для измерения скорости выполнения, при необходимости его так же довольно просто модифицировать под другие нужды, например, для поиска утечек памяти. Приведенный далее код не претендует на законченность и функциональность, это скорее демонстрация принципа, на основе которого можно построить реально полезный и легкий инструмент. Тем не менее, код рабочий и может быть использован для целей сбора метрик как есть или адаптирован для более специфичных задач. Так же хочу отметить, что в приведенном ниже коде собирается дополнительная информация, как ID процесса или имя хоста. Эти параметры были полезны мне в определенных ситуациях и оставлены исключительно для примера. Тот, кто решит адаптировать код под свои задачи может иметь потребность собирать совсем другие параметры, отчасти по этой причине указанный код не стал публиковать на публичный GitHub в виде законченного продукта.

В C# есть широко известный и полезный оператор using, он применим к типам, поддерживающим интерфейс IDisposable. Смысл в том, чтобы при выходе из блока оператора вызвать метод Dispose, в котором, как правило, осуществляется освобождение ресурсов. Однако данный механизм можно использовать для самых разных целей. В нашем случае, это будет измерение времени выполнения блока с последующим сохранением результата для анализа. Идея заключается в том, что в блоке using создается экземпляр класса, в момент создания собирается разного рода полезна информация и стартует StopWatch. Когда при выходе из блока отрабатывает Dispose фиксируется результат и объект отправляется для сохранения лога.

Оператор using это синтаксический сахар, при компиляции он трансформируется в блок try-finaly.

Например, код:

using(var obj = new SomeDisposableClass()) {
  // TODO something
}

Конвертируется в конструкцию вида:

IDisposable obj = new SomeDisposableClass();
 try {
  // TODO something
} finally {
  if (obj != null) {
     obj.Dispose();
  }
}

Таким образом, при любом выходе из блока try будет гарантированно и немедленно вызван метод Dispose, при этом логика кода, помещенного в using, никак не изменится. Все что мы поменяли это добавили вызов Dispose. Руководствуясь данной идеей сделаем простейший измеритель времени выполнения кода.

public class Meter :IDisposable {
  private Stopwatch _sw;
  private string _label;

  public static Meter Job(string lable) {
    return new Meter(lable);
  }
  
  Meter(string label) {
    _label = label;
    _sw = Stopwatch.StartNew();
  }
  
  public void Dispose() {
    _sw.Stop();
    Console.WriteLine($"{_label} : {_sw.Elapsed}"); // Здесь логируем
  }
}

И так, что же это нам дает?

// Не ломает выход из функций по return
static int Case0() {
  using (Meter.Job("case-0")) {
    return 1;
  }

  return 2;
}

// Предсказуемо работает в случаях yield return
static IEnumerable<string> Case1() {
  yield return "one";

  using (Meter.Job("case-1")) {
    yield return "two";
    yield return "three";
  }

  yield return "four";
}

// Не ломает прерывание циклов break
static void Case2() {
  while (true) {
    using (Meter.Job("case-2")) {
      // todo something
      break;
    }
  }
}

// Не мешет кострукции switch в любых местах
static int Case3(int @case) {
  using (Meter.Job("case-3")) {
    switch (@case) {
      case 1:
        using (Meter.Job($"case-3-{@case}")) {
          // todo something
          break;
        }
      case 2:
        using (Meter.Job($"case-3-{@case}")) {
          // todo something
          return @case;
        }
    }

  return @case;
  }
}

// Никак не влияет на обработку исключений
static void Case4() {
  try {
    using (Meter.Job($"case-4")) {
      // todo something
      throw new Exception();
    }
  } catch (Exception e) {
    Console.WriteLine(e);
  }
}

Что же не хватает в описанном приеме? Совершенно не раскрыта тема как залогировать результат, понятно, что от записи результата в консоль толку не особенно много. В большинстве случаев, вполне можно использовать распространенные популярные инструменты NLog, Log4Net, Serilog с плюшками визуализацией и минимальной аналитикой. В особо тяжелых случаях может понадобится более сложная аналитика, чтобы разобраться что где происходит.

Хранить результат можно в простом текстовом файле, но для данной задачи считаю это не очень удобным решением, поскольку участков кода может быть много, и они наверняка могут оказаться вложенными, к тому же еще и несколько параллельных потоков. Поэтому исключительно для удобства навигации по логу используем базу SQLite.

Начнем с определения класса, который отвечает за измерение времени и фиксации дополнительной полезной информации для последующего анализа.

public class LogItem : IDisposable {
  public string Id;     // Log item unique id
  public string Label;  // User text labl
  public string Lid;    // Log Id
  public string Method; // Method name
  public int Tid;       // Thread Id
  public DateTime CallTime;  // Start time
  public TimeSpan Elapsed;   // Metering
  public long ElapsedMs;     // Metering miliseconds
  public long ElapsedTicks;  // Metering ticks

  private Stopwatch _sw;
  private Logger _cl;

  public LogItem(Logger cl, string method, string label) {
    Id = Guid.NewGuid().ToString("N");
    _cl = cl;
    Lid = _cl.LId;
    Label = label;
    Method = method;
    Tid = Thread.CurrentThread.ManagedThreadId;

    CallTime = DateTime.Now;
    _sw = new Stopwatch();
    _sw.Start();
  }

  public void Dispose() {
    _sw.Stop();
    Elapsed = _sw.Elapsed;
    ElapsedMs = _sw.ElapsedMilliseconds;
    ElapsedTicks = _sw.ElapsedTicks;
    _cl.WriteLog(this);
  }
}

В конструктор класса LogItem передается ссылка на объект логера и дополнительная информация, полное имя метода в котором производится измерение и метка с произвольным сообщением. Разобраться в логах от исполнения асинхронного кода поможет поле Tid(Thread id), по которому можно группировать данные от одного потока. Так же при создании объекта LogItem фиксируется время начала измерения и стартует StopWatch. В методе Dispose останавливаем StopWatch и вызываем метод логера WriteLog передавая в него объект текущего отстрелявшего и зафиксировавшего всю необходимую информацию LogItem.

У логера по сути две основные задачи инициировать объект LogItem и зафиксировать результат после того как измерение будет закончено. Поскольку у меня все же возникает необходимость фиксировать результат не только в SQLite но так же и в текстовые файлы различных форматов или базы отличные от SQLite, логика взаимодействия вынесена в отдельный класс. В классе Logger оставлена лишь общая часть.

public class Logger {
  public string LId;   // Log id
  public string Login; // User login
  public int Pid;      // Process Id
  public string App;   // Application name
  public string Host;  // Host name
  public string Ip;    // Ip address

  private ConcurrentQueue<dynamic> queue; // Queue log items to save
  public Dictionary<Type, Action<dynamic>> LogDispatcher; // Different log objects handlers dispatcher

  public bool IsEnabled = true;

  public Logger(Dictionary<Type, Action<dynamic>> logDispatcher) {
    queue = new ConcurrentQueue<dynamic>();
    LogDispatcher = logDispatcher;
    LId = Guid.NewGuid().ToString("N");
    Login = WindowsIdentity.GetCurrent().Name;
    Host = Dns.GetHostName();
    Ip = Dns.GetHostEntry(Host).AddressList.FirstOrDefault(f => f.AddressFamily == System.Net.Sockets.AddressFamily.InterNetwork)?.ToString();
    var proc = Process.GetCurrentProcess();
    Pid = proc.Id;
    App = proc.ProcessName;

    queue.Enqueue(this); // Save the starting of a new measurement

    new Thread(() => { // Dequeue and save loop
      dynamic logItem;
      while (true) {
        if (queue.TryDequeue(out logItem)) {
          var logT = logItem.GetType();
          if (LogDispatcher.ContainsKey(logT)) {
            LogDispatcher[logT](logItem);
          }
        } else {
          Thread.Sleep(500);
        }
      }}) { IsBackground = true}.Start();
  }

  public LogItem Watch(int level, string label = null) {
    return new LogItem(this, GetMethodFullName(level), label);
  }

  private static string GetMethodFullName(int level) {
    var t = new StackTrace().GetFrames()?[level].GetMethod();

    if (t == null) return "";

    var path = t.ReflectedType != null ? t.ReflectedType.FullName : "_";

    return $"{path}.{t.Name}";
  }

  public void WriteLog(LogItem li) {
    if (IsEnabled) {
      queue.Enqueue(li);
    }
  }
}

И так, класс Logger является промежуточным, его задача собрать информацию касательно среды в которой запускается логирование. В приведенном примере это login пользователя, имя машины, сетевой адрес ID и имя процесса. Вся эта информация бывает полезна, когда хотим измерить время выполнения участков кода на машине пользователя, т.е. нужна по сути для идентификации в случае обнаружения аномалий. Думаю, читатель согласится что важно чтобы логер при измерении оказывал минимальное влияние на время выполнения измеряемого кода. Именно поэтому сохранение результата осуществляется через добавление ее в очередь, которую раскручивает фоновый процесс, сохраняя результат в базу, файл или передавая по сети. У такого подхода есть серьезный недостаток, если событий логирования будет слишком много очередь будет заполняться быстрее чем раскручиваться, пока не займет всю доступную приложению память. Но чтобы спровоцировать эту ситуацию нужно еще постараться. Диспетчеризация процедур обработчиков для сохранения разных классов осуществляет через словарь, в котором ключ — это тип, значение – процедура сохранения объекта этого типа.

Для класса логирования, который будет приведен ниже необходимо удовлетворить зависимость, установив nuget пакет System.Data>SQLite.

    public class SqliteLogger {
        private readonly HLTimeCall.Logger _iternalLogger;
        protected string _connectionString;
        static object dbLocker = new object();
        public SqliteLogger() {
            InitDb();
            var dispatcher = new Dictionary<Type, Action<dynamic>>();
            dispatcher[typeof(HLTimeCall.Logger)] = o => LogMainRecord(o);
            dispatcher[typeof(HLTimeCall.LogItem)] = o => LogCall(o);
            _iternalLogger = new HLTimeCall.Logger(dispatcher);
        }

        private void InitDb() {
            const string databaseFile = "TimeCallLogs.db";
            _connectionString = $"Data Source = {Path.GetFullPath(databaseFile)};";

            var dbFileName = Path.GetFullPath(databaseFile);
            if (!File.Exists(dbFileName)) {
                SQLiteConnection.CreateFile(dbFileName);
                Bootstrap();
            }
        }

        struct DbNames {
            public const string TMainRecord = "T_MAINRECORD";
            public const string TCalllog = "T_CALLLOG";

            public const string FLid = "LID";
            public const string FLogin = "LOGIN";
            public const string FPid = "PID";
            public const string FApp = "APP";
            public const string FHost = "HOST";
            public const string FIp = "IP";

            public const string FId = "ID";
            public const string FLabel = "LABEL";
            public const string FMethod = "METHOD";
            public const string FTid = "TID";
            public const string FCallTime = "CALL_TIME";
            public const string FElapsed = "ELAPSED";
            public const string FElapsedMs = "ELAPSED_MS";
            public const string FElapsedTicks = "ELAPSED_TICKS";
        }

        public void Bootstrap() {
            lock (dbLocker) {
                using (var conn = Connect()) {
                    using (var cmd = conn.CreateCommand()) {
                        cmd.Transaction = conn.BeginTransaction();
                        cmd.CommandType = System.Data.CommandType.Text;

                        cmd.CommandText =
                            $"CREATE TABLE {DbNames.TMainRecord} ({DbNames.FLid} VARCHAR(45) PRIMARY KEY UNIQUE NOT NULL, {DbNames.FLogin} VARCHAR(45), {DbNames.FPid} INTEGER, {DbNames.FApp} VARCHAR(45), {DbNames.FHost} VARCHAR(45), {DbNames.FIp} VARCHAR(45))";
                        cmd.ExecuteNonQuery();

                        cmd.CommandText =
                            $"CREATE TABLE {DbNames.TCalllog} ({DbNames.FId} VARCHAR(45) PRIMARY KEY UNIQUE NOT NULL, {DbNames.FLabel} VARCHAR(45), {DbNames.FLid} VARCHAR(45) NOT NULL, {DbNames.FMethod} VARCHAR(150), {DbNames.FTid} VARCHAR(45), {DbNames.FCallTime} DATETIME, {DbNames.FElapsed} TIME, {DbNames.FElapsedMs} INTEGER, {DbNames.FElapsedTicks} INTEGER)";
                        cmd.ExecuteNonQuery();

                        cmd.Transaction.Commit();
                    }
                }
            }
        }

        private DbConnection Connect() {
            var conn = new SQLiteConnection(_connectionString);
            conn.Open();

            return conn;
        }

        public HLTimeCall.LogItem Watch(string label = null) {
            return _iternalLogger.Watch(3, label);
        }

        static object CreateParameter(string key, object value) {
            return new SQLiteParameter(key, value ?? DBNull.Value);
        }

        private void LogMainRecord(HLTimeCall.Logger logItem) {
            lock (dbLocker) {
                using (var conn = Connect()) {
                    using (var cmd = conn.CreateCommand()) {
                        cmd.Transaction = conn.BeginTransaction();
                        cmd.CommandType = System.Data.CommandType.Text;
                        cmd.Parameters.Add(CreateParameter(DbNames.FLid, logItem.LId));
                        cmd.Parameters.Add(CreateParameter(DbNames.FLogin, logItem.Login));
                        cmd.Parameters.Add(CreateParameter(DbNames.FPid, logItem.Pid));
                        cmd.Parameters.Add(CreateParameter(DbNames.FApp, logItem.App));
                        cmd.Parameters.Add(CreateParameter(DbNames.FHost, logItem.Host));
                        cmd.Parameters.Add(CreateParameter(DbNames.FIp, logItem.Ip));
                        cmd.CommandText =
                            $"INSERT INTO {DbNames.TMainRecord}({DbNames.FLid},{DbNames.FLogin},{DbNames.FPid},{DbNames.FApp},{DbNames.FHost},{DbNames.FIp})VALUES(:{DbNames.FLid},:{DbNames.FLogin},:{DbNames.FPid},:{DbNames.FApp},:{DbNames.FHost},:{DbNames.FIp})";
                        cmd.ExecuteNonQuery();
                        cmd.Transaction.Commit();
                    }
                }
            }
        }

        private void LogCall(HLTimeCall.LogItem logItem) {
            lock (dbLocker) {
                using (var conn = Connect()) {
                    using (var cmd = conn.CreateCommand()) {
                        cmd.Transaction = conn.BeginTransaction();
                        cmd.CommandType = System.Data.CommandType.Text;
                        cmd.Parameters.Add(CreateParameter(DbNames.FId, logItem.Id));
                        cmd.Parameters.Add(CreateParameter(DbNames.FLabel, logItem.Label));
                        cmd.Parameters.Add(CreateParameter(DbNames.FLid, logItem.Lid));
                        cmd.Parameters.Add(CreateParameter(DbNames.FMethod, logItem.Method));
                        cmd.Parameters.Add(CreateParameter(DbNames.FTid, logItem.Tid));
                        cmd.Parameters.Add(CreateParameter(DbNames.FCallTime, logItem.CallTime));
                        cmd.Parameters.Add(CreateParameter(DbNames.FElapsed, logItem.Elapsed));
                        cmd.Parameters.Add(CreateParameter(DbNames.FElapsedMs, logItem.ElapsedMs));
                        cmd.Parameters.Add(CreateParameter(DbNames.FElapsedTicks, logItem.ElapsedTicks));
                        cmd.CommandText =
                            $"INSERT INTO {DbNames.TCalllog}({DbNames.FId},{DbNames.FLabel},{DbNames.FLid},{DbNames.FMethod},{DbNames.FTid},{DbNames.FCallTime},{DbNames.FElapsed},{DbNames.FElapsedMs},{DbNames.FElapsedTicks})VALUES(:{DbNames.FId},:{DbNames.FLabel},:{DbNames.FLid},:{DbNames.FMethod},:{DbNames.FTid},:{DbNames.FCallTime},:{DbNames.FElapsed},:{DbNames.FElapsedMs},:{DbNames.FElapsedTicks})";
                        cmd.ExecuteNonQuery();
                        cmd.Transaction.Commit();
                    }
                }
            }
        }
    }

Как уже было сказано, класс SqliteLogger отвечает за сохранение результатов измерения в базу. Прежде чем начать использовать базу ее нужно создать, этому и посвящено большее количество строчек кода. Здесь класс будет логировать факт создания логера(подразумевается что это происходит одновременно с запуском приложения), результат будет сохранен в таблицу T_MAINRECORD. Так же будем сохранять результат измерения в таблицу T_CALLLOG. За сохранение этих двух событий отвечают методы LogMainRecord и LogCall, ссылки на которые сохраняются в словаре dispatcher. Для правильного создания объекта LogItem нужно использовать функцию Watch, в блоке инициализации оператора using.

Например, так:

var cMeter = new SqliteLogger();

using (cMeter.Watch("Мы измеряли это место")) {
  // TODO
}

Теперь, чтобы использовать данный инструмент нужно расставить блоки using в сомнительных местах и дать приложению поработать. После остается проанализировать собранную информацию, которой надеюсь будет достаточно чтобы выявить проблемное место. Предлагаю подумать какие еще метрики можно собрать при помощи этого приема?

Спасибо за внимание, удачи и быстрого кода :-)