Recently I asked a question about how to analyze the impact of a code snippet in ADVPL. The big @ follow0984 gave a great answer , and even with my little intimacy with Protheus I was able to link the profiler and get a report.
However, I had difficulty interpreting some of the details of the report. Take this excerpt about function calls:
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
I can state the following:
-
LINHAFAKEwas called by theU_MAKEALLJSONfunction on line 310 -
MARMOTAwas called by aCODEBLOCKthat was defined in line 4 of fileSGEOF011.PRW -
STRTRAN(which is an internal function) was called on two separate lines of theESCENVSTfunction, lines 62 and 63 - There were 210 total calls to
MARMOTA, giving a total time of 87.1 seconds - There were 2755132 total calls to
STRTRAN, of which 1377566 were from line 42 of theESCENVSTfunction, and 1377566 from line 63 of the same function, taking a total of 1.3 seconds over line 62 calls and 1.2 seconds in calls from line 63
How did I interpret this? Well, it was not with the help of the article in TDN. The only thing that talked about profiler analysis in TDN indicated in @ Siga0984's response was this:
Send the console_lentidao.log and console.bak files to support evaluation
So, I went by what seemed more obvious:
-
CALLindicates the function that was called, with the name of the file where it was defined in parentheses -
Cis the number of calls, which is indicated in the next field -
Tis the total execution time in that context -
FROMindicates the various ways in which the calling function is reached, followed by the calling function, the calling function definition file and the line in which the call occurs (indicated byLN)
On the other hand, there were 2 fields that I did not understand at all:
- What does the
Mfield indicate? Why do I have toMARMOTAhave aMof 6,422? - What does the
Dfield indicate? Why does all values come with 0? (the other calls that I omitted are also all withD 0at the end of the lines)
I also had questions about some of the profiler report header information:
[conn_ios_in: 2]
[conn_bytes_in: 200]
[conn_peakbytes_in: 134]
[conn_ios_out: 1]
[conn_bytes_out: 539]
[conn_peakbytes_out: 539]
Does this conn_ios_in indicate what? What about conn_bytes_in ? It does not seem to be about general network traffic because I did 210 HTTP requests on this test.
I was also unable to get relevant information on the application's memory consumption, perhaps because I was not able to read the report. The MEMORY LOG PROFILER section came in blank, empty content.
The full report follows if it is of interest to assist in writing the response:
--- 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 ---