Análise de desempenho utilizando o Profiler

Introdução

Durante o desenvolvimento de um novo processo ou relatório temos como objetivo criar códigos com as seguintes propriedades:

• • Acurácia: as informações exibidas e manipuladas devem ser corretas;

  • Legibilidade: o código fonte deve ser construído de tal forma que um outro desenvolvedor que não participou da sua concepção possa compreendê-lo e alterá-lo com segurança e produtividade;

  • Eficiência: o processo ou relatório deve ser executado em tempo satisfatório na perspectiva do usuário.

Para alcançar cada uma destas propriedade, existem métodos e ferramentas que auxiliam o desenvolvedor.

O objetivo deste documento é explicar o funcionamento do Profiler no Bematech ERP, uma ferramenta que auxilia o processo de otimização de códigos JavaScript, tornando-os mais eficientes.

Não é o objetivo deste documento apresentar técnicas de otimização de código, de instruções SQL ou explicações teóricas sobre custo ou complexidade.

Onde está o problema?

Ao observar a execução de um processo ou relatório com desempenho abaixo do aceitável, podemos facilmente concluir que o “O sistema está lento”. Esta observação é genérica demais para ser útil, pois não iremos otimizar o sistema inteiro e sim alguns trechos ineficientes do sistema.

Identificar os códigos responsáveis por um baixo desempenho não é uma tarefa trivial, pois existem custos implícitos de difícil observação durante a leitura de um código. Um relatório, por mais simples que seja, realiza:

• Acesso ao cache local;

• Transferência de dados através da rede;

• Consultas no banco de dados;

• Uso de bibliotecas cujo código é desconhecido pelo desenvolvedor do relatório;

São muitos os fatores que podem afetar o desempenho de um processo ou relatório, sendo improdutivo tentar solucionar o problema utilizando apenas a intuição e otimizações na estratégia de tentativa e erro. O desenvolvedor precisa de informações que orientem a sua atenção para os códigos responsáveis pelo baixo desempenho.

Para gerar estas informações existem ferramentas chamadas de Profiler. Estas ferramentas analisam o desempenho de um processo através de técnicas que possibilitam uma análise detalhada dos custos internos de um processo, sendo a instrumentação e a amostragem as mais conhecidas e utilizadas.

O Bematech ERP possui uma ferramenta de Profiler baseada em instrumentação manual do código fonte. Esta ferramenta pode ser utilizada através da classe Profiler, responsável por realizar a instrumentação e pela geração de relatórios contendo as informações coletadas.

Configurando o Profiler

Antes de ser utilizado, o Profiler deve ser habilitado através da opção “Profiler Enabled” existente na página “Configuration > General” do Manage.

A opção “Min RunTime to Log Profiler” configura a gravação automática das estatísticas de todas as operações executadas pelo iEngine em um arquivo de log, o “profiler.log”. Todas as operações com tempo de execução superior ao valor informado serão gravadas. Esta configuração é extremamente importante para analisar um problema de baixo desempenho de difícil reprodução. Utilizando esta opção, com um tempo inferior ao observado pelo usuário, se garante a gravação das estatísticas para uma posterior análise.

Para se obter melhores resultados na análise, ferramentas e códigos utilizados exclusivamente para depuração devem ser desativados, pois eles podem elevar os tempos de execução observados. O uso do depurador torna a execução do código mais lenta e as paradas são totalizadas como tempo de execução dos métodos depurados. Logs são escritos no disco, operação que pode ser mais demorada do que o próprio método analisado.

Portanto é recomendado que sejam desligados o depurador de códigos JavaScript e e os Loggers que estejam com prioridade "DEBUG". Para desativar o depurador, desmarque a opção "JavaScript Debugger Enabled (requires restart)" existente na página "Configuration > General" do Manage. Para desativar os Loggers, verifique se o campo "Custom" existente na página "Log > Configuration" do Manage está vazia. Logs que não utilizem o nível de prioridade DEBUG, como o log.write(), devem ser comentados.

É recomendado que o Profiler seja desativado após a análise de desempenho, pois a coleta de informações requer um custo de processamento em todos os códigos instrumentados.

Instrumentação do código fonte

Instrumentar o código fonte nada mais é que adicionar códigos que meçam o tempo de execução ou alocação de memória do código instrumentado. Algumas ferramentas de Profiler realizam esta tarefa automaticamente, mas a existente no Bematech ERP exige que o desenvolvedor a realize manualmente.

A instrumentação é realizada através dos métodos startOperation e endOperation do Profiler. Uma instância de Profiler é publicada pelo iEngine através da variável global “profiler”, portanto não é necessária a criação de uma nova instância.

Abaixo um exemplo de instrumentação:

profiler.startOperation("Código analisado", null, true);

