How do you read the ADVPL profiler report?

2

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:

  • LINHAFAKE was called by the U_MAKEALLJSON function on line 310
  • MARMOTA was called by a CODEBLOCK that was defined in line 4 of file SGEOF011.PRW
  • STRTRAN (which is an internal function) was called on two separate lines of the ESCENVST function, 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 the ESCENVST function, 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:

  • CALL indicates the function that was called, with the name of the file where it was defined in parentheses
  • C is the number of calls, which is indicated in the next field
  • T is the total execution time in that context
  • FROM indicates 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 by LN )

On the other hand, there were 2 fields that I did not understand at all:

  • What does the M field indicate? Why do I have to MARMOTA have a M of 6,422?
  • What does the D field indicate? Why does all values come with 0? (the other calls that I omitted are also all with D 0 at 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 ---
    
asked by anonymous 29.11.2018 / 22:07

1 answer

3
  • What does the M field indicate? Why do I have that MARMOTA has an M of 6.422?

R: M indicates the time of the longest call. For example, the MARMOTA function was called 210 times, consuming a total time of 87.1 seconds, right? The call that took more of this function took 6.4 seconds.

  • What does the D field indicate? Why does all values come with 0? (at other calls that I omitted are also all with D 0 at the end of the lines)

R: Try to turn on Application Server memory monitoring - Configuration DebugThreadUsedMemory=1 , I think this "D" should show memory allocation difference between the beginning and end of the execution of a routine or function.

  • I also had questions on some information in the report header of the profiler:

R: The fields appear to be information about the connection between SmartClient and Application Server - how many messages were exchanged during execution, total traffic in bytes, and size of the largest message.

    
04.12.2018 / 20:49