Profiling
profile module
The profile module analyses function run-times (SLang Doc). It can be used to analyse/profile the run-time of functions and function-calls within of self-defined functions or functions added to SLang by other modules, i.e., intrinsic SLang functions are excluded.
As the documentary has yet to be continued, here some informations:
- The profile module is loaded with isis> require("profile");
- It adds the following functions: profile_begin, profile_calibrate, profile_end, profile_off, profile_on, profile_report
- Before including/loading any other modules/functions isis> profile_on(); has to be executed!
Example
Under /home/falkner/Public/isis/profile there are example files. In the profile_function.sl there are some definitions of dummy functions, which will be profiled. There are several inner_fncts, which are called by and outer_fnct in different ways to show run-time differences. The profile_example.sl script shows how to actually use the profile module with an basic example. In the end a profile_report.txt is produced, which shows the profile result. In the first column (__#function__) all functions are listed, which where called between "profile_begin" and "profile_end". __ncalls__ represents how often each function was called and __ms/call__ is the corresponding time in milliseconds per call. __totalselfms__/__totalsecs__ is the total time (~ncalls*time/call) in msecs or secs, respectively. Note that the run-time of the outer_fnct is already subtracted by the run-time of its subfunctions! __Function__ gives the number of function calls within this function.
Please note that all inner_fnct are basically calculating the same, but their run-time differs a lot. Avoiding loops and utilize that isis is able to perform array-operations is the fastest. But even if loops cannot be avoided, the choice how to write them can make a big difference. The most time consuming step here is to extend an array by one array-element in each step of the loop.
profile_function.sl
define inner_fnct1( x ){ return sqrt(sin(sqr(x))) mod 10; } define inner_fnct3( x ){ return sqrt(sin(sqr(x))) mod 10; } define inner_fnct4( x ){ return sqrt(sin(sqr(x))) mod 10; } define inner_fnct5( x ){ return sqrt(sin(sqr(x))) mod 10; } define inner_fnct2( x ){ variable y = _typeof(x)[length(x)]; _for $1 ( 0, length(x)-1 ){ y[$1] = sqrt(sin(sqr(x[$1]))) mod 10; } return y; } define outer_fnct(x){ variable y1 = inner_fnct1(x); variable y2 = inner_fnct2(x); variable y3 = Double_Type[0]; foreach $1 ( x ){ y3 = [y3, inner_fnct3($1)]; } variable y4 = Double_Type[length(x)]; _for $1 ( 0, length(x)-1 ){ y4[$1] = inner_fnct4($1); } variable y5 = Double_Type[length(x)]; for( $1=0; $1<length(x); $1++ ){ y5[$1] = inner_fnct5($1); } }
profile_example.sl
%% The profile module has to be included and enabled %% before any other module require("profile"); profile_on(); %% after that other modules and scripts can be loaded require("isisscripts"); ()=evalfile("profile_function.sl"); variable x = [0:1e5]; %% Before calling the funktion you want to profile start the profiling %% The 1 is an optional argument which adds line-by-line profiling profile_begin(1); outer_fnct(x); %% Afterwards the profiling has to be ended and a report can be written: profile_end(); profile_report("profile_report.txt"); %% The profile module can be switch off by: profile_off();
profile_report.txt
#---------------------------------------------------------------- # Function Call Profile Report #---------------------------------------------------------------- #function ncalls ms/call totalselfms totalsecs Function File inner_fnct3 100000 0.0019 185.7670 0.1858 0 0 ./profile_function.sl inner_fnct5 100000 0.0013 129.8830 0.1299 0 0 ./profile_function.sl inner_fnct4 100000 0.0013 127.6480 0.1276 0 0 ./profile_function.sl inner_fnct2 1 74.1160 74.1160 0.0741 0 0 ./profile_function.sl inner_fnct1 1 15.0210 15.0210 0.0150 0 0 ./profile_function.sl outer_fnct 1 0.4360 0.4360 0.0004 300002 0 ./profile_function.sl #---------------------------------------------------------------- # Line by Line Profile Report #---------------------------------------------------------------- #ncalls ms/call totalselfms totalsecs Fcalls Scalls File:line 1 0.44400 0.00800 0.00044 600006 0 ./profile_example.sl:15 1 0.00000 0.00000 0.00000 0 0 ./profile_example.sl:18