try {

code();

} finally {

profiler.endOperation();

}

Os métodos startOperation e endOperation possuem a seguinte assinatura:

• profiler.startOperation(name, details, sumInteractions);

• profiler.endOperation(details).

O parâmetro details tem a utilidade de adicionar informações relevantes ao código analisado, como os parâmetros recebidos por uma função. O sumInterations determina que as várias execuções do código instrumentado devem ser totalizadas.

Em uma primeira análise, não informe “details” (null) e sempre ative o sumInteractions (true), como no exemplo acima. O objetivo é gerar uma visão mais sintética que possibilite observar que códigos são relevantes e merecem ser detalhados com mais instrumentação.

Profiler Automático de Funções

É possível mensurar automaticamente todas as chamadas à funções do sistema, sem a necessidade de alterar o código para incluir as invocações ao objeto profiler. Para ativar essa funcionalidade, marque a opção "Automatic Profiler Active" existente na página "Configuration > General" do Manage. A opção "Profiler Enabled" também deve estar habilitada.

Análise do Log do Profiler

As informações coletadas pela instrumentação podem ser obtidas através dos métodos getHtmlStatistics() e getTxtStatistics() do Profiler. Estes métodos geram um relatório com os tempos de execução e alocação de memória de todos os códigos instrumentados.

Apesar de legível, o relatório não permite uma a análise manual produtiva, pois o volume de informações normalmente é elevado. Para simplificar esta análise existe o processo “/Desenvolvimento/Análise do Log do Profiler” que apresenta as informações coletadas pelo Profiler em uma visão mais sintética e útil para o desenvolvedor.

Este processo permite analisar um resultado contido nos arquivos de log do profiler ou de uma estatística coletada manualmente pelo desenvolvedor através do método getTxtStatistics(). Abaixo a interface inicial do processo:

Normalmente uma otimização necessita de vários ciclos de instrumentação, otimização e análise dos resultados. A forma mais produtiva de reproduzir este ciclo é isolar o código a ser otimizado na guia iDBCsql dentro da seguinte estrutura:

profiler.forcedLog = true;

profiler.startOperation("MyTest");

try {

code();

} finally {

profiler.endOperation();

}

File.fileFromString("c:\Bematech\profiler.txt", profiler.getTxtStatistics());

Este código gera a cada execução o arquivo “c:\Bematech\profiler.txt” com as estatísticas coletadas pelo Profiler. O resultado deste arquivo pode ser analisado utilizando a opção “Utilizar arquivo com estatísticas”.

O maior benefício desta abordagem é a velocidade para realizar uma nova análise. Basta executar o script na guia iDBCsql e pressionar o botão “Atualizar” do processo “Análise do Log do Profiler” para visualizar o resultado. Ela elimina a necessidade de fechar a sessão, logar no sistema, entrar no processo ou relatório, preencher variáiveis e procurar o resultado no log.

Quando não é possível isolar o código na guia iDBCsql, devemos fazer uso das informações gravadas no log do profiler. Para isto, devemos primeiramente garantir que as estatísticas coletadas durante a execução de um relatório ou processo sejam gravadas no log. Duas alternativas:

1. Explicitamente indicar no código fonte que o profiler gerado deve ser gravado no log através da instrução “profiler.forcedLog = true”. Esta instrução pode estar em qualquer local do código, mas preferencialmente deve ser adicionada no início.

2. Configurar a propriedade “Min RunTime to Log Profiler (ms)” do Manage para um valor inferior ao tempo de execução do processo ou relatório.

Após a execução do processo ou relatório, o resultado do profiler deverá ter sido gravado no log. Na interface do processo “Análise do Log do Profiler” deverá ser selecionado o arquivo de profiler. O arquivo de log do dia corrente é o “profiler.log”.

Os arquivos de log do profiler podem conter um volume elevado de informações, portanto é recomendado a utilização dos campos Filtros para conseguir localizar rapidamente as estatísticas desejadas. Uma boa estratégia é pesquisa por um nome de operação utilizada apenas no processo ou relatório analisado.

Após a seleção do arquivo e dos filtros será exibida a interface abaixo, onde serão exibidos todos os registros do arquivo de log que satisfaçam os filtros informados. Deve ser selecionado o registro desejado pela hora de início e pelo tempo de execução e em seguida pressionado o botão Analisar.

O resultado da análise do log do Profiler pode ser observado abaixo:

O principal resultado da análise é a grade “Operações Agrupadas por Nome”. Esta grade apresenta os campos:

• Nome: parâmetro “name” informado ao método Profiler.startOperation.

• Quantidade: quantidade total de vezes que o código instrumentado foi executado.

• Tempo c/ filhas: tempo de execução total do código instrumentado.

• Tempo s/ filhas: tempo de execução do código instrumentado desconsiderando os códigos filhos que já possuem instrumentação.

