Olá Habr!
Eu acho que quase todo programa tem log. Além disso, em um número de aplicativos já novos (o que significa um mar de condições não triviais), os logs geralmente se tornam vitais em um servidor de combate.
No entanto, apesar da importância e prevalência de tal tecnologia, notei que as pessoas geralmente cometem erros padrão ao trabalhar com elas. Este artigo descreve o comportamento do .Net de várias maneiras, no entanto, fiz pequenas inserções do mundo Java, apenas para fazer uma comparação.
Alocações (alocação de memória)
O erro mais comum (de acordo com minhas observações) é uma negligência em relação às pequenas alocações de memória próximas ao local da chamada para a função log.Debug(...) .
Portanto, nosso código padrão em .Net:
private static readonly ILog Log4NetLog = LogManager.GetLogger(typeof(Program)); private static readonly Logger NLogLog = NLog.LogManager.GetCurrentClassLogger(); private static void PublishData(int id, string name, EMail email, decimal amount) { Log4NetLog.Debug($"Id={id}"); // 1 Log4NetLog.DebugFormat("Id={0}", id); // 2 Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3 Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4 NLogLog.Debug($"Id={id}"); // 5 NLogLog.Debug("Id={0}", id); // 6 NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 7 NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 8 }
De várias maneiras, vi apenas as bibliotecas log4net e NLog e, portanto, as usarei nos exemplos.
Então, as perguntas são:
- Em quais linhas a memória será alocada mesmo se a Depuração estiver desativada?
- Se a memória é alocada, quão fácil é detectar no mesmo dotTrace que especificamente os registradores são os responsáveis por essa mesma alocação de memória?
A resposta correta para a primeira pergunta: a memória não é alocada apenas no parágrafo "6". E a resposta para a segunda pergunta: é incrivelmente difícil de entender, porque esse código geralmente se espalha pelo projeto. Você pode se lembrar de um aplicativo .Net típico. Geralmente, ele possui código semelhante que faz o GC funcionar.
No entanto, vamos examinar os detalhes técnicos para entender exatamente onde teremos impacto no desempenho.
Então, o primeiro ponto:
Log4NetLog.Debug($"Id={id}"); // 1
De fato, o compilador o converterá em:
var temp = string.Format("Id={0}", id); // <-- Log4NetLog.Debug(temp);
Ou seja, a primeira expressão forçará essencialmente o processador a criar uma string e a passará para o criador de logs. Ele verificará rapidamente se você não precisa fazer logon e, portanto, a linha foi criada apenas na memória. E, mais importante, se você copiar mais desse código, as linhas serão criadas em montes de locais de programa, ou seja, o programa funcionará um pouco mais devagar. Em todos os lugares.
O segundo exemplo é um pouco mais eficiente, já que uma linha não é criada nela:
Log4NetLog.DebugFormat("Id={0}", id);
No entanto, a memória ainda é alocada aqui, pois o boxe ocorrerá. Deixe-me lembrá-lo da assinatura do método DebugFormat:
void DebugFormat(string format, object arg0)
Como você pode ver, a entrada requer um tipo de referência. No entanto, estamos tentando passar um tipo int significativo. Como resultado, cada chamada fará com que o id parâmetro de heap seja passado para transmiti-lo ao método. E deixe-me lembrá-lo de que o parâmetro em si não é necessário no próprio método, pois a Debug é desativada pela condição da tarefa.
O exemplo a seguir é carregado e simples:
Log4NetLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); // 3
Estou certo de que você já entendeu que novamente a linha se destacará na pilha e assim por diante. Portanto, pule imediatamente este exemplo. O seguinte método de chamada parece mais eficiente:
Log4NetLog.DebugFormat("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount); // 4
E é assim, no entanto, vamos calcular quantas vezes é necessário alocar um pedaço de memória:
email.Normalize() leva à criação de algum tipo de objeto. Portanto, esse objeto será alocado na pilha (ou na pilha - não importa, pois o boxe tornará necessário selecionar tudo na pilha)id irá para um monte, como já consideramos anteriormente.- O Log4net possui a seguinte interface para chamadas formatadas longas:
void DebugFormat(string format, params object[] args) . Como você pode ver, o .Net criará uma matriz na pilha para passá-la ao método DebugFormat .
Como resultado, uma chamada bastante típica para uma operação de log resultará em um monte de objetos na memória. O que é bastante decepcionante, já que o próprio registro é geralmente desativado. No entanto, vamos para o NLog.
Esta linha provocará a alocação do objeto no heap:
NLogLog.Debug($"Id={id}");
Tudo é óbvio aqui, mas a linha abaixo não tem mais essa desvantagem:
NLogLog.Debug("Id={0}", id);
E o motivo é que o NLog possui uma assinatura especial para ints: void Debug(string message, int argument) . Além disso, mesmo se você transferir uma estrutura diferente, o void Debug<TArgument>([Localizable(false)] string message, TArgument argument) . E esse método não requer boxe, pois após o JIT, uma função separada será criada para cada tipo (é claro, isso não é totalmente verdade, mas o ponto importante é: não haverá boxe).
Vou pular o script fácil de entender com uma linha de entrada grande e vou direto para:
NLogLog.Debug("Id={0}; name={1}; email={2}; amount={3}", id, name, email.Normalize(), amount);
Curiosamente, o NLog não aumentou o número de parâmetros genéricos para métodos e, portanto, a assinatura será usada: void Debug([Localizable(false)] string message, params object[] args) . E isso levará novamente à criação de objetos em pilhas e assim por diante.
Conclusões e melhorias
A principal conclusão: se você tiver muitas chamadas para os métodos de log do programa que não levam à gravação física no arquivo, poderá começar do zero para alocar muitos objetos desnecessários no heap. E, assim, inibindo o trabalho do programa.
Conclusão 2: Se você não passar muitos objetos para um método, use NLog. Devido ao fato de cuidar dos parâmetros genéricos, você pode ficar mais relaxado com o desempenho.
No entanto, para ser completamente seguro, é mais lógico fazer isso:
if (NLogLog.IsDebugEnabled) { NLogLog.Debug($"Id={id}; name={name}; email={email.Normalize()}; amount={amount}"); }
Aqui, o método de log não será chamado se não for necessário. No entanto, se você ainda precisar despejar os dados no log, a conveniente Interpolação de String será usada. No interior, os registradores (pelo menos o mesmo NLog) têm otimizações para gravar uma linha diretamente nos logs (ou seja, a formatação ocorrerá imediatamente no Stream , em vez de criar uma linha na memória). No entanto, essa otimização do NLog diminui com o fato de que você precisa redefinir os dados para um arquivo.
Exemplo de Kotlin
Para diluir a descrição do trabalho dos registradores populares em .Net, darei uma maneira interessante de encerrar chamadas no kotlin. A idéia é baseada literalmente em um recurso interessante da linguagem: métodos em linha . Portanto, um código simples para gerar algo para depuração:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { "Identity: $id" } } }
E será convertido pelo compilador em algo assim:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val message = "Identity: $id" logger.debug(message) }catch (e: Exception){ } } } }
É importante aqui: tudo dentro de aparelhos perto de debug é uma lambda. No entanto, ele será incorporado ao seu método, ou seja, um objeto de função não será criado no heap. Assim, você pode ocultar grandes operações dentro, que serão chamadas apenas se você desejar gerar o resultado para debug . Por exemplo:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ logger.debug { val idList = getIdList() "Identity: $idList" } } }
Aqui, getIdList será chamado apenas se você precisar enviar algo para o arquivo. E tudo porque o código é convertido em:
class SomeService{ private companion object : KLogging() fun publishData(id: Int){ if(logger.isDebugEnabled){ try{ val idList = getIdList() val message = "Identity: $idList" logger.debug(message) }catch (){ } } logger.debug { "Identity: $id" } } }
Objeto grande ==> Pilha de objetos grandes
Além do exemplo anterior. Estou certo de que muitas pessoas sabem que .Net / JVM tem o conceito de "Large Object Heap". Mais precisamente, não há definição especial em Java; no entanto, os alocadores geralmente criam objetos grandes imediatamente na última geração (para minimizar o movimento de objetos e nivelar o problema de penetração rápida de memória para um alocador de fluxo contínuo).
De volta ao exemplo:
NLogLog.Debug($"Id={id}");
Como você entende, se o objeto de id tiver uma implementação de ToString , que cria uma string do tamanho de um megabyte, os seguintes hits na face LOH:
ToString própria ToString chama- Formatando
$"Id={id}" - E se os desenvolvedores do criador de logs não detectaram todas essas coisas (e é extremamente difícil escrever um teste para a ausência de objetos no LOH), o criador de log adicionará problemas.
E aqui você pode usar três métodos para registrar essas coisas:
- Use um layout especial e não exija uma chamada para o
ToString . Por exemplo, o NLog possui um JsonLayout . Assim, você pode simplesmente transferir um objeto para o criador de logs, que será serializado imediatamente para o fluxo resultante (por exemplo, para um arquivo). - Escreva você mesmo no arquivo. Ou em outras palavras - não use o logger. Só posso aconselhar sozinho como descobrir em qual arquivo o NLog gravará:
var filePath = NLog.LogManager.Configuration.AllTargets.OfType<FileTarget>().First().FileName.Render(LogEventInfo.CreateNullEvent()) . Obviamente, essa função retornará o primeiro FileTarget que FileTarget , mas se todos escreverem na mesma pasta, dessa forma, você poderá descobrir a pasta para gravação e enviar diretamente um dump do seu objeto para o arquivo. - Se você tiver log4j2 (o segundo é importante), poderá usar StringBuilderFormattable . Ele foi criado apenas para gerar dados no logger em pedaços (além disso, para não alocar parte dos pedaços na pilha, pois eles já estão selecionados).
public interface StringBuilderFormattable { void formatTo(StringBuilder buffer); }
Sincronicidade (e questões de assincronia)
Uma vez, em um programa, notei que durante as operações carregadas, cerca de metade do tempo de espera da interface do usuário era contabilizada pelas operações de log. Mais uma vez: metade do tempo do programa foi gasto em uma chamada para o logger.Debug ou algo assim. E a razão para isso é simples: usamos o log4net, que pode gravar arquivos apenas de forma síncrona.
A partir daqui deduzi a regra 1 : o criador de logs sempre deve trabalhar em outro segmento. Você não deve bloquear o código do aplicativo por causa de rastreamentos, porque é incrivelmente estranho. Em outras palavras - usando NLog - você sempre precisa colocar async=true na tag nlog (é a principal). Ou, como o exemplo diz:
<targets async="true"> ... your targets go here ... </targets>
Se você usar o log4net, redirecione-o para o NLog ou crie o AsyncFileAppender.
Para o mundo Java: o Logback e o Log4J2 têm a capacidade de fazer log assíncrono. Aqui está uma comparação do site oficial :
No entanto, quando tudo é escrito de forma assíncrona, surge outro problema - o que fazer em caso de erros críticos? Afinal, acontece que um programa não sai porque saiu do segmento Main (por exemplo, um programa pode sair chamando Application.Exit ou Environment.FailFast , que não é muito bonito, mas ocorre). Nesse caso, você deve sempre chamar Flush antes de interromper seu processo. Caso contrário, se você cair no servidor de batalha, as informações mais valiosas serão perdidas.
Conclusão
Espero que este artigo o ajude a escrever programas rápidos com registro conveniente. Eu destaquei apenas parte dos problemas que vejo parte no código. Todos eles não são os mais óbvios, mas não os mais difíceis.
De qualquer forma, como eu disse no começo, trabalhar com registradores está em quase todas as aplicações. Além disso, de acordo com minhas anotações, cerca de metade das classes produzem algo para o log. Portanto, a operação correta com essas funções afeta quase toda a aplicação.