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:

Ending the profile process

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

Example

# Start the profileSTAT=func ASYRTIMING.START("",1)# The code is now profiled...# End the profileSTAT=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 detailTotal 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_CSTD177 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_CSTD1 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_CSTD167 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_CSTD1 14 ms 0,70 %Gosub GET_T From APSADX_CSTD1 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 WMC0ALOG178 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_CSTD21 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 WMC0ALOGD1 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 WMCNAPSADXP3 4 ms 0,20 %Gosub DECLARE_VAR From WMC0ACTXCACHE174 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 WMLAPSADX2 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_CSTD2 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 ASYRSUB27 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 %