company_banner

Удобный инструмент для измерений C# кода

  • Tutorial

В стремительно развивающемся, большом и сложном продукте поиск узких мест, в плане производительности, становится не тривиальной задачей. Конечно есть инструменты для решения таких задач, например, 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 в сомнительных местах и дать приложению поработать. После остается проанализировать собранную информацию, которой надеюсь будет достаточно чтобы выявить проблемное место. Предлагаю подумать какие еще метрики можно собрать при помощи этого приема?

Спасибо за внимание, удачи и быстрого кода :-)
Tinkoff
it’s Tinkoff — просто о сложном

Комментарии 14

    +6

    Разве такие потребности не решаются тем же прометеусом?
    А у вас здесь кроме неподдерживаемого кода ещё и создание тредов руками (ещё и без try..catch, что может привести к краху всего процесса) и динамики непонятно зачем и это на первый взгляд только.
    Ну и ещё вопросы — кто будет ваш тред останавливать, учитывая, что при завершении процесса в очереди могут быть ещё задачи?
    и BlockingCollection был бы здесь более подходящим вариантом с его семафорами и GetConsumingEnumerable, а не Thread.Sleep в цикле как у вас.

      +1
      А какие потребности решаются прометеусом? Хранение метрик, да решаются. Здесь я пишу как обложить код измерителями не нарушая его работу, а как хранить вопрос уже другой. На удаленных машинах(подразумевается desctop приложение) может и не быть доступа к серверу прометеуса, а померить что-то нужно, как вариант можно использовать sqlite базу, почему нет.

      Неподдерживаемый код — ну что за инфантильные ярлыки? Ну почему же тредов руками? Первое — тред один. Второе — интересно узнать каким место вы создаете треды? Только не надо писать про Task, он нужен когда создается множество тредов через тредпул(под капотом) и с удобным управлением. Вот насчет try..catch, соглашусь не помешал бы, хотя у меня еще не было в этом месте исключений, но в принципе они возможны. Динамика понятно зачем нужна, чтобы отвязаться от типов, иногда это удобно, например, чтобы писать обработчики для уже существующих или произвольных logItem. Злоупотреблять динамикой не стоит, но иногда и чуть-чуть, где это сэкономит время и силы почему же нет?

      Тред из-баграунд, остановится влсед за приложением. Нет цели собрать абсолютно все измерения, зачем? К тому же даже если остановить тред, в очереди останутся события, и что остановка изменит, зачем это?

      BlockingCollection был бы здесь более подходящим вариантом

      Вполне возможно и лучше, согласен, одно и тоже можно сделать разными способами, выбор способа отчасти вопрос привычки.
        +2
        А какие потребности решаются прометеусом? Хранение метрик, да решаются

        Оп, извиняюсь, я тут имел ввиду AppMetrics и его аналоги.
        Неподдерживаемый код потому, что никому кроме вас он не нужен — тот же AppMetrics лучше протестирован и постоянно обновляется/фиксятся баги.


        Только не надо писать про Task, он нужен когда создается множество тредов через тредпул(под капотом) и с удобным управлением

        Отчего же не надо, когда тут самый подходящий случай? И тредпул как раз-таки не про множество тредов, а совсем наоборот чтобы треды не плодить.
        И кстати, если бы использовали нормальную очередь с поддержкой асинхронного ожидания, то выделять тред вообще бы не пришлось.
        Но если уж так надо было сделать всё синхронно, то можно выставить TaskCreationOptions.LongRunning, чтобы тредпул (но только если понадобится!) не стеснялся создать ещё один тред.


        Извиняюсь, что несколько резко высказываюсь, с утра воду отключили.

          0
          Оп, извиняюсь, я тут имел ввиду AppMetrics и его аналоги.

          Может быть, не могу сказать.
          никому кроме вас он не нужен

          Не следует говорить за всех)
          лучше протестирован и постоянно обновляется/фиксятся баги

          Вспоминается цитата):
          Есть два способа разработки проекта приложения: сделать его настолько простым, чтобы было очевидно, что в нем нет недостатков, или сделать его таким сложным, чтобы в нем не было очевидных недостатков. Ч. Э. Р. Хоар (C. A. R. Hoare)

          Отчего же не надо, когда тут самый подходящий случай? И тредпул как раз-таки не про множество тредов, а совсем наоборот чтобы треды не плодить.

          Тут наверно можем долго спорить. Как я понимаю основная идея тредпула это ускорить создание потоков, типа кеширования для потоков. Ресурсы под поток выделяются достаточно долго, что легко проверить например создав 10к потоков в цикле. Тредпул на то и пул что содержит уже готовые потоки, которые переиспользуются для выполнения тех же тасков. Поэтому 10к тасков создаются быстро и достаточно быстро обрабатываются на уже готовых потоках. А если у меня 1 поток на все время жизни приложения, зачем же мне таск, хотя не исключаю что его можно использовать. Кстати с тасками и тредпулами тоже есть нюансы, некоторые потоки используются для числодробилок вычислений их создавать больше чем ядер смысла нет. Другие могут использоваться для ввода вывода и большую часть времени висят в блокировке, таких можно создавать почти неограниченно, цпу для них не основной ресурс. Некоторые типы потоков могут потреблять много памяти их количество нужно регулировать по доступной для процесса памяти. В этих случаях под разные задачи приходится писать кастомные тредпулы. В случае создания треда «руками», во всю эту механику не вмешиваемся.
          если бы использовали нормальную очередь

          За это спасибо, подумаю над этим, вполне возможно вы правы, стоит попробовать BlockingCollection.

          Извиняюсь, что несколько резко высказываюсь, с утра воду отключили.

          Понимаю вас, с утра не обнаружить в кране воду это жестко. Казалось бы 21 век, компьютеры, ракеты, а бесперебойную подачу воды реализовать не могут!
          +1

          Похоже Вы изобрели https://miniprofiler.com/

            0
            Кстати да, очень похоже. Нужно будет пощупать.
        0

        del

          +4
          Однажды мне попало на поддержку весьма жирное и написанное не по феншую приложение, афтор которого бесследно исчез. Приложение начало сильно тормозить, а оно активно использовалось для решения бизнес задач. И мне пришлось экстремально быстро искать проблему, причем нужно было понять что происходит внутри весьма длинных методов. Тогда буквально за 20 минут и был написан почти этот логер, он помог решить проблему достаточно быстро. Потом я его немного причесал и стал много где использовать, в том числе и вместе с тем же Prometheus. Статью писал исключительно чтобы поделиться идеей, кто-то может столкнуться с похожей задачей, а кто-то может придумать как адаптировать решение для своих целей.
            +3
            Несколько лет назад реализовал и поддерживаю нечто подобное, только гораздо более монструозное решение. Одновременно решает проблему логирования и профилирования.
            Настраиваемые логеры, древовидная структура вызовов, замер времени выполнения операции, логирование ошибок, возможность замера времени выполнения без логирования (для ведения статистики) и тому подобное.
            Читабельность логов повысилась кардинально. Обложенные логами методы пишут точку вход и выхода из операции, её уникальный номер. Очень помогает в многопоточном коде, избавляет от необходимости россыпи строк типа «Log.Debug(»Begin ...)" «Log.Debug(»End...)".
            Есть предварительная договорённость с менеджментом по выводу этого кода в опенсорс с публикацией на гите и NuGet, но пока руки не доходят.
            П.С.: В нашем решении асинхронности нет. После каждого изменения в этом коде делаю замеры студийным профайлером — оверхед на логирование минимальный, измеряется долями процента, а качества анализа логов и закрытия саппорт-тикетов повышается кардинально.
            Пример вывода профайлера (периодически пишется в логи для выяснения боттлнеков при жалобах на производительность приложения):
              0
              Очень интересно, хотелось бы посмотреть. Поделитесь пожалуйста ссылкой если все же решитесь опубликовать.
                +3
                Как только соберусь — обязательно статья на хабре будет. Можете подписаться, чтобы не пропустить.
              0

              Лично я для измерения кода предпочитаю пользоваться линейкой.




              А если серьёзно, то в нашем проекте очень похожая структура для сбора статистики, только на Java:
              try (var psr = new WatchScope(<...name...>)) { }.

                –4
                1)Имхо использование using'а не по назначению не правильно… Еще бы в финализаторы позапихивать измерение метрик кода
                2)Зачем писать свой логгер, если можно использовать какой-нибудь log4net, который может писать куда угодно и поддерживает параллельную запись в файл из разных потоков.
                  +2
                  Простите, а где можно почитать о назначении директивы using и о том, где её можно использовать, а где нет?
                  using — это всего лишь синтаксический сахар, превращаемый компилятором в конструкцию:
                  try {… } finally { if (obj != null) obj.Dispose(); }
                  Поэтому не вижу ничего криминального в использовании using там, где это сокращает объём кода, особенно с C#8, который дал возможность упрощать using до одной строки.

                  Что касается второй части — никто не отменяет log4net. Просто обычные логгеры не умеют логировать время выполнения операций, поэтому есть смысл использовать их в связке с конструкцией, типа той, что предложена автором статьи. Логгер — это абстракция, и не имеет значения куда пишутся записи — файл, база, почта, веб-сервис. Смысл предложенной конструкции совсем не в этом.

                Только полноправные пользователи могут оставлять комментарии. Войдите, пожалуйста.

                Самое читаемое