The profiling tool helps to find hot spots in a program that are worth optimising. To use the profiler, start ECLiPSe or TkECLiPSe with the -P command line option (or use the EC_OPTION_WITH_PROFILER via the C interface, or the with_profiler option via the Tcl interface, see D). It is not necessary to compile the profiled code in a special way; this profiler works independently of compiler optimizations and debug mode.
To profile the execution of a particular goal, use profile/1:
?- profile(Goal).
or select the Time Profile option from TkECLiPSe’s Query-menu. The profiler then executes the Goal in the profiling mode, which means that every 100th of a second the execution is interrupted and the profiler records the currently executing procedure. For example
?- profile(queen([1,2,3,4,5,6,7,8,9],Out)).
goal succeeded
PROFILING STATISTICS
--------------------
Goal: queen([1, 2, 3, 4, 5, 6, 7, 8, 9], Out)
Result: success
Sampling rate: every 0.01s process_cputime
Samples taken: 2
Thread cputime: 0.03s
Predicate Module %Time Time %Cum
--------------------------------------------------------
qdelete /4 eclipse 50.0% 0.01s 50.0%
nodiag /3 eclipse 50.0% 0.01s 100.0%
Out = [1, 3, 6, 8, 2, 4, 9, 7, 5]
Yes (0.14s cpu)
The profiler output contains the following information:
Auxiliary system predicates are printed under a common name without arity, e.g., arithmetic or all_solutions. Predicates which are local to locked modules are printed together on a single line that contains only the module name. By default only predicates written in Prolog are profiled, i.e., if a Prolog predicate calls an external or built-in predicate written in C, the time will be assigned to the Prolog predicate.
The predicate profile(Goal, Flags) can be used to change the way profiling is made, Flags is a list of flags. Currently only the flag simple is accepted and it causes separate profiling of simple predicates, i.e., those written in C.
The problem with the results displayed above is that the sampling frequency is too low when compared to the total user time spent executing the goal. In fact in the above example the profiler was only able to take two samples before the goal terminated.
The frequency at which the profiler samples is fixed, so in order to obtain more representative results one should have an auxiliary predicate which calls the goal a number of times, and compile and profile a call to this auxiliary predicate. e.g.,
queen_100 :- (for(_,1,100,1) do queen([1,2,3,4,5,6,7,8,9],_Out)).
Note that, when compiled, the above do/2 loop would be efficiently implemented and not cause overhead that would distort the measurement. Section 5.2 presents a detailed description of logical loops.
?- profile(queen_100).
goal succeeded
PROFILING STATISTICS
--------------------
Goal: queen_100
Result: success
Sampling rate: every 0.01s process_cputime
Samples taken: 319
Thread cputime: 3.19
Predicate Module %Time Time %Cum
--------------------------------------------------------
nodiag /3 eclipse 52.2% 1.67s 52.2%
qdelete /4 eclipse 27.4% 0.87s 79.6%
qperm /2 eclipse 17.0% 0.54s 96.5%
safe /1 eclipse 2.8% 0.09s 99.4%
queen /2 eclipse 0.6% 0.02s 100.0%
Yes (3.33s cpu)
In the above example, the profiler takes over three hundred samples resulting in a more accurate view of where the time is being spent in the program. In this instance we can see that more than half of the time is spent in the nodiag/3 predicate, making it an ideal candidate for optimisation. This is left as an exercise for the reader.
Limitation: in ECLiPSe7.0, only the engine that called profile/1 is profiled.