Deixando rastros, ou como usar log

Esse post é necessário para outro que vou escrever.... 🤔

Log é uma ferramenta muito importante. Se você é apenas um desenvolvedor, talvez não saiba a utilidade dele, mas com certeza que cuida da operação do seu software sabe.

Com esse post, quero mostra:

1. O que é um log?
2. Porque usar log em Java?
3. Como usar SLF4J em Java?
4. Apresentar um simples benchmark entre implementações do SLF4J.

Formato de Arquivo

Pra ser bem estrito ao nome log significa registro. E esse tipo de arquivo não é necessariamente associado a um conteúdo. Há inuméros outros tipos de log, como por exemplo no Apache Kafka, cada partition é um arquivo de log, há base de dados que funcionam basicamente como um log de operações, acredito que o Datomic é assim.

Na realidade, um arquivo de log é um arquivo que conterá registros de algo, que será sempre adicionado ao final do arquivo.

Nesse post vamos tratar de logs de execução. Esses são essenciais para qualquer aplicação.

Porque sua aplicação deve ter log

Existem aplicações, servidores, agentes e scripts. A diferença entre esses tipos de software está no modo como eles são executados.

Script

No caso de script, a execução desse sempre será supervisionada por um desenvolvedor, ou alguém de suporte. Normalmente é executado pela linha de comando e as informações devem ser mostradas no console. Nesse caso não é necessário um biblioteca de log, a eficiência não é um problema.

Aplicações

Aplicações é um que temos instalado no nosso computador ou celular. Quando um erro acontece na aplicação tempos duas coisas:

1. A descrição do erro por um usuário mal-humorado
2. Um usuário mal-humorado

Nesse caso, muitas vezes o que o usuário irá descrever pode não ser suficiente para se compreender o erro. Se esse erro ocorrer com um aplicativo de celular... você tem uma legião de usuários mal-humarados e só... Como corrigir o erro?

Nesse caso o log deverá descrever o estado da aplicação e será bastante útil para um troubleshooting simples ou a correção do bug.

Agentes e Servidores

Ahhh... E se você não tem um usuário? Vai dar erro, ninguém vai ver... Você não vai saber como e onde deu o erro... Como faz?

Primeiro uma definição, Agentes são softwares inteligentes que são autonomos. Eles não precisam de interação com outros softwares/usuários. Você pode ver um em ação... o google!

Nesse caso, um log de execução é essencial. Você precisa saber o estado atual do seu sistema e se der algum erro, deve ter informações suficientes para compreender o que aconteceu.

Uma biblioteca para todos usarem

No mundo Java há uma grande preocupação com padronização. Assim até se tratando de Log também temos uma padrão:

1. Não use a biblioteca padrão do Java. Porque? Porque não oras!
2. Use SLF4J e escolha a implementação que você quiser.

Com SFL4J você não precisa fazer quase nenhuma configuração em código, apenas instanciar em suas classes uma instância do logger.

O SLF4J

O Simple Logging Facade for Java é uma biblioteca para abstrair log, assim você não precisariam ficar preso a uma implementação de biblioteca de log. Quer mudar a biblioteca de log? Só mudar umas linhas no pom.xml!

Configurando o SLF4J

Para configurar o SLF4J e sua implementação, você irá precisar basicamente:

1. Adicionar a dependência slf4j-api
2. Adicionar uma implementação do SLF4J
   1. Ou o Log4J2
   2. Ou o Logback
   3. Ou outras implementações
3. Instanciar o log e deixar rastros.

Basicamente não é necessário um arquivo de configuração, apesar de ser altamente recomendável!

Vou deixar aqui um exemplo não tão básico, pois usa o variáveis de ambiente para configurar o Log:

Observe que na linha 21 e 22, estou usando as variáveis de ambiente LOG_LEVEL e APPENDER, com os respectivos valores padrão DEBUG e STDOUT. Assim essas configurações podem ser alteradas sem a necessidade de uma build! 😎

Agora para instanciar o log:

import org.slf4j.Logger;
import org.slf4j.LoggerFactory;

public class MyClass {
    private static final Logger logger = LoggerFactory.getLogger(MyClass.class);

        public void beHappy() {
            logger.info("Yeah!");
            // being happy!
        }
}

Níveis de Log

Um dos conceitos básicos do log é o Nível, ele gradua a importância da informação sendo registrada.

