3

Recentemente fiz uma pergunta sobre como analisar o impacto de um trecho de código em ADVPL. O grande @siga0984 deu uma ótima resposta, e mesmo com a minha pequena intimidade com o Protheus consegui ligar o profiler e obter um relatório.

Porém, tive dificuldades em interpretar alguns detalhes do relatório. Tome esse excerto sobre as chamadas de funções:

CALL                 LINHAFAKE (   SGEOF001.PRW) C  1377566 T   127.299 M     0.203 D 0
-- FROM   U_MAKEALLJSON (SGEOF001.PRW) LN    310 C  1377566 T   127.299 M     0.203 D 0

CALL                   MARMOTA (   SGEOF011.PRW) C      210 T    87.098 M     6.422 D 0
-- FROM     #CODEBLOCK# (SGEOF011.PRW) LN      4 C      210 T    87.098 M     6.422 D 0

CALL                   STRTRAN (       Internal) C  2755132 T     2.486 M     0.016 D 0
-- FROM        ESCENVST (SGEOF001.PRW) LN     62 C  1377566 T     1.310 M     0.016 D 0
-- FROM        ESCENVST (SGEOF001.PRW) LN     63 C  1377566 T     1.176 M     0.016 D 0

Eu consigo afirmar o seguinte:

  • LINHAFAKE foi chamado pela função U_MAKEALLJSON na linha 310
  • MARMOTA foi chamado por um CODEBLOCK que foi definida na linha 4 do arquivo SGEOF011.PRW
  • STRTRAN (que é uma função interna) foi chamada em duas linhas distintas da função ESCENVST, as linhas 62 e 63
  • houve 210 chamadas totais a MARMOTA, dando um tempo total de 87.1 segundos
  • houve 2755132 chamadas totais a STRTRAN, sendo que 1377566 foram da linha 42 da função ESCENVST, e 1377566 da linha 63 da mesma função, demorando um total de 1.3 segundos sobre as chamadas da linha 62 e 1.2 segundos nas chamadas da linha 63

Como consegui interpretar isso? Bem, não foi com ajuda do artigo na TDN. A única coisa que falava sobre análise do profiler no TDN indicado na resposta do @siga0984 foi o seguinte:

Envie os arquivos console_lentidao.log e console.bak para o suporte avaliar

Então, fui pelo que se pareceu mais óbvio:

  • CALL indica a função que foi chamada, com o nome do arquivo onde ela foi definida entre parênteses
  • C é a quantidade de chamadas, que é indicada no campo seguinte
  • T é o tempo total de execução naquele contexto
  • FROM indica as diversas maneiras em que a função chamada é alcançada, seguido então pela função chamadora, arquivo de definição da função chamadora e linha em que ocorre a chamada (indicada pelo LN)

Em compensação, teve 2 campos que eu não entendi de jeito nenhum:

  • o que o campo M indica? Por que eu tenho que MARMOTA tem um M de 6.422?
  • o que o campo D indica? Por que todos os valores vem com 0? (as outras chamadas que omiti também são todas com D 0 no final das linhas)

Também tive dúvidas em algumas informações do cabeçalho do relatório do profiler:

[conn_ios_in: 2]
[conn_bytes_in: 200]
[conn_peakbytes_in: 134]
[conn_ios_out: 1]
[conn_bytes_out: 539]
[conn_peakbytes_out: 539]

Esse conn_ios_in indica o quê? E esse conn_bytes_in? Não me parece ser sobre tráfego de rede geral, porque fiz 210 requisições HTTP nesse teste.

Também não consegui obter informações relevantes do consumo de memória da aplicação, talvez por não saber ler o relatório. A seção MEMORY LOG PROFILER veio em branco, vazia de conteúdo.

O relatório completo segue abaixo, se for de interesse para ajudar na escrita da resposta:

--- BEGIN APP PROFILER ( THREAD [1368] ) ----------------------
[program: U_FEXT]
[user: ****]
[computer: ****]
[environment: ****]
[rpodb: top]
[localfiles: CTREE]
[apo: c:\totvs 12\microsiga\protheus\apo\tttp120.rpo]
[begin: Tue Nov 27 16:41:23 2018]
[spent: 00:50:25]
[build: 7.00.131227A-20150107]
[thread: 1368]
[remark: ]

[conn_ios_in: 2]
[conn_bytes_in: 200]
[conn_peakbytes_in: 134]
[conn_ios_out: 1]
[conn_bytes_out: 539]
[conn_peakbytes_out: 539]


------------------------ ADITIONAL MEMORY INFO - RUNNING ENV ----------
Constant List Count .....     1345 Size      14241 Bytes
Macro Array Cache Count .        0 Size          0 Bytes
Program List Count ......        5
-----------------------------------------------------------------------

Total Internal Calls         5511113 Timer   2619.209 s.
Total ClMethod Calls               0 Timer      0.000 s.
Total User APO Calls        30307089 Timer  11562.917 s.


--- CALLS DETAILED INFO ( SORT BY NAME ) ---


CALL                      AADD (       Internal) C      210 T     0.000 M     0.000 D 0
-- FROM         MARMOTA (SGEOF011.PRW) LN     14 C      210 T     0.000 M     0.000 D 0

CALL                       ASC (       Internal) C 19285924 T     1.395 M     0.016 D 0
-- FROM        ESCENVST (SGEOF001.PRW) LN     68 C 19285924 T     1.395 M     0.016 D 0

CALL                       CHR (       Internal) C      420 T     0.000 M     0.000 D 0
-- FROM         MARMOTA (SGEOF011.PRW) LN     16 C      420 T     0.000 M     0.000 D 0

CALL                    CONOUT (       Internal) C      210 T     0.927 M     0.016 D 0
-- FROM         MARMOTA (SGEOF011.PRW) LN     16 C      210 T     0.927 M     0.016 D 0

CALL                CREATEARRA (       Internal) C      211 T     0.000 M     0.000 D 0
-- FROM         MARMOTA (SGEOF011.PRW) LN     14 C      210 T     0.000 M     0.000 D 0
-- FROM   U_MAKEALLJSON (SGEOF001.PRW) LN    268 C        1 T     0.000 M     0.000 D 0

CALL                  ERRORSYS (   APLIB240.PRW) C        1 T     0.016 M     0.016 D 0
-- FROM                (Internal Step) LN      1 C        1 T     0.016 M     0.016 D 0

CALL                  ESCENVST (   SGEOF001.PRW) C  1377566 T   118.311 M     0.187 D 0
-- FROM       LINHAFAKE (SGEOF001.PRW) LN    233 C  1377566 T   118.311 M     0.187 D 0

CALL                GETENVSERV (       Internal) C        1 T     0.000 M     0.000 D 0
-- FROM        ERRORSYS (APLIB240.PRW) LN     22 C        1 T     0.000 M     0.000 D 0

CALL                GETPVPROFS (       Internal) C        1 T     0.000 M     0.000 D 0
-- FROM        ERRORSYS (APLIB240.PRW) LN     22 C        1 T     0.000 M     0.000 D 0

CALL                GETREMOTET (       Internal) C  2755134 T     2.207 M     0.016 D 0
-- FROM         ISBLIND (APLIB100.PRW) LN   4188 C  2755134 T     2.207 M     0.016 D 0

CALL                GETSRVININ (       Internal) C        1 T     0.000 M     0.000 D 0
-- FROM        ERRORSYS (APLIB240.PRW) LN     22 C        1 T     0.000 M     0.000 D 0

CALL                  HTTPPOST (       Internal) C      210 T    86.093 M     6.422 D 0
-- FROM         MARMOTA (SGEOF011.PRW) LN     14 C      210 T    86.093 M     6.422 D 0

CALL                   INCPROC (   MSPROCES.PRW) C  1377567 T  2608.448 M     0.110 D 0
-- FROM   U_MAKEALLJSON (SGEOF001.PRW) LN    308 C  1377567 T  2608.448 M     0.110 D 0

