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 %