No SLF4J há os seguintes níveis: ERROR, WARN, INFO, DEBUG, TRACE. Sendo o TRACE o menos importante e o ERROR o mais importante.

É nível de log deve ser ajustado de acordo com a necessidade, por exemplo. Uma aplicação no ambiente de desenvolvimento deve rodar em DEBUG ou TRACE. Uma aplicação em ambiente de testes em INFO. Já uma aplicação em produção deve rodar em ERROR ou WARN.

Caso exista um bug em em produção e seja necessário pegar mais logs, a aplicação deve ser reiniciada para INFO.

Mas fique atento, mudar o nível de log pode impactar a performance da aplicação.

Dicas

É normal em desenvolvedores menos experientes, criar mensagens com contatenação de strings... Mas isso não é uma boa prática, porque em código sensíveis, pode impactar a performace.

Mas há duas maneiras de resolver isso com o SLF4J.

Usando binding

No SLF4J você pode resolver esse usando o binding. Você irá ver que as assinaturas dos métodos de log aceitam inúmeros parâmetros. Cara parametro será associado ao valor {} na mensagem de log. Assim, caso a mensagem não seja exibida por causa do nível de log, serão evitada as criações de algumas strings.

logger.trace("This is a trace message: ctx={} other-var={}", ctx, otherVar);

Verificando Nível de Log

Caso a mensagem seja realmente complicada, e você queira formatar ela dignamente... Há outra saída...

logger.debug("this is a debug message. If the level is bellow debug, it will not showed");
if(logger.isDebugEnabled()) {
    logger.debug("Some message formatted: value1=" + value1 + " ctxName=" + ctx.getName());
}

Não use chamadas de metodos

Uma outra dica é nunca usar chamadas de métodos como parâmetro! Porque? Porque se o esse log não estiver habilitado, o método será chamado sempre. Deixe a JVM chamar o toString. Segue a vida....

logger.debug("This is a log registry: ctxName={}", ctx.getName()); // Wrong!
logger.debug("This is a log registry: ctx={}", ctx);               // Better now! Implement .toString correctly

Benchmark

Eu fiz um benchmark rápido, mas o objetivo dele não é mostrar qual implementação é melhor. Há algumas razões pra se escolher o logback, mas isso fica a sua escolha.

vepo / slf4j-benchmark

Benchmark

To execute

mvn clean compile -P logback exec:java -DLOG_LEVEL=INFO -DAPPENDER=STDOUT
mvn clean compile -P logback exec:java -DLOG_LEVEL=DEBUG -DAPPENDER=STDOUT
mvn clean compile -P logback exec:java -DLOG_LEVEL=INFO -DAPPENDER=FILE
mvn clean compile -P logback exec:java -DLOG_LEVEL=DEBUG -DAPPENDER=FILE

mvn clean compile -P log4j exec:java -DLOG_LEVEL=info -DAPPENDER=stdout
mvn clean compile -P log4j exec:java -DLOG_LEVEL=debug -DAPPENDER=stdout
mvn clean compile -P log4j exec:java -DLOG_LEVEL=info -DAPPENDER=file
mvn clean compile -P log4j exec:java -DLOG_LEVEL=debug -DAPPENDER=file

Logback

Level	Appender	Time	op/μs
DEBUG	STDOUT	28055ms	28,055
INFO	STDOUT	14ms	0,014
DEBUG	FILE	4976ms	4,976
INFO	FILE	17ms	0,017
DEBUG	ASYNC	N/A	N/A
INFO	ASYNC	N/A	N/A

Log4j

Level	Appender	Time	op/μs
DEBUG	STDOUT	30593ms	30,593
INFO	STDOUT	16ms	0,016
DEBUG	FILE	5137ms	5,123
INFO	FILE	20ms	0,020

View on GitHub

O ponto central do meu benchmark é mostrar como o uso do nível de log impacta na performance.

No meu teste, são feitas 1.000.000 de chamadas ao log. Então...

Podemos ver, que se reduzirmos o nível de log podemos reduzir o tempo de execução! Isso porque:

1. Menos código é executado
2. Não há gargalo para escrita (arquivo, console, TCP, etc...)

Conclusão

Nenhum software pode ser executado sem algum tipo de log. Para softwares mais sensíveis o log deve ser levado a sério.

Usando corretamente o log, você não terá impacto na performance, e ainda conseguirá mais informações para troubleshooting e bug fix!

😎