LogProfiler - Profiler de execução de programas AdvPL

LogProfiler - Profiler de execução de programas AdvPL

Este documento aborda a utilização de um recurso da plataforma TOTVS Tec e TOTVS | Platform para medir o tempo utilizado na execução de uma aplicação AdvPL (conhecido popularmente por "Profiler"), funcionalidade implementada nativamente no servidor de aplicação (TOTVS | Application Server), bem como um exemplo de sua utilização e visão geral dos resultados gerados.

Requisitos

O recurso LogProfiler está disponível a partir da build 7.00.090818P, para o TOTVS | Application Server. A primeira implementação deste recurso no binário foi na build 7.00.081215P, porém os dados gerados para análise de performance ainda não ofereciam um nível de detalhamento que contemplasse um diagnóstico mais apurado ao executar rotinas complexas.

Indicação

Este recurso é indicado para a análise de performance em rotinas e aplicações AdvPL, em momento de desenvolvimento e/ou homologação, para avaliar a quantidade de instruções executadas e tempo de resposta destas instruções, para análise de pontos críticos, funções mais chamadas e pontos que podem ser melhorados em um processo. Também é indicado para as situações onde uma determinada rotina, que tinha um tempo médio de processo determinado, passou a apresentar, a partir de um determinado momento, um tempo maior de execução, e existe a necessidade de descobrir se o fator que desencadeou este comportamento está relacionado à algumas funções do código executado, que tiveram alteração de comportamento e tempo de resposta, ou até mesmo uma alteração de lógica ou implementação no código-fonte, onde uma ou mais funções tiveram funcionalidades agregadas que consequentemente acarretaram em um acréscimo no tempo de execução de cada chamada.

Dadas as características do LogProfiler, é possível utilizar este recurso inclusive em um ambiente de produção para avaliar, por exemplo, uma rotina ou funcionalidade que apresenta comportamentos de performance evidente entre um ambiente de homologação e um de produção, onde a análise em ambiente de homologação não identificou nenhum ponto crítico ou significativo no processo, porém no ambiente de produção a performance da rotina é prejudicada.

Configuração

O registro de performance de execução das rotinas é realizado diretamente no log de console do TOTVS | Application Server (console.log), em formato texto, com leiaute para visualização. Deste modo, deve ser verificado se a geração do arquivo de log de console está habilitada no TOTVS | Application Server. Para habilitar a geração deste arquivo, deve-se acrescentar a chave ConsoleLog=1, na seção [GENERAL], do arquivo de configuração do TOTVS | Application Server (appserver.ini ). Esta configuração somente é considerada no momento da inicialização do TOTVS | Application Server (como serviço ou console).

A habilitação deste recurso é configurada por ambiente dentro de um serviço do TOTVS | Application Server, inserindo na configuração do ambiente (seção [Environment]) a chave LogProfiler=1, diretamente no arquivo de configuração do TOTVS | Application Server. Esta chave pode ser inserida mesmo com o serviço em execução, e terá efeito sob todos os novos JOBS e/ou novas conexões de TOTVS | SmartClient executadas neste TOTVS | Application Server iniciadas após a chave ser configurada.

O recurso de profiler também está sendo implementado gradativamente em pontos específicos do sistema, para gerar informações instrumentadas de execução de código, por exemplo na engine de Web Services, onde um profiler habilitado no INI não será tão eficaz, pois quando a Working Thread de Web Service termina, o profiler mostrado contemplará todas as requisições de processamento, tornando praticamente impossível a identificação do peso de cada chamada. Estas implementações de profiler estão documentadas respectivamente em cada componente.

Informações geradas no LOG de Console

Após o término de uma rotina, executada com o LogProfiler habilitado, a partir de um TOTVS | SmartClient, será gerado no log de console uma entrada com a informação “BEGIN APP PROFILER”, contendo os seguintes dados :

      --- BEGIN APP PROFILER ( THREAD [X] USER [Y] MAIN [Z] ) ---

Onde "X" indica o número da thread/processo que executou a rotina, "Y" o nome do usuário da estação remota que executou a rotina e "Z" o nome da rotina. Caso o processo seja executado por um JOB no arquivo de configuração ou um JOB interno iniciado a partir de um programa AdvPL, a informação apresentada é “BEGIN JOB PROFILER”, seguido do nome do JOB configurado (ou em branco caso seja um JOB iniciado pela aplicação AdvPL), e o nome do programa executado pelo JOB.

