5 técnicas avançadas de debug em Java que todo desenvolvedor deveria saber

Debug (depuração) em produção sempre foi difícil e está se tornando ainda mais difícil. Com as arquiteturas se tornando mais distribuídas e o código mais assíncrono, localizar e resolver erros que acontecem em produção não é uma tarefa para novatos. Nesse artigo são discutidas algumas técnicas avançadas que podem ajudar a encontrar mais rapidamente a causa de falhas no ambiente de produção, sem sobrecarregar o ambiente que já é tão requisitado.

Jstack com melhorias. A jstack já existe há um bom tempo, aproximadamente o mesmo tempo que a JVM, e mesmo hoje ela continua sendo uma ferramenta crucial para todo desenvolvedor. Sempre que um processo Java inicia e trava ou para de responder, jstack é a ferramenta para rastrear a pilha de execução de cada thread. Ainda assim, jstack tem algumas desvantagens que reduzem a sua habilidade de ajudar a fazer depuração de problemas complexos em produção. A primeira é que enquanto ela diz o que cada thread está fazendo através de sua pilha de execução, ela não diz o que ou porquê elas estão fazendo isso - tipo de informação que normalmente estaria disponível somente através de um depurador - e também não fala quando cada thread começou a trabalhar.

Felizmente, há uma forma ótima de corrigir isso e tornar essa ferramenta ainda melhor, injetando o estado de uma variável nos dados de cada thread. A chave para resolver esse problema reside em um dos lugares mais inesperados. Durante a execução, em nenhum momento a jstack consulta a JVM ou o código da aplicação para apresentar o estado das variáveis. Contudo, há uma importante exceção que pode ser usada que é o atributo name da classe Thread, cujo valor é usado no dump da pilha. Configurando esse valor corretamente é possível melhorar a saída não informativa do jstack, que é semelhante a isso:

"pool-1-thread-1″ #17 prio=5 os_prio=31 tid=0x00007f9d620c9800 nid=0x6d03 in Object.wait() [0x000000013ebcc000]

Compare com a seguinte informação que contém a descrição do que está sendo atualmente feito pela thread, os parâmetros de entrada que foram passados e a hora que ela começou a processar a requisição:

"pool-1-thread- #17: Queue: ACTIVE_PROD, MessageID: AB5CAD, type: Analyze, TransactionID: 56578956, Start Time: 10/8/2014 18:34″

Aqui está um exemplo de como configurar um nome para a thread:

private void processMessage(Message message) { //an entry point into your code
  String name = Thread.currentThread().getName();
  try {
    Thread.currentThread().setName(prettyFormat(name, getCurrTranscationID(),
      message.getMsgType(), message.getMsgID(), getCurrentTime()));
    doProcessMessage(message);
  } finally {
    Thread.currentThread().setName(name); // return to original name
   }
}

Nesse exemplo, onde uma thread está processando as mensagens de uma fila, podemos ver a fila destino da qual a thread está retirando as mensagens, o ID da mensagem sendo processada, a transação na qual ela está relacionada - que é crítico para reproduzir localmente - e por último, mas não menos importante, a hora que o processamento da mensagem começou. Esta última parte da informação possibilita olhar na saída da jstack mostrando centenas de threads em execução e permite visualizar quais iniciaram primeiro e que são as mais prováveis de estarem causando o travamento da aplicação.

(Clique na imagem para aumentá-la)

Um exemplo de como a jstack aprimorada mostra o estado de variáveis para cada thread no dump. A data e hora de início de cada thread é mostrado como TS.

Essa abordagem também funciona quando é usado um profiler, uma ferramenta de monitoramento comercial, o console JMX ou mesmo o novo Mission Control do Java 8. Em todos esses casos, a capacidade de olhar o estado de uma thread em execução, ou um dump histórico de uma thread e ver exatamente o que ela estava fazendo quando iniciou é substancialmente melhorada quando se tem o contexto da thread com os estados.

.

O estado dessa variável de thread será apresentada por qualquer JDK, depurador comercial ou profiler.

Mas a importância de se nomear as threads pode ser ainda maior. Esse procedimento desempenha um papel muito maior na depuração em ambiente de produção, mesmo que não seja usado o jstack. Uma situação é o uso do callback global uncaughtExceptionHandler da classe Thread que serve como uma última linha de defesa antes que uma exceção não tratada encerre uma thread ou a envie de volta ao pool de threads.