• Tempo das filhas: “Tempo c/ filhas” - “Tempo s/ filhas”.

• Qtd blocos c/ filhas: quantidade total de blocos de memória alocados pelo código instrumentado.

• Qtd blocos s/ filhas: quantidade de blocos de memória alocados pelo código instrumentado desconsiderado as alocações realizadas pelos códigos filhos que já possuem instrumentação.

• Qtd blocos das filhas: “Qtd blocos c/ filhas” - “Qtd blocos s/ filhas”.

O conceito de operação filha, pode ser melhor compreendido através do exemplo abaixo:

profiler.startOperation("MyTest", null, true);

try {

sleep(1000);

test();

} finally {

profiler.endOperation();

}

O resultado da análise deste código será:

Ao observar o tempo de execução da operação MyTest, observamos que o tempo total é de aproximadamente 10seg. Não existem códigos filhos que possuam instrumentação, logo temos que olhas o código contido em MyTest para compreender onde está a demora.

Analisando o código, observamos facilmente a explicação para uma demora de 1seg pela execução de um sleep(). Também podemos concluir que os outros 9 segundos devem estar sendo consumidos pela função test(). Para confirmar esta suposição, iremos instrumentar a função test(), como observado no código abaixo:

profiler.startOperation("MyTest", null, true);

try {

sleep(1000);

test();

} finally {

profiler.endOperation();

}

function test() {

profiler.startOperation("test()", null, true);

try {

sleep(9000);

} finally {

profiler.endOperation();

}

}

Abaixo o resultado da análise:

Agora podemos observar que do 9 dos 10 de segundos execução de “MyTest” estão sendo consumidos por test(). Esta função agora merece maior atenção na nossa análise, pois ela é responsável por 90% do tempo de processamento.

Ao analisar o código da função “test”, percebemos que os 9 segundos estão sendo consumidos por um sleep, o que justifique a demora, não havendo mais necessidade de buscar operações filhas.

Encontrando oportunidades de melhoria

A busca por oportunidades de melhorias no código fonte é uma das tarefas mais demoradas em um processo de otimização. Para ser produtivo nesta busca, o desenvolvedor deve interpretar com atenção os campos da grade “Operações agrupadas por nome” para perceber oportunidades de otimização, principalmente os campos Quantidade e Tempo s/ filhas.

Quantidade

A melhor otimização possível é a eliminação de códigos desnecessários e o campo Quantidade é o melhor indicativo de desperdícios. O benefício esperado ao reduzir a quantidade de execuções normalmente é uma redução proporcional do Tempo c/ filhas.

Exemplo: durante a otimização de uma venda se observa que o código “new OperacaoPedido()” foi executado 4 vezes e é a operação de maior custo observada na análise. A princípio, apenas uma execução deveria ser necessária e ao corrigir o processo para realizar apenas uma construção, se observou que esta operação deixou de ser a de maior custo.

Este tipo de otimização é interessante, pois tornar o código “new OperacaoPedido()” mais rápido pode ser uma tarefa complexa. Ao eliminar as chamadas redundantes tornamos este código menos relevante no tempo total da operação, focando a otimização em outros códigos mais simples e que trarão maior benefício ao processo de otimização.

A quantidade tem um papel ainda mais importante quando está relacionada a operações que envolvam I/O. Normalmente as operações de I/O, como disco e rede, tem custos elevados que ocorrem a cada execução, como o custo de conexão e propagação em operações de socket e o custo do acesso randômico em operações que utilizam o disco. Estes custos podem ser minimizados realizando leituras em blocos, ao invés de byte a byte, ou a execução de vários SQL em uma única chamada do método Database.query().

Tempo s/ filhas

Uma outra estratégia de otimização é dar foco nas operações com maior Tempo s/ filhas. Esta estratégia é boa quando não se conhece o código a ser otimizado a ponto de ser possível criticar se as quantidades de execuções das operações são coerente. Não por acaso, a grade “Operações agrupadas por Nome” é por padrão ordenada para exibir as operações com maior Tempo s/ filhas.

Duas conclusões são possíveis após a análise de um código fonte com elevado Tempo s/ filhas:

1. A operação em questão possui um tempo s/ filhas alto, pois executa métodos e funções que não foram instrumentados. Ao adicionar instrumentação nestes códigos, se observa que o custo da operação é reduzido e outras operações passam a ser mais representativas.

2. Todos os métodos e funções utilizados na operação já foram instrumentados e o código da operação realmente é responsável pelo tempo observado.

Se chegamos a segunda conclusão, teremos encontrado um bom candidato para a otimização de código e devemos procurar uma forma de torná-lo mais rápido. Técnicas de otimização fogem ao escopo deste documento, mas algumas dicas básicas são:

1. Evite pesquisas sequenciais. Estruturas como Arrays ordenados, DataSets e tabelas hashs (propriedades de objetos) permitem pesquisas mais eficientes;

2. Evite execução redundante em laços. Códigos contidos em um laço que não tem o resultado alterado durante a execução do laço podem ter o seu cálculo antecipado e armazenado em variáveis.

3. Nas consultas ao banco de dados, analise se o plano de execução gerado é adequado. Caso não seja, reveja a expressão SQL até conseguir um bom plano de execução. As vezes é necessária a criação de um novo índice para otimizar uma consulta.

Quando não for possível otimizar um código, avalie a possibilidade de diminuir a quantidade de execuções criando um cache de resultados. O problema desta abordagem é a eventual complexidade de garantir a consistência do cache caso os dados que originaram o cache sejam alterados.

Em alguns cenários é aceitável trabalhar com caches levemente defasados, possibilitando a criação de caches com estratégias de atualização simples e eficientes. Um exemplo desta abordagem é a classe DBCache (o cache local). Os dados contidos no cache podem estar desatualizados em até 1 minuto em relação ao banco de dados. Garantir os dados em cache sempre atualizados exigiria um acesso ao banco de dados a cada acesso ao cache, tornando inviável o uso do cache local.

Boas práticas de instrumentação

Ao iniciar um processo de otimização é importante adicionar instrumentação que englobe toda a operação analisada. Exemplo: se um relatório está sendo analisado, todo o código contido na interação “run” deve estar contido dentro de um startOperation() e um endOperation(). Se a execução associada a um botão for lenta, todo o evento onClick ou a interação destino associada deve ser coberta.

O objetivo desta prática é garantir que o tempo total da operação possa ser observado no resultado da análise e seja comparado com a percepção de tempo do usuário. Se o valor for próximo, significa que o código suspeito realmente é responsável pela demora observada e pode se prosseguir com a investigação. Caso o tempo observado seja muito inferior ao tempo observado pelo usuário, o problema pode estar em códigos executados antes ou depois do código suspeito e neste caso o código que a princípio seria o problema, não merece ser analisado.

Após um processo de otimização é interessante preservar as instrumentações adicionadas, pois em otimizações futuras estas informações já estarão disponíveis sem maiores esforços. A única ressalva é não manter instrumentação em códigos que sejam executados na ordem de milhares de vezes, pois o profiler tem um custo que pode ser maior que o próprio código analisado. Vale ressaltar que este custo é percebido apenas quando o iEngine está com o Profiler habilitado.

Avaliando o custo de execuções remotas

Os métodos da classe Connection e Database possuem um comportamento interessante que merece ser destacado.

Uma execução remota, como uma consulta ao banco de dados, é uma operação que pode ser observada em 2 etapas na perspectiva do iEngine cliente:

1. O envio da expressão SQL para o servidor, observado no profiler como “Writing to TCP/IP socket”;

2. A leitura dos registros que foram retornados pelo banco de dados, observado como “Reading from TCP/IP socket”;

No entanto, durante estas 2 etapas, existe o tempo necessário para executar a consulta e o custo de acesso ao banco de dados. Este custo é desconhecido pelo cliente, pois é uma operação que está ocorrendo no iEngine servidor. Na perspectiva do cliente, está ocorrendo apenas uma demora na recepção da resposta. Abaixo um diagrama que ilustra melhor este conceito:

Na perspectiva do iEngine cliente, o tempo da operação “Reading from TCP/IP socket” incluí o tempo do processamento do servidor. Portanto sempre devemos interpretar o tempo desta operação como o custo de transmissão mais o custo de processamento no servidor, este último sendo passível de otimização, como o obtido ao otimizar uma expressão SQL.

Maiores detalhes do que ocorreu durante um “Reading from TCP/IP socket” podem ser obtidos analisando o log do profiler gerado pelo servidor.

Conclusão

O processo de otimização deve ser realizado com técnicas e ferramentas que direcionem o processo para os reais gargalos de performance. A otimização baseada apenas na intuição é improdutiva e ineficiente.

Toda tentativa de otimização necessita de uma medição do tempo de execução anterior e posterior à modificação. Apenas as alterações que gerem ganhos significativos devem ser mantidas, principalmente quando a otimização gera um prejuízo na legibilidade do código.

A ferramenta de Profiler do Bematech ERP é a principal ferramenta para guiar o desenvolvedor no processo de otimização e saber utilizá-la é fundamental para ser produtivo nesta tarefa.

Outras referências

• • API do Profiler: http://desenvolve.bematech.com:8001/help/symbols/Profiler.html.

  • Texto do Wikipedia explicando o conceito e funcionamento das ferramentas de profiler: http://en.wikipedia.org/wiki/Profiler_(computer_science).