Após esta informação, são gravadas as chamadas de todas as funções básicas e de RPO feitas pelo programa, onde abaixo do totalizador de cada chamada, são apresentadas as origens de cada chamada, no formato abaixo :

      CALL <FUNNAME> ( <RECURSO> ) C <calltot> T <timertot> M <slowest>-- FROM ORIGEM LN <line>      C <thiscall> T <thistime> M <slowest>-- FROM ORIGEM LN <line> C <thiscall> T <thistime>      M <slowest>(…)

A informação prefixada com "CALL" é um totalizador de chamadas de uma função, cujo nome é apresentado em <FUNNAME>, a origem/fonte da função é identificada em <RECURSO> (para funções básicas da linguagem AdvPL, o recurso é Internal, para funções de RPO o recurso é o nome do código-fonte onde o código-fonte da função está escrito), e nos acumuladores <calltot>, <timertot> e <slowest>, são apresentados respectivamente o número total de chamadas da função, o tempo total utilizado por todas as chamadas e a chamada desta função que demorou mais tempo.

Abaixo dela serão apresentados uma ou mais linhas prefixadas com "– FROM", onde é apresentado em ORIGEM qual a função e respectivo código-fonte que fez a chamada, em <line> é apresentada a linha do código-fonte onde a chamada foi feita e em <thiscall>, <thistime> e <slowest> são apresentados, respectivamente, quantas chamadas para a função <FUNNAME> tiveram origem neste ponto, qual foi o tempo gasto com estas chamadas neste ponto e qual foi a chamada mais lenta realizada deste ponto.

Para exemplificar o nível de detalhamento das informações geradas, vamos ver inicialmente o programa abaixo:

Ao ser executado, através de um TOTVS | SmartClient, com a configuração LogProfiler especificada no ambiente em uso, observe o log de console gerado:

[INFO ][SERVER] Env [advpltests_top_mssql] Log profiler enabled
[INFO ][SERVER] [22/01/2010 14:35:26] Iniciando Programa u_myprofile      Thread 4876 (juliow,TEC-AUTOQUAD)
010000,020000,030000,040000,050000,060000,070000,080000,090000,100000,110000,120000,130000,140000,150000,160000,170000,180000,190000,200000
,210000,220000,230000,240000,250000,260000,270000,280000,290000,300000,310000,320000,330000,340000,350000,360000,370000,380000,390000,400000
,410000,420000,430000,440000,450000,460000,470000,480000,490000,500000,510000,520000,530000,540000,550000,560000,570000,580000,590000,600000
,610000,620000,630000,640000,650000,660000,670000,680000,690000,700000,710000,720000,730000,740000,750000,760000,770000,780000,790000,800000
,810000,820000,830000,840000,850000,860000,870000,880000,890000,900000,910000,920000,930000,940000,950000,960000,970000,980000,990000,000001,
[INFO      ][SERVER] [Thread 4876] [22/01/2010 14:35:48] Fim Thread (juliow, TEC-AUTOQUAD)

Após o final do programa, foi gerado o seguinte LOG:

