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çãoU_MAKEALLJSON
na linha 310MARMOTA
foi chamado por umCODEBLOCK
que foi definida na linha 4 do arquivoSGEOF011.PRW
STRTRAN
(que é uma função interna) foi chamada em duas linhas distintas da funçãoESCENVST
, 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çãoESCENVST
, 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êntesesC
é a quantidade de chamadas, que é indicada no campo seguinteT
é o tempo total de execução naquele contextoFROM
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 peloLN
)
Em compensação, teve 2 campos que eu não entendi de jeito nenhum:
- o que o campo
M
indica? Por que eu tenho queMARMOTA
tem umM
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 comD 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 ---