Neste artigo, coloquei benchmarks das chamadas mais privadas de loggers. Conduzi todos os experimentos no log4net e NLog, no Intel Windows 10 x64 com SSD M.2.

Os resultados brutos podem ser visualizados no GitHub . O código está no mesmo repositório (é necessário o .Net 4.7.2 + Microsoft Visual Studio 2017+ para executar).

O que, como e por quê - sob o corte.

Para não ler por muito tempo, a tabela de resultados:

NoOpLogging

Primeiro, vamos estimar quanto gastamos tempo chamando um método para registro, o que no final não levará a nada. Na maioria dos casos (na minha experiência), o Debug detalhado está desativado nos servidores de batalha, no entanto, ninguém remove as chamadas.

Primeiro, o resultado:

E o código:

void Log4NetNoParams() => _log4Net.Debug("test"); void Log4NetSingleReferenceParam() => _log4Net.DebugFormat("test {0}", _stringArgument); void Log4NetSingleValueParam() => _log4Net.DebugFormat("test {0}", _intArgument); void Log4NetMultipleReferencesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void Log4NetMultipleValuesParam() => _log4Net.DebugFormat( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); void NLogNetNoParams() => _nlog.Debug("test"); void NLogNetSingleReferenceParam() => _nlog.Debug("test {0}", _stringArgument); void NLogNetSingleValueParam() => _nlog.Debug("test {0}", _intArgument); void NLogNetMultipleReferencesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument, _stringArgument); void NLogNetMultipleValuesParam() => _nlog.Debug( "test {0} {1} {2} {3} {4} {5} {6} {7} {8}", _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument, _intArgument); 

Primeiro, vamos determinar por que esses testes foram escolhidos:

• Os experimentos foram realizados nas bibliotecas mais populares.

• NLog e log4net têm assinaturas de funções diferentes para um pequeno número de argumentos:

  
  
  • log4net:
  
  

   void DebugFormat(string format, object arg0) 

  
  
  • Nlog:
  
  

   void Debug(string message, string argument) void Debug<TArgument>(string message, TArgument argument) 

  
  
  • Teoria: ao transferir um tipo significativo para o log4net, o boxe deve ocorrer, o que simplesmente gasta o tempo do processador e não leva a nada. No caso do NLog, não existe esse comportamento, portanto, o último deve funcionar mais rapidamente.
  
  
• As assinaturas para um grande número de argumentos nas bibliotecas são aproximadamente as mesmas, então eu gostaria de saber:
  
  • Quão mais eficiente é invocar métodos com um pequeno número de parâmetros.
  • Existe uma diferença na velocidade de chamar o método "Is ... Enabled" entre as duas bibliotecas

E agora a análise dos resultados:

• Devido ao uso de argumentos genéricos no NLog, ele funciona mais rápido no caso em que o log direto não é necessário. Ou seja, no caso em que no seu programa Debug o nível é ativado apenas no sistema de teste, apenas alterar a biblioteca pode acelerar o software (e melhorar a vida dos usuários).
• Se você tiver desativado o log e quiser chamar um método com um grande número de argumentos, será mais eficiente dividi-lo em dois. Por esse motivo, as chamadas de método acima funcionarão dez vezes mais rápido.
• Quando você escreve uma função que pode receber qualquer objeto, geralmente é mais eficaz ficar confuso e criar uma função genérica. Devido a uma otimização tão simples, o código funcionará mais rapidamente (isso é claramente visto na diferença de horário entre as chamadas para Log4NetSingleReferenceParam e Log4NetSingleValueParam )

Registro de arquivos

A maioria dos programas (de acordo com minhas observações) ainda registra os resultados em um arquivo, portanto, para comparação, escolhemos esta operação. Por uma questão de simplicidade, apenas assumimos a configuração dos registradores quando um arquivo é gravado no arquivo sem buffer, sem bloqueios adicionais, etc.

Resultados:

Código usado:

• log4net:

 var roller = new RollingFileAppender(); roller.ImmediateFlush = true; roller.RollingStyle = RollingFileAppender.RollingMode.Once; roller.MaxFileSize = 128 * 1000 * 1000; 

• Nlog:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = false, KeepFileOpen = false }; 