--- BEGIN APP PROFILER ( THREAD [4876] USER [juliow] MAIN [U_MYPROFILE] ) 
---CALL               U_MYPROFILE (       MYPROFILE.PRW) C        1 T    21.859 M    21.859
-- FROM                     #UNKNOW_I# LN      7 C        1 T    21.859 M      21.859
CALL               DOSOMETHING (  MYPROFILE.PRW) C        1 T    10.938 M    10.938
-- FROM    U_MYPROFILE (MYPROFILE.PRW)      LN     11 C        1 T    10.938 M    10.938
CALL                   MsgInfo (       Internal) C        1 T     6.562 M          6.562
-- FROM    U_MYPROFILE (MYPROFILE.PRW) LN     12 C        1 T     6.562 M     6.562
CALL                  MsgYesNo (       Internal) C        1 T     4.359 M     4.359
-- FROM    U_MYPROFILE (MYPROFILE.PRW) LN      9 C        1 T     4.359 M          4.359
CALL                     sleep (       Internal) C      100 T    10.938 M     0.110
-- FROM    DOSOMETHING (MYPROFILE.PRW)      LN     30 C      100 T    10.938 M     0.110
CALL                       str (       Internal) C        1 T     0.000 M          0.000
-- FROM    U_MYPROFILE (MYPROFILE.PRW) LN     12 C        1 T     0.000 M     0.000
CALL                   seconds (       Internal) C        2 T     0.000 M     0.000
-- FROM    U_MYPROFILE (MYPROFILE.PRW) LN     10 C        1 T     0.000 M          0.000
-- FROM    U_MYPROFILE (MYPROFILE.PRW) LN     12 C        1 T     0.000 M     0.000
CALL                      left (       Internal) C    10000 T     0.000 M     0.000
-- FROM    DOSOMETHING (MYPROFILE.PRW) LN     27 C    10000 T     0.000 M          0.000
CALL                    ConOut (       Internal) C        1 T     0.000 M     0.000
-- FROM    DOSOMETHING (MYPROFILE.PRW)      LN     33 C        1 T     0.000 M     0.000
CALL                  ERRORSYS (   APLIB240.PRW) C        1 T     0.000 M          0.000
-- FROM                     #UNKNOW_I# LN     16 C        1 T     0.000 M     0.000
CALL             SysErrorBlock (       Internal) C        1 T     0.000 M     0.000
-- FROM        ERRORSYS (APLIB240.PRW) LN     17 C        1 T     0.000 M          0.000
--- END APP PROFILER ---

Ao analisar o resultado acima, obtemos as seguintes informações: A função U_MYPROFILE levou 21,859 segundos para ser executada, onde 10,938 foram usados com a chamada da função DOSOMETHING, chamada da função U_MYPROFILER, na linha 11 do fonte MYPROFILE.PRW ... 6,562 segundos foram gastos com a função MsgInfo() (como é uma função de Interface, ela contabiliza o tempo que ficou esperando uma ação de usuário), 4,359 segundos com a função MsgYesNo(), a função seconds() foi chamada 2 vezes.

Existem funções que ainda não são contempladas pelo LogProfiler, são funções atômicas e extremamente rápidas, mas a utilização das mesmas ainda não é reportado pelo Profiler, esta implementação está em avaliação. São elas:

Como interpretar as informações geradas pelo Profiler

Uma vez obtido um log de profiler com as informações para análise, por ser um log que pode ser muito grande e completo, a análise das informações geradas para a tomada de decisão e identificação de gargalos ou pontos críticos deve seguir um roteiro pré-determinado.

Inicialmente, deve-se identificar onde é gasto aproximadamente 80% do tempo de processamento, sempre começando pelas funções básicas da linguagem (funções identificadas no profiler como “Internal”). Depois, verificar dentro das funções identificadas, começando pela que consome maior tempo, se existem diferenças de tempo significativas nas chamadas de acordo com a origem e/ou se existem pontos que chamam muitas vezes a mesma função. Nas análises iniciais feitas com este recurso em diversos fontes, algumas ocorrências comuns foram identificadas, sendo:

• Função DBSeek() em tabela acessada via TOTVS | DBAccess
  
  A instrução DBSeek() realiza uma busca binária por uma chave parametrizada, completa ou parcial, e, em caso de sucesso, reposiciona a tabela alvo da busca no registro que atende a condição de busca, ou mediante parâmetro, no caso de não haver correspondência entre a chave de busca fornecida, o registro imediatamente posterior à chave especificada é posicionado.
  Nos casos onde é utilizada uma busca que deve posicionar no próximo registro da ordem atual da tabela quando não houver correspondência exata (comportamento conhecido como Soft Seek), o TOTVS | DBAccess pode fazer muitas queries para determinar qual é este próximo registro.
  Normalmente, em determinadas situações no sistema, tais chamadas são necessárias, porém em outros casos, algumas alterações na lógica do programa permitem uma busca mais eficiente e reduzir este número de chamadas.
  Por exemplo, verificando um determinado profiler, em uma operação de 50 segundos, 23,77 segundos foram gastos com instruções DBSeek(). Vide exemplo abaixo, onde foram isoladas apenas as maiores chamadas e origens:
  
  

        CALL    dbseek(Internal)                                   C       3237 T       23.770 M        0.078
  -- FROM TSTCLASS:GETCPOINFO      (TSTX0010.PRW) (123)           C        458 T       14.039 M        0.078

  
  
  Neste caso, o código-fonte foi analisado, e percebeu-se que era possível fazer uma query leve no banco de dados, que retorna em uma requisição todos os registros necessários para processamento, sem precisar fazer as 458 chamadas de DBSeek().
  
   

