Perf4j - Analise de performance em Java

10:05 in Java

Acredito que a maioria dos desenvolvedores ao menos uma vez mediu o tempo de execução de um método na aplicação. Para quem como eu meche com Java, muitas vezes recorremos ao System.currentTimeMillis():

 Long agora = System.currentTimeMillis();
 //Algum método demorado
 System.out.println((System.currentTimeMillis()-agora)+"ms");

A saída desse código é o tempo de execução em milisegundos, bem simples, já é algo ilustrativo para medir o desempenho da aplicação, porém muitas vezes isso não tem todas as informações que gostaríamos de ter.
Eis que algum louco inventou um tal de perf4j, uma biblioteca parecida com o log4j, mas voltada para medir a performance da aplicação (O log4j é uma biblioteca de log). Através do perf4j, é possível até gerar gráficos de desempenho, e ele também mostra o tempo médio de execução dos métodos durante a execução.
Vou mostra uma maneira simples de se usar o perf4j mesclado com o Java Logging API, assim podemos salvar os resultados da performance em um arquivo e lê-los quando precisarmos.
O perf4j funciona baseado na classe StopWatch, e apartir dela podemos gerar as nossas estatísticas. Inicialmente o código vai ficar maior porém os dados que podemos conseguir em cima disso são bem maiores.

OBS: Já tive problemas com essa manipulação de arquivos e locks do Sistema operacional, quando estamos trabalhando com arquivos, o ideal é sincronizar e tornar a leitura do arquivo Thread Safe

String arquivo = "statistics.log";//nome do arquivo que será armazena as estatisticas
Logger logger = Logger.getLogger("com.rollingwithcode");//Qualquer pacote serve.
logger.addHandler(new FileHandler(arquivo));//adiciona ao log o arquivo como handler, a Java Logging API, usa esse arquivo para armazenar o log.
StopWatch stop = new JavaLogStopWatch("Teste", logger);//o primeiro argumento é o nome ilustrativo desse log, cada método deve ter seu próprio nome, assim se torna mais intuitivo e mais especifico quando se lê o arquivo.
//Aqui vem alguma execução que pode ser demorada.
stop.stop();

Após a execução da ultima linha algo como:
24/08/2009 13:43:32 org.perf4j.javalog.JavaLogStopWatch log
INFO: start[1251132212406] time[406] tag[Teste]
Deverá ser exibido na console. Essa saída é até menos legível que a do System.currentTimeMillis(), porém o poder do per4j será mostrado a seguir.

Vamos ler o arquivo de log gerado, seria interessante executar mais alguns métodos para armazenar no log, o per4j trabalha com uma classe chamada LogParser para gerar estatísticas em cima do arquivo de log gerado (statistics.log).

String arquivo = "statistics.log";
String temp = "lido.log";//Arquivo temporário, os dados são jogados do statistics para esse outro arquivo de log.
LogParser parser = new LogParser(new BufferedReader(new FileReader(arquivo)),
                        new PrintStream(new FileOutputStream(temp), true), null, 30000L, false,
                        new GroupedTimingStatisticsTextFormatter());
parser.parseLog();

A criação do LogParser é simples, primeiro argumento é o arquivo de log que geramos através do StopWatch, o segundo é o arquivo temporário a ser salvo, o terceiro parâmetro (null) é utilizado para gráficos, os outros dois parametros não vem ao caso agora, o ultimo parâmetro é o formatador do arquivo temporário, define o layout do arquivo.

O método parseLog faz a leitura do arquivo. Agora basta você ver o arquivo lido.log e termos o arquivo legível trazendo a media de tempo de execução do arquivo (Avg), o tempo mínimo (Min), o tempo máximo (Max), a quantidade de vezes que o método foi chamado (Count). Agora sim as informações são bem maiores não acham?

Aconselho o uso do perf4j, excelente ferramenta para analise de performance em Java.