Quando o exception handler(tratador de exceções) é alcançado, a execução do código já foi interrompida e tanto os frames (pilha com a sequência de chamada de métodos efetuada pela thread) quanto as variáveis de estado não existem mais. A única informação de estado que permite analisar o que estava sendo feito pela thread, seus parâmetros e data de início está no nome da thread.

É importante ter em mente que o framework de threads pode capturar exceções implicitamente sem que o usuário saiba. Um bom exemplo é o ThreadPollExecutorService que captura todas as exceções do tipo Runnable e as delega para o método afterExecute, que pode ser sobrescrito para mostrar alguma informação útil. Então, indiferente de qual framework você usa, lembre-se que quando a execução de um thread é interrompida devido a um erro, ainda é possível fazer o log da exceção com o estado da thread, evitando que as tarefas simplesmente desapareçam sem deixar rastros.

jstack com throughput e deadlock. Outra desvantagem de ferramentas como jstack ou Mission Control é que elas precisam ser ativadas manualmente na JVM. Isso reduz a efetividade no ambiente de produção no qual 99% do tempo que os problemas ocorrem não há ninguém para depurar.

Felizmente, há uma forma de ativar a jstack programaticamente quando o throughput da aplicação cai abaixo de uma faixa pré-definida ou quando satisfaz um conjunto de condições. É possível, inclusive, ativar o jstack automaticamente quando a JVM tem um deadlock, permitindo verificar quais threads estão bloqueadas e o que as demais estão threads estão fazendo e isso tudo em parceria com o estado das variáveis armazenados no atributo name das threads. O valor disso pode ser inestimável pois deadlocks e problemas de concorrência são raros na maioria das vezes e notoriamente difíceis de reproduzir. Nesse caso, ativar o jstack automaticamente no momento do deadlock, e mostrar informações a respeito das variáveis em cada thread, pode ser um grande catalisador para reproduzir e resolver esses tipos de erros.

Este link dá maiores detalhes de como detectar deadlocks automaticamente de dentro da sua aplicação.

Capturar variáveis em tempo de execução. Citamos algumas forma de capturar o estado da JVM através de contextos das threads. Apesar dessa abordagem ser eficiente, ela é restrita aos estados das variáveis que foram formatadas em uma String atribuída ao nome da thread durante sua execução. Ao invés disso, seria mais apropriado entrar na JVM e obter o valor de qualquer variável, em qualquer ponto do código durante a execução, sem a necessidade de anexar um depurador ou instalar uma nova versão da aplicação. Uma grande ferramenta que não teve o devido reconhecimento que merecia e permite fazer exatamente isso que foi citado é a BTrace.

BTrace é uma ferramenta útil que usa scripts construídos com uma linguagem parecida com Java e os executa na JVM para capturar ou agregar qualquer formato de estado de variável sem ter que reiniciar a JVM ou instalar uma nova versão da aplicação. Isso possibilita executar ações poderosas como imprimir a pilha de execução das threads, salvar as informações da pilha em um arquivo específico, imprimir o número de itens em uma fila ou em um pool de conexões e muito mais.

Isso é feito usando um script BTrace composto de declarações de funções que são injetadas em certas posições do código através de uma transformação de bytecode, um processo que será detalhado a seguir. A melhor forma de testar a ferramenta é anexar os seus scripts em uma aplicação em execução. O uso é bem simples, na linha de comando digite: btrace <PID da JVM> <nome do script>. Não é necessário reiniciar a JVM.

BTrace é muito bem documentada e traz vários scripts de exemplo mostrando cenários de depuração envolvendo IO, alocação de memória e carregamento de classes. Alguns exemplos de scripts que podem ser facilmente feitos com o BTrace são:

• NewArray.java: Imprime sempre que um char[] é criado e também mostra como adicionar condições personalizadas com base em valores. Muito útil para fazer profiling seletivo de memória.
• FileTracker.java: Imprime sempre que a aplicação escreve em um arquivo em uma localização específica. Útil para localizar a causa do excesso de operação de IO.
• Classload.java: Reage sempre que uma classe é carregada na JVM. Interessante para depurar situações de jar-hell.