• Uso da função AScan() em arrays grandes
  
  A operação AScan() – busca em array – normalmente é uma operação rápida, onde um bloco de código é executado para cada elemento do array, em sequência, onde a função retorna o número do primeiro elemento onde o bloco de código de busca executado retornou a condição .T. ( TRUE ).
  
  As ocorrências de excesso de consumo de tempo nestas operações costumam acontecer em dois casos:
  
  
  
  1 – O bloco de código usado para estabelecer a condição de busca contém funções dentro dele. Por exemplo:
  
  
  nPos := AScan (aMeuArray , { | x | x[1] == ABC->(Recno()) })
  
  
  Para cada elemento do array a ser comparado, a função Recno() é executada. Em um array de 1000 elementos, onde o elemento procurado foi encontrado na posição 750 do array, a função Recno() foi chamada 750 vezes. Caso nenhum registro seja encontrado, a função será executada 1000 vezes (tamanho do array). Embora a função Recno() seja rápida, já que o registro atual não deveria ser alterado durante a busca pelo processo atual, é mais vantagem armazenar o Recno() em uma variável de memória e fazer a busca com ele, ficando o fonte assim:
  
  
  
  nABCRecno := ABC->(Recno())
  
  nPos := AScan ( aMeuArray , { | x | x[1] == nABCRecno } )
  
  
  
  2 – O array pode crescer durante o processo, ou já é criado com um tamanho grande, e a operação de varrer o array com mais elementos demora mais tempo, e se nenhum elemento foi encontrado, o bloco de código informado como parâmetro foi executado uma vez para cada elemento do array. Cada comparação, mesmo sendo rápida, quando executadas muitas vezes dentro de loopings, tornam o número de chamadas extremamente grande, contribuindo significativamente no tempo de processamento. Neste caso, deve ser avaliado se é possível diminuir as incidências de busca de dados dentro do array e, mediante um estudo de caso, pode-se estudar a utilização de um array ordenado, onde o algoritmo de busca é muito, mas muito mais eficiente. O estudo de caso e uso de array ordenado serão abordados em assunto/documento específico para tal finalidade.
  
  
   
• Tempo alto em determinadas operações DBSkip()
  
  
  Sob determinadas circunstâncias, e em alguns fontes, poucas chamadas da função DBSkip(), em um determinado ponto acessando uma determinada tabela, pode consumir mais tempo do que muitas chamadas de DBSkip() feitas para outra tabela em outros pontos do sistema.
  
  Em geral, quando aparecem diferenças significativas dos tempos de DBSkip() entre tabelas distintas, ou o Banco de Dados e/ou TOTVS | DBAccess apresentaram picos de CPU e/ou I/O durante o processo, ou a tabela em questão estava utilizando uma expressão de filtro que não é totalmente resolvida pela RDD, havendo internamente na aplicação um tráfego adicional de registros para validação no TOTVS | Application Server, onde muitos registros são lidos e trafegados, mas poucos registros atendem a condição de filtro. Esta situação é explicada na documentação da função DBSetFilter(), este documento deve ser lido na íntegra, e o código-fonte AdvPL que apresentou ocorrências de diferença de tempo de pulo de registro (DBSkip()) significativas deve ser verificado.

Continuando a análise

Baseado nas informações obtidas nas chamadas de funções básicas, caso não haja nenhuma divergência e/ou aparentemente está tudo “rapidinho”, onde nenhuma das funções internas sobressai, isto é, o tempo total de processo está bem distribuído entre diversas funções, que executam rápido, a próxima etapa de análise é na lógica do programa, e nas funções do repositório chamadas no processo. Esta etapa é um pouco mais complexa, pois as alterações podem ter impacto em outros pontos do sistema, e requer conhecimento amplo nos fontes envolvidos.

