Weber: Created page with " Category:Isis / Slang ====== profile module ====== The '''profile''' module analyses function run-times ([http://www.jedsoft.org/slang/doc/html/slang-21.html SLang Doc]..."

2018-04-11T15:00:40Z

Created page with " Category:Isis / Slang ====== profile module ====== The '''profile''' module analyses function run-times ([http://www.jedsoft.org/slang/doc/html/slang-21.html SLang Doc]..."

New page

[[Category:Isis / Slang]]
====== profile module ======

The '''profile''' module analyses function run-times ([http://www.jedsoft.org/slang/doc/html/slang-21.html 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_fnct''s, 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'''
<pre>
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);
}
}
</pre>

'''profile_example.sl'''
<pre>
%% 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();
</pre>

'''profile_report.txt'''
<pre>
#----------------------------------------------------------------
# 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
</pre>

Profiling - Revision history

Weber: Created page with " Category:Isis / Slang ====== profile module ====== The '''profile''' module analyses function run-times ([http://www.jedsoft.org/slang/doc/html/slang-21.html SLang Doc]..."