O BTrace foi projetado para ser uma ferramenta não intrusiva, significando que ela não altera o estado da aplicação ou o controle de fluxo. Isso é útil pois reduz a chance de interferir negativamente no código executado, tornando o seu uso em produção muito mais aceitável. Essa capacidade, porém, leva a algumas restrições: não é possível criar objetos, nem mesmo strings; utilizar bibliotecas de terceiros, mesmo que seja para logging; ou mesmo fazer operações simples como construir laços por receio de criar laços infinitos. Para superar essa limitações citadas é necessário utilizar uma outra técnica: criar um agente Java.

Agente Java. Um agente Java é um arquivo JAR que fornece acesso pela JVM a um objeto de instrumentação e permite modificar o bytecote carregado na JVM para alterar o seu comportamento. Isso permite essencialmente que o código carregado e compilado pela JVM seja "reescrito" sem reiniciar a aplicação ou alterar o arquivo ".class" armazenado em disco. Imagine isso como um BTrace mais poderoso, capaz de injetar código novo em qualquer lugar da aplicação, tanto no código da própria aplicação quanto em bibliotecas de terceiros, com o objetivo de capturar qualquer pedaço de informação necessário.

A grande desvantagem de escrever um agente é que, ao contrário do BTrace que usa scripts para capturar estados, os agentes Java trabalham diretamente no bytecode. Isso significa que se a intenção for injetar código na aplicação, então será necessário criar o bytecode correto, que pode ser difícil de produzir e ler, e usar uma sintaxe de operações baseada em pilha que lembra muitas vezes a linguagem Assembly.Uma vez que o bytecode é compilado, se houver qualquer problema referente à sua localização de inserção o verificador da JVM irá rejeitá-lo sem dar muitas explicações.

Para ajudar nessa tarefa, foram escritas várias bibliotecas para geração de bytecode, tais como JavaAssist e ASM. Uma ferramenta bastante útil é o visualizador de bytecode do ASM, disponível como plugin para o Eclipse, que permite editar qualquer código Java no editor e o bytecode equivalente é gerado automaticamente e pode ser copiado e colado diretamente no agente.

Veja um exemplo real de agente utilizado em nossa empresa para detectar vazamento de memória esporádico vindo de códigos de terceiros em nossos servidores e relacionados com o estado da aplicação.

Geração dinâmica dos scripts de bytecode no Eclipse usando o plugin do ASM.

Agentes Nativos da JVM. Essa última técnica que falaremos brevemente é a construção de Agentes Nativos da JVM. Essa abordagem usa a camada de API C++ JVM TI, que permite controle sem precedentes e acesso às partes internas da JVM. Isso possibilita receber notificações quando o GC inicia e para, quando novas threads são executadas, monitores são obtidos e muitas outras funcionalidades de baixo nível. Essa é de longe a abordagem mais poderosa para obter o estado do código em execução, visto que o agente está executando no mesmo nível da JVM.

Mas grande poder leva a grandes responsabilidade e alguns desafios complexos tornam essa abordagem difícil de implementar. A primeira é que o código executando no nível da JVM deixa de ser escrito em Java portável e precisa ser escrito em C++ - dependente da plataforma. A segunda desvantagem é que a API, enquanto extremamente poderosa, é difícil de usar e dependendo do conjunto específico de capacidades que estão sendo consumidos pode impactar significativamente no desempenho da aplicação.

Como vantagem, se usada corretamente essa camada fornece acesso a partes da JVM que de outra forma estariam indisponíveis e que podem ser úteis na procura de erros em produção. Quando começamos a escrever a Takipi para depuração em produção, não tínhamos certeza do quanto a JVM TI se tornaria crucial para construir a nossa ferramenta. O motivo para isso é que através dessa camada é possível detectar exceções, chamadas no SO ou mapear o código da aplicação sem instrumentação manual. Se você tiver tempo para conhecer essa API, conheça-a pois ela abre uma janela dentro da JVM que poucos de nós conhecemos.

Sobre o Author

Tal Weiss é CEO da Takipi. Tal começou a projetar aplicações escaláveis e de tempo real em Java e C++ há mais de 15 anos. Ele também gosta de analisar um bug desafiante e instrumentar código Java. No seu tempo livre Tal é baterista de Jazz.