How do you read the ADVPL profiler report?

Question

How do you read the ADVPL profiler report?

Asked 6 years, 11 months ago

Viewed 775 times

3

I recently asked a question about how to analyze the impact of a chunk of code on ADVPL. The big @siga0984 gave a great answer, and even with my little intimacy with Protheus I managed to connect the profiler and get a report.

However, I had difficulty interpreting some details of the report. Take this excerpt about the 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 function U_MAKEALLJSON on line 310
MARMOTA was called by a CODEBLOCK which was defined on line 4 of the file SGEOF011.PRW
STRTRAN (which is an internal function) was called in two distinct lines of the function ESCENVST, 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, where 1377566 were from function line 42 ESCENVST, and line 63 1377566 of the same function, taking a total of 1.3 seconds on line 62 and 1.2 seconds on line 63 calls

How did I get that? Well, it wasn’t with the help of the article on TDN. The only thing that talked about profiler analysis in TDN indicated in the @siga0984 response was the following:

Send the files console_lentidao.log and console.Bak to support evaluate

So I went for what seemed most 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 following field
T is the total running time in that context
FROM indicates the various ways in which the called function is reached, then followed by the calling function, the defining file of the calling function and the line in which the call occurs (indicated by LN)

On the other hand, there were two fields that I didn’t understand at all:

what the field M indicates? Why do I have to MARMOTA has a M of 6.422?
what the field D indicates? Why all values come with 0? (the other calls I omitted are also all with D 0 at the end of the lines)

I also had doubts in some information header of the profiler report:

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

That one conn_ios_in indicates what? And this conn_bytes_in? It doesn’t seem to be about general network traffic, because I made 210 HTTP requests in this test.

Also I could not obtain relevant information from the application’s memory consumption, perhaps because I could not read the report. The section MEMORY LOG PROFILER came blank, empty of content.

The full report follows below, if it is of interest to help in writing the reply:

--- 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 answer

Browser other questions tagged performance advpl

You are not signed in. Login or sign up in order to post.

by siga0984 • **649** points · Answer 1 · 2018-12-04T19:49:33+00:00

what the field M indicates? Why I have that GROUNDHOG has an M of 6.422?

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

what the field D indicates? Why all values come with 0? (as other calls I omitted are also all with D 0 at the end of lines)

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

I also had doubts about some information in the header of the report of the profiler:

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