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