Neste momento, a pergunta é:“ --- Existe forma de chegar ao mesmo resultado chamando menos instruções?” . Verificando no log gerado, temos a rastreabilidade da origem da chamada de uma determinada função, então conseguimos navegar na árvore de execução buscando no log quem chamou quem, e quantas vezes. Nesta análise, também partimos das funções básicas, por exemplo uma DBSkip(), que foi chamada 2830 vezes, e consumiu tempo total de 1,197 segundos. Estamos olhando um trace de um Web Service de atualização de um registro na base de dados ... estamos falando de um, apenas um registro. Como a atualização de um registro fez 2.830 DBSkip(), distribuídos em  25 pontos de chamada?

CALL    dbskip(Internal)                                   C       2830 T        1.197 M        0.016
-- FROM CHAMTEC:GETATTACH      (CHAMTEC WEBSERVICES.PRW) (1849) C         19 T        0.016 M        0.016
-- FROM FILLGETDADOS (APLIB171.PRW) (117)           C         28 T        0.000 M        0.000
-- FROM FILLGETDADOS (APLIB171.PRW) (94)                   C         16 T            0.000 M        0.000
-- FROM FTABPADRAO (PONXFUN.PRX) (880)                     C       1232 T        0.591 M        0.016
-- FROM FTABTURNO (PONXFUN.PRX) (5032)                     C        192 T        0.251 M        0.016
-- FROM MSMM (MATXFUNB.PRX)      (519)                          C        192 T        0.202 M        0.016
-- FROM REGTOMEMORY (MATXATU.PRX) (6634)              C        370 T        0.015 M        0.015
-- FROM RETORDER (RHLIBSIX.PRX) (57)                       C          1 T            0.000 M        0.000
-- FROM RUNTRIGGER (MATXATU.PRX) (1450)                    C          5 T        0.000 M        0.000
--      FROM SENDWFTEMPLATE (TMKA510.PRW) (2294)                C        141 T        0.015 M        0.015
-- FROM SLAREGISTER:FINDSEVERITY      (TMKA530B.PRW) (947)      C          5 T        0.000 M        0.000
-- FROM SLAREGISTER:FINDSLA (TMKA530B.PRW) (599)           C          4 T        0.000 M        0.000
-- FROM SLAREGISTER:FINDSLA (TMKA530B.PRW) (657)           C          3 T            0.000 M        0.000
-- FROM SLAREGISTERTOP:FILLENTITIES (TMKA530J.PRW) (183)   C          4 T        0.000 M        0.000
--      FROM SLAREGISTERTOP:LOAD (TMKA530J.PRW) (136)           C          2 T        0.000 M        0.000
-- FROM SLASERVICE:LOAD      (TMKA530S.PRW) (137)               C          5 T        0.000 M        0.000
-- FROM TABLEINDEX (APLIB200.PRW) (1714)          C          5 T        0.000 M        0.000
-- FROM TELESERVICEUSERDIALOG:SHOWDIALOG (TMKA503A.PRW) (467) C         44 T         0.000 M        0.000
-- FROM TELESERVICINGTOP:FILLRELATIONS (TMKA505.PRW) (165) C          4 T        0.015 M        0.015
--      FROM TKPUTDTFIM (TMKA510.PRW) (596)                     C          1 T        0.000 M        0.000
-- FROM TKPUTDTFIM (TMKA510.PRW)      (615)                     C         20 T        0.015 M        0.015
-- FROM TSTABLE:LOAD (TMKA500H.PRW) (193)                  C        458 T        0.015 M        0.015
-- FROM TSTABLESTRUCTURETOP:FILLDETAIL (TMKA505F.PRW) (328) C         19 T           0.000 M        0.000
-- FROM TSTOOLBARLISTTOP:FILLCLASS (TMKA505C.PRW) (104)    C         40 T        0.031 M        0.016
--      FROM U_SIMBODY (SIMXTMK.PRW) (5350)                     C         20 T        0.031 M        0.016