Como você pode ver, a configuração dos registradores é mais ou menos semelhante e de acordo com os resultados:

• O NLog é um pouco mais rápido que o log4net, algo em torno de 15%.
• Segundo os testes, descobriu-se que é mais eficiente registrar menos parâmetros. No entanto, não se deve esquecer que, com um número maior de parâmetros, a sequência resultante também se expandiu. Portanto, a tabela apenas compara corretamente o NLog ao log4net.

NLog - diferentes tipos de bloqueios

Código fonte:

 new FileTarget($"target_{_logIndex++}") { ArchiveAboveSize = 128 * 1000 * 1000, MaxArchiveFiles = 16, AutoFlush = true, ConcurrentWrites = XXXXX, KeepFileOpen = YYYYY }; 

Se colocarmos todas as combinações possíveis no lugar de XXXXX e AAAA, obtemos o teste da tabela.

Os resultados são bastante previsíveis:

• Se você ativar ConcurrentWrites, o sistema pegará e fornecerá o Mutex constantemente, o que não é gratuito. Mas, como vemos, gravar uma linha em um arquivo é aproximadamente equivalente a um bloqueio do sistema.
• Fechar e abrir um arquivo, como vemos, afeta ainda mais o desempenho do sistema. Nos exemplos com KeepFileOpen=true para cada operação de criação de log, criamos um arquivo (junto com o Handle), KeepFileOpen=true no disco, chamado Flush, retornamos o Handle e também fizemos várias operações de capô do motor. Como resultado, a velocidade cai centenas de vezes.

Registro assíncrono e diferentes métodos de bloqueio

A biblioteca NLog também pode executar todas as operações de E / S em outro encadeamento, liberando imediatamente o atual. E ele faz isso com competência, preservando a ordem dos eventos, descartando todos os dados em blocos, e em cada bloco um número inteiro é um número de evento (para que as linhas cortadas não sejam obtidas) e assim por diante.

Os resultados de diferentes métodos sem bloqueio:

A comparação das abordagens de bloqueio e assíncronas será mais adiante, mas aqui - apenas a última.

Código AsyncTargetWrapper :

 new AsyncTargetWrapper(fileTargetWithConcurrentWritesAndCloseFileAsync) { OverflowAction = AsyncTargetWrapperOverflowAction.Block, QueueLimit = 10000 } 

Como você pode ver, as configurações do wrapper são tais que um despejo direto no arquivo não leva muito tempo. Assim, um buffer grande é acumulado, o que significa que todas as operações que exigem muitos recursos, como "arquivo aberto", são executadas uma vez para todo o bloco. No entanto, esse algoritmo requer memória adicional (e muito).

Conclusões:

• Se a saída assíncrona for usada, não importa que tipo de configuração de saída com o arquivo seja usada. Você pode abrir e fechar o arquivo toda vez, com um buffer grande será quase imperceptível.
• Todas as medições são verdadeiras apenas para o caso em que os dados são liberados para o disco na mesma velocidade do preenchimento de buffers (eu fiz isso devido ao rápido sistema de arquivos + pausas naturais entre as medições).

Log síncrono e assíncrono

Conclusões:

• Apesar do disco rápido (no meu caso - M.2 SSD), a gravação em um arquivo em outro fluxo acelera o trabalho várias vezes. Se seu aplicativo gravar em discos HDD e até rodar em uma máquina virtual, o ganho será ainda maior.
• No entanto, apesar da operação ainda mais rápida do código assíncrono, a falta de registro fornece um ganho ainda maior (embora um pouco diferente, dependendo da biblioteca).

Criando Registradores

Resultados:

O que foi testado:

 [Benchmark] public object CreateLog4NetFromString() { return LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _log4NetStringLogIndex) % 1000)); } [Benchmark] public object CreateNLogFromString() { return NLog.LogManager.GetLogger("my-logger_" + (Interlocked.Increment(ref _nLogStringLogIndex) % 1000)); } [Benchmark] public object CreateLog4NetLogger() { return new [] { LogManager.GetLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogTypeOfLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(typeof(BaseTest)), // x16 times }; } [Benchmark] public object CreateNLogDynamicLogger() { return new[] { NLog.LogManager.GetCurrentClassLogger(), // x16 times }; } 

Observação importante: infelizmente, para mim foi difícil fazer um benchmark reproduzível que não levasse à falta de memória, mas que criaria diferentes registradores (ou seja, para tipos diferentes, para linhas diferentes e assim por diante).

No entanto, tendo estudado o trabalho das bibliotecas, descobri que quase as operações mais difíceis são executadas para criar uma chave do criador de logs (isto é, determinar um nome, limpar argumentos genéricos etc.).
Além disso, para estabilizar o benchmark para a criação de um logger para o log4net, foi necessário executar não uma operação, mas 16 (isto é, uma matriz de 16 objetos idênticos é retornada). Se você não retornar nada, o .Net otimizou a execução para mim (aparentemente, apenas não retornando o resultado), o que levou a resultados incorretos.

E conclusões:

• Os criadores de logs são criados mais rapidamente a partir de strings (o NLog é mais rápido novamente, no entanto, a diferença entre as bibliotecas é pequena, considerando que os criadores de logs são criados não apenas assim, mas para o trabalho subsequente com eles).
• O log4net é mais rápido que o NLog ao inicializar um projeto. Talvez isso se deva ao cache adicional no lado do NLog, o que ajuda a acelerar as chamadas diretas para Debug , Info etc. De fato, todo ILogger sabe a resposta: chamar os métodos a seguir ou não (e isso requer pelo menos algum tipo de ligação à configuração geral). Devido a esse esquema de trabalho, a Memória insuficiente foi usada por mim na maioria dos testes (se eu usar linhas diferentes etc.).
• LogManager.GetCurrentClassLogger() é ainda mais lento que LogManager.GetLogget(typeof(XXX)) . Isso é lógico, mesmo os desenvolvedores do NLog não recomendam chamar o primeiro método em um loop.
• E o mais importante: a velocidade de todos esses métodos geralmente afeta apenas o início a frio do aplicativo quando os campos do formulário private static readonly ILogger Log = LogManager.GetCurrentClassLogger() . Ou seja, não afeta diretamente o desempenho do sistema.

Conclusão

Qual é a melhor maneira de lidar com logs:

• Se for possível não fazer logon, este será o mais rápido (o que é óbvio até agora).
• Se o projeto tiver muitas chamadas de criador de logs que não despejam dados em um arquivo (no console etc.), o NLog será mais rápido. Além disso, ele aloca menos objetos no heap.
• Se você ainda precisar gravar em um arquivo, o NLog funcionará de forma assíncrona mais rapidamente. Sim, consome mais memória (em comparação com o NLog no modo síncrono, pois de acordo com minhas medições anteriores, o log4net nem tenta reutilizar matrizes e Stream ). No entanto, o programa poderá executar mais rapidamente.
• Criar um criador de logs não é uma operação livre; portanto, é melhor criá-lo com um campo estático. Isso não se aplica à criação de uma sequência, ou seja, algo como LogManager.GetLogger("123") . Essas chamadas funcionam mais rapidamente, o que significa que um criador de logs pode ser criado para grandes instâncias de objetos (por exemplo, "um criador de logs para o contexto da consulta").
• Se você deseja gerar muitos parâmetros para o log, mas na maioria dos casos não haverá despejo direto de dados no arquivo, é melhor fazer várias chamadas. Portanto, o NLog não criará objetos adicionais no heap se eles não forem necessários lá.

Conclusões para o seu código:

• Se o seu método aceitar um objeto arbitrário (ou seja, object ) e, na maioria dos casos, não fizer nada (o que é verdadeiro para contratos / validadores), é mais correto agrupar chamadas em um formato genérico (ou seja, criar métodos com o formato Something<TArg>(TArg arg) ). Isso funcionará muito mais rápido.
• Se no seu código uma redefinição de dados do arquivo for permitida e, ao mesmo tempo, trabalhar com outra coisa, é melhor ficar confuso e dar suporte a isso. Sim, parece óbvio que a execução paralela pode acelerar o trabalho; no entanto, no caso de operações de E / S, essa abordagem também oferece um aumento de desempenho adicional em máquinas com discos lentos.