CALL                   ISBLIND (   APLIB100.PRW) C  2755134 T  2574.461 M     0.110 D 0
-- FROM         INCPROC (MSPROCES.PRW) LN    168 C  1377567 T  1289.645 M     0.020 D 0
-- FROM         INCPROC (MSPROCES.PRW) LN    171 C  1377567 T  1284.816 M     0.110 D 0

CALL                 LINHAFAKE (   SGEOF001.PRW) C  1377566 T   127.299 M     0.203 D 0
-- FROM   U_MAKEALLJSON (SGEOF001.PRW) LN    310 C  1377566 T   127.299 M     0.203 D 0

CALL                   MARMOTA (   SGEOF011.PRW) C      210 T    87.098 M     6.422 D 0
-- FROM     #CODEBLOCK# (SGEOF011.PRW) LN      4 C      210 T    87.098 M     6.422 D 0

CALL                   STRTRAN (       Internal) C  2755132 T     2.486 M     0.016 D 0
-- FROM        ESCENVST (SGEOF001.PRW) LN     62 C  1377566 T     1.310 M     0.016 D 0
-- FROM        ESCENVST (SGEOF001.PRW) LN     63 C  1377566 T     1.176 M     0.016 D 0

CALL                SYSERRORBL (       Internal) C        1 T     0.000 M     0.000 D 0
-- FROM        ERRORSYS (APLIB240.PRW) LN     23 C        1 T     0.000 M     0.000 D 0

CALL                      TYPE (       Internal) C  2755134 T  2529.982 M     0.047 D 0
-- FROM         ISBLIND (APLIB100.PRW) LN   4188 C  2755134 T  2529.982 M     0.047 D 0

CALL                    U_FEXT (   SGEOF011.PRW) C        1 T  3021.317 M  3021.317 D 0
-- FROM                (Internal Step) LN      1 C        1 T  3021.317 M  3021.317 D 0

CALL             U_MAKEALLJSON (   SGEOF001.PRW) C        1 T  3021.317 M  3021.317 D 0
-- FROM          U_FEXT (SGEOF011.PRW) LN      4 C        1 T  3021.317 M  3021.317 D 0

CALL                   VALTYPE (       Internal) C  1377567 T     0.769 M     0.016 D 0
-- FROM         INCPROC (MSPROCES.PRW) LN      0 C  1377567 T     0.769 M     0.016 D 0

--- SOURCE DETAILED INFO ---

                  APLIB240.PRW 19/12/2014 17:45:08 [FULL]
                  SGEOF001.PRW 27/11/2018 16:41:10 [USER]
                  MSPROCES.PRW 19/12/2014 19:03:54 [FULL]
                  APLIB100.PRW 23/02/2015 09:10:40 [FULL]
                  SGEOF011.PRW 27/11/2018 16:00:01 [USER]

--- MEMORY LOG PROFILER ---

[Thread  1368] 
--- END APP PROFILER ---

1 Resposta 1

4
+50
  • o que o campo M indica? Por que eu tenho que MARMOTA tem um M de 6.422?

R: M indica o tempo da maior chamada. Por exemplo, a função MARMOTA foi chamada 210 vezes, consumindo um tempo total de 87.1 segundos, certo ? A chamada que demorou mais desta função demorou 6.4 segundos.

  • o que o campo D indica? Por que todos os valores vem com 0? (as outras chamadas que omiti também são todas com D 0 no final das linhas)

R: Experimenta ligar o monitoramento de memória do Application Server -- Configuração DebugThreadUsedMemory=1, eu acho que este "D" deveria mostrar a diferença de alocação de memória entre o inicio e o final da execução de uma rotina ou função.

  • Também tive dúvidas em algumas informações do cabeçalho do relatório do profiler:

R: Os campos parecem ser informações da conexão entre o SmartClient e o Application Server -- quantas mensagens foram trocadas durante a execução, trafego total em bytes, e tamanho da maior mensagem.

Você deve fazer log-in para responder a esta pergunta.

Esta não é a resposta que você está procurando? Pesquise outras perguntas com a tag .