Ferramenta conveniente para medir o código C #

Em um produto rápido, grande e complexo, encontrar gargalos em termos de desempenho não é uma tarefa trivial. Obviamente, existem ferramentas para resolver esses problemas, por exemplo, o BenchmarkDotNet . Sem dúvida, esta é uma ferramenta útil e necessária, mas nem sempre é conveniente. Isso pode ser detectado, por exemplo, quando é necessário medir não o método público completamente, definindo o atributo correspondente, mas algum trecho de código dentro do método privado. Aqui, em nenhum caso, criticarei a ferramenta designada, mas quero apenas apontar a necessidade de uma maneira ligeiramente diferente de coletar métricas para fragmentos de código. Existem métodos muito complexos e confusos, com ramificação, com loops, lidando com situações excepcionais, e o problema pode estar em algum lugar. Para encontrá-lo, é necessário cobrir abundantemente o código com instrumentos de medição, enquanto existe um desejo óbvio de não tocar ou processar a lógica existente.

Você pode usar a classe StopWatch para medir o tempo de execução das seções de código.

Algo assim:

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

Para não inserir o StopWatch por código a cada vez, você pode unificar o procedimento de medição por meio de uma função de ordem superior, por exemplo, da seguinte forma:

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

E use desta maneira:

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

Você pode virar a chamada de dentro para fora através do ramal:

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

E use assim:

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

Parece que o problema parece estar resolvido, mas ainda assim essa técnica é extremamente limitada. O fato é que pode haver saídas de retorno no código medido, portanto você não pode agrupá-lo em Ação. Mesmo usando o Func não resolverá o problema. Abaixo, quero descrever uma técnica que usei mais de uma vez, com as menores alterações no código resolverá o problema de medir seções arbitrárias do código. Vamos construir um logger simples e compacto para medir a velocidade de execução; se necessário, também é bastante simples modificá-lo para outras necessidades, por exemplo, procurar vazamentos de memória. O código abaixo não afirma ser completo e funcional, mas uma demonstração do princípio com base no qual você pode criar uma ferramenta realmente útil e fácil. No entanto, o código está funcionando e pode ser usado com a finalidade de coletar métricas como estão ou adaptadas para tarefas mais específicas. Também quero observar que no código abaixo são coletadas informações adicionais, como o ID do processo ou o nome do host. Esses parâmetros foram úteis para mim em determinadas situações e são deixados apenas como exemplo. Qualquer pessoa que decida adaptar o código às suas tarefas pode precisar coletar parâmetros completamente diferentes; em parte por esse motivo, o código especificado não foi publicado no GitHub público como um produto final.

O C # possui uma instrução de uso bem conhecida e útil, é aplicável a tipos que suportam a interface IDisposable. O ponto é que, quando você sai do bloco do operador, chame o método Dispose, no qual, via de regra, os recursos são liberados. No entanto, esse mecanismo pode ser usado para vários propósitos. No nosso caso, isso será uma medida do tempo de execução do bloco, seguido pelo salvamento do resultado para análise. A ideia é que uma instância da classe seja criada no bloco using, no momento da criação, vários tipos de informações úteis são coletadas e o StopWatch é iniciado. Quando Dispose é executado ao sair do bloco, o resultado é corrigido e o objeto é enviado para salvar o log.

A instrução using é açúcar sintático; quando compilada, ela se transforma em um bloco try-finaly.

Por exemplo, o código:

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

Convertido em um design do formulário:

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

Assim, em qualquer saída do bloco try, o método Dispose será garantido e chamado imediatamente, enquanto a lógica do código colocado em uso não será alterada de forma alguma. Tudo o que mudamos é adicionar uma chamada Dispose. Guiados por essa idéia, faremos o medidor de tempo de execução mais simples.

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

E então, o que isso nos dá?

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

