Herramienta conveniente para medir el código C #

En un producto rápido, grande y complejo, encontrar cuellos de botella en términos de rendimiento no es una tarea trivial. Por supuesto, existen herramientas para resolver tales problemas, por ejemplo, BenchmarkDotNet . Sin lugar a dudas, esta es una herramienta útil y necesaria, pero no siempre es conveniente. Esto se puede detectar, por ejemplo, cuando es necesario medir no el método público por completo mediante la configuración del atributo correspondiente, sino algún fragmento de código dentro del método privado. Aquí, en ningún caso criticaré la herramienta designada, pero solo quiero señalar la necesidad de una forma ligeramente diferente de recopilar métricas para fragmentos de código. Existen métodos muy complejos y confusos, con ramificación, con bucles, manejo de situaciones excepcionales, y el lugar del problema puede estar en algún lugar dentro. Para encontrarlo, debe cubrir abundantemente el código con instrumentos de medición, mientras que existe un deseo obvio de no tocar o procesar la lógica existente.

Puede usar la clase StopWatch para medir el tiempo de ejecución de las secciones de código.

Algo como esto:

var sw = new Stopwatch(); sw.Start(); //   sw.Stop(); Console.WriteLine(sw.Elapsed); //   

Para no colocar StopWatch por código cada vez, puede unificar el procedimiento de medición a través de una función de orden superior, por ejemplo, así:

 static void LambdaMeter(string label, Action act) { var sw = new Stopwatch(); sw.Start(); act(); sw.Stop(); Console.WriteLine($"{label} : {sw.Elapsed}"); //   } 

Y usa de esta manera:

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

Puede activar la llamada al revés a través de la extensión:

 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}"); //   } } 

Y use así:

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

Parece que el problema parece estar resuelto, pero aún así esta técnica es extremadamente limitada. El hecho es que puede haber salidas de retorno en el código medido, por lo que no puede ajustarlo en Acción. Incluso usar Func no resolverá el problema. A continuación, quiero describir una técnica que usé más de una vez, con los cambios más pequeños en el código resolverá el problema de medir secciones arbitrarias de código. Construiremos un registrador simple y compacto para medir la velocidad de ejecución; si es necesario, también es bastante simple modificarlo para otras necesidades, por ejemplo, para buscar pérdidas de memoria. El siguiente código no pretende ser completo y funcional, sino una demostración del principio sobre la base de la cual puede construir una herramienta realmente útil y fácil. Sin embargo, el código funciona y se puede utilizar con el fin de recopilar métricas tal cual o adaptarse a tareas más específicas. También quiero señalar que en el siguiente código se recopila información adicional, como el ID del proceso o el nombre del host. Estos parámetros me fueron útiles en ciertas situaciones y se dejan únicamente como ejemplo. Cualquiera que decida adaptar el código a sus tareas puede necesitar recopilar parámetros completamente diferentes, en parte por esta razón el código especificado no se publicó en el GitHub público como un producto terminado.

C # tiene una declaración de uso bien conocida y útil, es aplicable a los tipos que admiten la interfaz IDisposable. El punto es que, cuando salga del bloque de operador, llame al método Dispose, en el que, por regla general, se liberan recursos. Sin embargo, este mecanismo puede usarse para una variedad de propósitos. En nuestro caso, esto será una medida del tiempo de ejecución del bloque, seguido de guardar el resultado para su análisis. La idea es que se cree una instancia de la clase en el bloque de uso, en el momento de la creación, se recopilan varios tipos de información útil y se inicia StopWatch. Cuando Dispose se ejecuta al salir del bloque, el resultado es fijo y el objeto se envía para guardar el registro.

La declaración de uso es azúcar sintáctica; cuando se compila, se transforma en un bloque try-finaly.

Por ejemplo, el código:

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

Convertido a un diseño de la forma:

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

Por lo tanto, en cualquier salida del bloque try, el método Dispose estará garantizado y se llamará de inmediato, mientras que la lógica del código que se utiliza no cambiará de ninguna manera. Todo lo que cambiamos es agregar una llamada Dispose. Guiados por esta idea, haremos el medidor de tiempo de ejecución más simple.

 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}"); //   } } 

Y entonces, ¿qué nos da esto?

 //       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); } } 