Metade das chamadas foram realizadas de uma função (FTabPadrao), e consumiram quase metade do tempo de DBSkip()...pouco mais de ½ segundo.  Vamos ver quem chama esta função.

      CALL    FTABPADRAO(PONXFUN.PRX)                            C        269 T        3.633 M        0.032-- FROM BLDCALTNOSEQ      (PONXFUN.PRX) (2707)                  C         77 T        0.031 M        0.016-- FROM FTABTURNO (PONXFUN.PRX) (5031)         C        192 T        3.602 M        0.032

A função FTabPadrao() foi chamada 269 vezes, todas as chamadas demoraram 3,6 segundos. Ela por sua vez chamou a DBSkip() 1232 vezes, entre outras funções. Analisando a árvore de chamadas, e verificando os fontes, pode haver uma alternativa diferente para fazer esta função, e/ou pode haver uma alternativa onde não seja necessário chamar a mesma função 269 vezes, mas apenas 10 ou 20. Reduzindo a quantidade de chamada de funções do fonte (PRW), automaticamente todas as chamadas que esta função faz são reduzidas. Se a função FTabPadrao for chamada apenas 20 vezes ao invés de 269, o tempo total deve cair de 3,63 segundos para 0,27 segundos. Em um processo de 10 segundos, onde uma chamada de 3,6 segundos é reduzida para 0,3 segundos, o tempo total é reduzido de 10 para 6,7 segundos, houve uma redução de 33 % no tempo total.

Dicas importantes

1. Sempre a análise deve partir de um ambiente real, com dados reais, e sempre as ações tomadas devem partir das chamadas que consomem maiores tempos. Mexer em uma função por que eu acho que vai melhorar, na maioria dos casos apenas gera instabilidade e não gera retorno visível.
2. Procure obter um ou mais profilers da mesma rotina. Se eles apresentam diferenças em tempo, mas não apresentam diferenças de carga (mesma quantidade de instruções executadas em tempos diferentes), a máquina ou algum componente do ambiente pode estar carregado.
3. Não é prático e viável analisar profilers muito pequenos, ou parciais. Se um determinado processo de cálculo processa 30 dias de movimento, e demora 3 horas, mas o processamento de apenas um dia demora 5 minutos, é preferível rodar o processo inteiro com os 30 dias para gerar o profiler. Um array estático usado  no processo atualizado durante o processamento pode ter um tempo insignificante com um dia de movimento, e consumir um tempo muito representativo quando você executar o processo inteiro.
4. Como a execução de uma aplicação que usa recursos distribuídos está sujeita ao estado e disponibilidade de tais recursos, um profiler pode ser usado em um ambiente de produção, para identificar ocorrências como “lentidões esporádicas” no ambiente, aquelas somente reproduzidas no ambiente de produção. Para isto, basta “clonar” a configuração de ambiente (environment) do TOTVS | Application Server (appserver.ini) com outro nome, habilitar nesta cópia a chave LogProfiler=1, e no momento que o sistema estiver apresentando a “tal lentidão”, abre-se um TOTVS | SmartClient conectando e usando este ambiente (environment), em um slave da produção mesmo, para que no final do processo apenas esta execução gere um log de profiler, que vai mostrar onde os tempos foram gastos. Comparando dois profilers obtidos na execução da mesma rotina, um quando o servidor está “rápido”, e outro onde está apresentando “lentidão”, as diferenças nos tempos apresentarão exatamente quais funções estão sendo afetadas, e ajudar muito na busca pelas causas.
5. A cada ação tomada no fonte na busca pelo ganho de performance, deve ser feito um novo profiler, para certificar-se que efetivamente houve uma redução no tempo de processo. Determinadas alterações podem dar uma ilusão de performance, como por exemplo fazer um cache para uma determinada requisição. “--- É óbvio que vai ficar mais rápido ...”: Não, não é óbvio não, pois para fazer o cache você chamará outras funções, criará arrays e afins, e no final das contas, após você executar o profiler, pode ser que o seu cache apresente apenas 10% de ganho de performance, e a um custo no aumento do consumo de memória gritante em relação a versão anterior, 10% mais lenta, mas que não usava tanta memória.
6. Cuidado com o excesso de otimização, pois quanto mais específico/especialista for o seu código-fonte, ele tende a ser mais rápido, porém perde-se a portabilidade e legibilidade do código-fonte, dificultando muito a manutenção do mesmo.