Profiling code

Profiling the Sage X3 script code is important to obtain the best possible performance. It localizes time consuming programs and measures how often certain code sections are called. This is possible by using a dedicated library.

Starting the profile process

This is performed by using the function ASYRTIMING.START. This function includes two parameters:

  • A string character value that defines the temporary file name without an extension and path, where the calls and timestamps are written. If an empty value is given, the name will be generated by using the following method:

    • Get the user code in lower case.
    • Get a unique ID linked to the process by using adxuid(1).
    • Build a path in the "tmp" sub-directory from current Sage X3 solution, and create a file called with the two previous segments separated by an underscore, and with a ".tra" extension.
  • An additional integer is set to '0' by default. Its value will be modified to '1' if the code called by Gosub needs to be analyzed.

Ending the profile process

This is performed by using the function ASYRTIMING.STOP. Four parameter must be filled:

  • A pointer on the current context.
  • The temporary file name where the calls and timestamps have been written. If the file name is not provided, the same algorithm will be used to generate it.
  • The same integer value to know if Gosub must be analyzed.
  • A string variable that returns the generated detailed log file.

Example

# Start the profile
STAT=func ASYRTIMING.START("",1)
# The code is now profiled
...
# End the profile
STAT=func ASYRTIMING.STOP(GACTX,"",1,WFICTRACE)
The generated logfile provides a list of Gosub and Calls, the total time spent, the number of calls per element, and the time spent by every element of the list in milliseconds. Finally, it lists the percentage weight of time spent by every element out of the total code profiling time, sorted in descending order. An example is given below:
Timing detail
Total time : 1977 ms -> 0:00:01:977 (hh:mm:ss:000)
Gosub REMPLIT_SYS From APSADX_CSTD                    2 1274 ms  64,44 %
Gosub GET_PARAM_USER From ACTXCACHE_CSTD            167   68 ms   3,43 %
Gosub ACTION From ASYRSUB                           573   61 ms   3,08 %
Gosub _ALOADATTRIBUTE_ID From WMC1APSADX              1   39 ms   1,97 %
Gosub ACTION From ALOG_CSTD                         178   37 ms   1,87 %
Gosub _ADDLINE From ALOG_CSTD                       177   36 ms   1,82 %
Gosub AINFO_INSTANCE From ASYRSUB                   183   28 ms   1,41 %
Gosub _FLUSHLOG From ALOG_CSTD                        4   27 ms   1,36 %
Gosub INC_NUMIMP From ALOG_CSTD                       1   25 ms   1,26 %
Gosub _ADDTRT From WMC0ALOG                           1   22 ms   1,11 %
Call C_ALOGD From @SUPERV.STC/C_ALOGD               177   19 ms   0,96 %
Gosub APUTLINE From ALOG_CSTD                       167   18 ms   0,91 %
Call AREAD From @SUPERV.STC/C_APSADX                  2   17 ms   0,85 %
Gosub CREATE_INSTANCE From ASYRSUB                  183   16 ms   0,80 %
Call GET_PARAM_SUB From ADP_TOOL                      1   15 ms   0,75 %
Gosub SET_NUMERO From WMC1APSADXP                     3   15 ms   0,75 %
Gosub MAJ_NUMIMP From ALOG_CSTD                       1   14 ms   0,70 %
Gosub GET_T From APSADX_CSTD                          1   14 ms   0,70 %
Gosub ACTION From ALOGD_CSTD                        177   14 ms   0,70 %
Gosub ACTION From APSADX_CSTD                        26   13 ms   0,65 %
Gosub _COUPE_TEXTE From ALOG_CSTD                   167   12 ms   0,60 %
Gosub ACTION From WMC0ALOG                          178   12 ms   0,60 %
Gosub ACTION From WMC0ACTXCACHE                     172   10 ms   0,50 %
Gosub GET_PARAM_USER_NUM From WMC0ACTXCACHE         167   10 ms   0,50 %
Gosub ACTION From APSADXP_CSTD                       21   10 ms   0,50 %
Gosub ACTION From WMC0ALOGD                         177   10 ms   0,50 %
Gosub TR_NUMIMP From ALOG_CSTD                        1   10 ms   0,50 %
Gosub _ALNKPRO From WMCNAPSADX                        1   10 ms   0,50 %
Gosub _ADDTRT From WMC0APSADXP                        1   10 ms   0,50 %
Gosub ACTION From ACTXCACHE_CSTD                    172    8 ms   0,40 %
Gosub _ADDTRT From WMC0ALOGD                          1    8 ms   0,40 %
Call GET_PARAM_USER_NUM From @SUPERV.STC/C_ACTXCAC  167    7 ms   0,35 %
Call APUTLINE From @SUPERV.STC/C_ALOG               167    7 ms   0,35 %
Gosub _ADDTRT From WMC0APSADX                         1    6 ms   0,30 %
Call GET_CURFCT From PSADX                            1    5 ms   0,25 %
Gosub APUTLINE From WMC0ALOG                        167    5 ms   0,25 %
Gosub C_ALOGD From WMC0ALOGD                        177    4 ms   0,20 %
Call CONSTRUCTOR From @SUPERV.STC/C_ALOGD           177    4 ms   0,20 %
Gosub DECLARE_VAR From WMC0ALOGD                    177    4 ms   0,20 %
Gosub _ALNKPRO From WMCNAPSADXP                       3    4 ms   0,20 %
Gosub DECLARE_VAR From WMC0ACTXCACHE                174    4 ms   0,20 %
Call GET_PARAM_USER_SUB From ADP_TOOL                 1    3 ms   0,15 %
Call AGETMAXERROR From @SUPERV.STC/C_APSADXP         27    3 ms   0,15 %
Gosub ACTION From WMC0WMACONTEXTAFOLD                 5    2 ms   0,10 %
Call AREAD From WMLAPSADX                             2    2 ms   0,10 %
Call ADELETEERROR From ASYRSUB                        9    2 ms   0,10 %
Gosub _GETFILPATH From ALOG_CSTD                      4    1 ms   0,05 %
Call GET_MODULE_FROM_CHP From AFNC                    1    1 ms   0,05 %
Call GET_SITE_From.mdL From AFNC                      1    1 ms   0,05 %
Gosub AREAD From APSADX_CSTD                          2    1 ms   0,05 %
Gosub PROPAGATE_PROCESS From WMC1APSADXP              3    1 ms   0,05 %
Gosub ABEGINLOG From WMC0ALOG                         1    1 ms   0,05 %
Call GET_CPY_FROM_SITE From ADP_TOOL                  1    1 ms   0,05 %
Call AGETMAXERROR From ASYRSUB                       27    1 ms   0,05 %
Call C_APSADX From @SUPERV.STC/C_APSADX               2    1 ms   0,05 %
Call GET_LEG_FROM_CPY From ADP_TOOL                   1    1 ms   0,05 %
Gosub ACTION From WMC0APSADXP                        21    1 ms   0,05 %