¿Qué falta en la técnica descrita? El tema de cómo asegurar el resultado no se reveló por completo, está claro que no tiene mucho sentido registrar el resultado en la consola. En la mayoría de los casos, es bastante posible utilizar las populares herramientas populares NLog, Log4Net, Serilog con bollos de visualización y análisis mínimos. En casos especialmente severos, se pueden necesitar análisis más sofisticados para descubrir qué sucede.

Puede almacenar el resultado en un archivo de texto simple, pero para esta tarea creo que esta no es una solución muy conveniente, ya que puede haber muchas piezas de código, y probablemente puedan estar anidadas, además de varios hilos paralelos. Por lo tanto, únicamente para la conveniencia de navegar por el registro, utilizamos la base de datos SQLite.

Comenzamos definiendo una clase que es responsable de medir el tiempo y capturar información adicional útil para su posterior análisis.

 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); } } 

Se pasa un enlace al objeto registrador e información adicional al constructor de la clase LogItem, el nombre completo del método en el que se realiza la medición y una etiqueta con un mensaje arbitrario. Para comprender los registros de la ejecución de código asíncrono, el campo Tid (Id. De subproceso) ayudará, mediante el cual puede agrupar datos de un subproceso. Además, al crear un objeto LogItem, el tiempo de inicio de la medición es fijo y se inicia StopWatch. En el método Dispose, detenga StopWatch y llame al método de registro WriteLog, pasando el objeto del tirador actual y reparando toda la información necesaria de LogItem.

El registrador esencialmente tiene dos tareas principales: iniciar un objeto LogItem y registrar el resultado después de que se complete la medición. Como todavía tengo la necesidad de registrar el resultado no solo en SQLite sino también en archivos de texto de varios formatos o bases de datos que no sean SQLite, la lógica de interacción se coloca en una clase separada. En la clase Logger, solo queda la parte general.

 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); } } } 

Y así, la clase Logger es intermedia, su tarea es recopilar información sobre el entorno en el que se inicia el registro. En el ejemplo anterior, este es el inicio de sesión del usuario, el nombre de la máquina, la identificación de la dirección de red y el nombre del proceso. Toda esta información es útil cuando queremos medir el tiempo de ejecución de secciones de código en la máquina del usuario, es decir. Esencialmente para la identificación en caso de detección de anomalías. Creo que el lector estará de acuerdo en que es importante que el registrador durante la medición tenga un impacto mínimo en el tiempo de ejecución del código medido. Es por eso que guardar el resultado se lleva a cabo agregándolo a la cola, que gira el proceso en segundo plano, guardando el resultado en la base de datos, archivo o transfiriéndolo a través de la red. Este enfoque tiene un serio inconveniente: si hay demasiados eventos de registro, la cola se llenará más rápido que girar hasta que ocupe toda la memoria disponible para la aplicación. Pero para provocar esta situación, aún debe intentarlo. El envío de procedimientos de controlador para guardar diferentes clases se lleva a cabo a través de un diccionario en el que la clave es un tipo, el valor es el procedimiento para guardar un objeto de este tipo.

Para la clase de registro, que se proporcionará a continuación, es necesario satisfacer la dependencia instalando el paquete 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(); } } } } } 

Como ya se mencionó, la clase SqliteLogger es responsable de almacenar los resultados de la medición en la base de datos. Antes de comenzar a usar la base de datos, debe crearla; se dedican más líneas de código a esto. Aquí la clase registrará el hecho de crear el registrador (se entiende que esto sucede simultáneamente con el inicio de la aplicación), el resultado se guardará en la tabla T_MAINRECORD. También guardaremos el resultado de la medición en la tabla T_CALLLOG. Los métodos LogMainRecord y LogCall son responsables de almacenar estos dos eventos; las referencias a ellos se almacenan en el diccionario del despachador. Para crear el objeto LogItem correctamente, debe usar la función Watch en el bloque de inicialización de la instrucción using.

Por ejemplo, así:

 var cMeter = new SqliteLogger(); using (cMeter.Watch("   ")) { // TODO } 

Ahora, para usar esta herramienta, debe organizar el uso de bloques en lugares cuestionables y dejar que la aplicación funcione. Después de eso, queda por analizar la información recopilada, que espero sea suficiente para identificar el lugar del problema. ¿Propongo pensar en qué otras métricas se pueden recopilar utilizando esta técnica?

Gracias por su atención, buena suerte y código rápido :-)