O que está faltando na técnica descrita? O tópico de como proteger o resultado não foi completamente divulgado, é claro que não faz muito sentido registrar o resultado no console. Na maioria dos casos, é bem possível usar as ferramentas populares populares NLog, Log4Net, Serilog com pães de visualização e análises mínimas. Em casos especialmente graves, análises mais sofisticadas podem ser necessárias para descobrir o que acontece.

Você pode armazenar o resultado em um arquivo de texto simples, mas, para esta tarefa, acho que essa não é uma solução muito conveniente, pois pode haver muitos trechos de código e provavelmente podem ser aninhados, além disso, vários threads paralelos. Portanto, apenas para a conveniência de navegar no log, usamos o banco de dados SQLite.

Começamos definindo uma classe que é responsável por medir o tempo e capturar informações úteis adicionais para análises posteriores.

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

Um link para o objeto do logger e informações adicionais são transmitidas ao construtor da classe LogItem, o nome completo do método no qual a medição é feita e um rótulo com uma mensagem arbitrária. Para entender os logs da execução do código assíncrono, o campo Tid (ID do thread) ajudará, pelo qual você pode agrupar dados de um thread. Além disso, ao criar um objeto LogItem, o horário de início da medição é fixo e o StopWatch é iniciado. No método Dispose, pare o StopWatch e chame o método do registrador WriteLog, passando o objeto do shooter atual e fixando todas as informações necessárias do LogItem.

O criador de logs possui basicamente duas tarefas principais: iniciar um objeto LogItem e registrar o resultado após a conclusão da medição. Como ainda tenho a necessidade de registrar o resultado não apenas no SQLite, mas também em arquivos de texto de vários formatos ou bancos de dados que não sejam o SQLite, a lógica da interação é colocada em uma classe separada. Na classe Logger, apenas a parte geral é deixada.

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

E assim, a classe Logger é intermediária, sua tarefa é coletar informações sobre o ambiente em que o log é iniciado. No exemplo acima, este é o login do usuário, nome da máquina, ID do endereço de rede e nome do processo. Toda essa informação é útil quando queremos medir o tempo de execução de seções de código na máquina do usuário, ou seja, Essencialmente para identificação em caso de detecção de anomalias. Acho que o leitor concorda que é importante que o criador de logs durante a medição tenha um impacto mínimo no tempo de execução do código medido. É por isso que o resultado é realizado adicionando-o à fila, que gira o processo em segundo plano, salvando o resultado no banco de dados, arquivo ou transferindo-o pela rede. Essa abordagem tem uma desvantagem séria: se houver muitos eventos de log, a fila será preenchida mais rapidamente do que girando até ocupar toda a memória disponível para o aplicativo. Mas, para provocar essa situação, você ainda precisa tentar. O envio de procedimentos do manipulador para salvar diferentes classes é realizado por meio de um dicionário no qual a chave é um tipo, o valor é o procedimento para salvar um objeto desse tipo.

Para a classe de log, que será fornecida abaixo, é necessário satisfazer a dependência instalando o pacote de 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 já mencionado, a classe SqliteLogger é responsável por armazenar os resultados da medição no banco de dados. Antes de começar a usar o banco de dados, é necessário criá-lo; mais linhas de código são dedicadas a isso. Aqui a classe registrará o fato de criar o criador de logs (entende-se que isso acontece simultaneamente com o lançamento do aplicativo), o resultado será salvo na tabela T_MAINRECORD. Também salvaremos o resultado da medição na tabela T_CALLLOG. Os métodos LogMainRecord e LogCall são responsáveis ​​por armazenar esses dois eventos; as referências a eles são armazenadas no dicionário do dispatcher. Para criar o objeto LogItem corretamente, você precisa usar a função Watch no bloco de inicialização da instrução using.

Por exemplo, assim:

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

Agora, para usar essa ferramenta, você precisa organizar o uso de blocos em locais questionáveis ​​e deixar o aplicativo funcionar. Depois disso, resta analisar as informações coletadas, que, espero, sejam suficientes para identificar o local do problema. Proponho pensar em quais outras métricas podem ser coletadas usando essa técnica?

Obrigado pela atenção, boa sorte e código rápido :-)