The execution of a goal can be profiled using profile/1, which takes
the goal as its argument. This will turn on the profiler, recording for
each invoked predicate the number of calls, choice points created, redos
tried and the predicate's callers. Counts accumulated from any previous
executions of the profiler will be reset.
The goal is then executed with timing information additionally monitored.
Once the goal has completed execution, the results of the execution profile
can be seen by calling the show_profile_results/2 builtin predicate. The
first argument to show_profile_results/2 is the display mode and is
one of the atoms: by_time, by_calls, by_choice_points or
by_redos. This determines how the output is sorted and what the percent
figure that is printed relates to. For example, if the argument is by_time
then the results are sorted according to the time spent in the predicates (in
descending order) and the percentage figure is the proporation of
total execution time spent executing that predicate.
The second argument gives the number of procedures to show information about,
thus a value of 10 means that the top ten predicates are printed.
The predicate show_profile_results/1 is equivalent to
show_profile_results/2 with second argument given a value of 10 and
similarly show_profile_results/0 is equivalent to
show_profile_results/1 with the argument by_time.
The following example illustrates the output of show_profile_results/2:
| ?- [chat].
% loading file /opt/quintus/generic/q3.5/demo/chat/chat.qof
% chat.qof loaded in module user, 0.620 sec 1,520 bytes
yes
| ?- profile(hi(questions)).
% The profiler is switched on
...
yes
[profile]
| ?- show_profile_results(by_time, 3).
Proc Calls ChPts Redos Time % Caller(proc,cl#,cll#,%)
user:setof/3 227 0 0 2.04 34.0
user:satisfy/1,6,1 152 61.0
user:seto/3,1,1 48 20.0
user:satisfy/1,7,1 27 17.0
user:satisfy/1 35738 36782 14112 0.32 5.3
user:satisfy/1,1,2 13857 43.0
user:satisfy/1,2,1 12137 31.0
user:satisfy/1,1,1 7315 18.0
user:satisfy/1,3,1 1155 6.0
user:inv_map_l/5 4732 4732 3115 0.20 3.3
user:inv_map_l/5,2,1 3115 60.0
user:inv_map/4,5,1 1617 40.0
yes
[profile]
| ?- show_profile_results(by_calls, 3).
Proc Calls ChPts Redos Time % Caller(proc,cl#,cll#,%)
user:satisfy/1 35738 36782 14112 0.32 15.3
user:satisfy/1,1,2 13857 43.0
user:satisfy/1,2,1 12137 31.0
user:satisfy/1,1,1 7315 18.0
user:satisfy/1,3,1 1155 6.0
user:satisfy/1,4,1 1044 0.0
user:holds/2,1,1 3 0.0
user:database/1 13616 0 0 0.06 5.8
user:satisfy/1,14,1 13616 100.0
The output lists the predicate name, the number of calls to that predicate,
number of times a choice point was created, the number of the times the
predicate was retried on backtracking and the time (in seconds) spent
executing that predicate. The percentage figure depends on the display mode.
In the example above 15.3% of the goal calls were to satisfy/1, but
only 5.3% of the execution time was spent in satisfy/1.
Then follows the list of callers, showing for each caller the predicate name and arity, the clause number and the call number within that clause of the call (see mpg-ref-add_spypoint), followed by the number of calls made by this caller and the percentage of execution time attributed to this caller.
Notice in the example that more callers are shown for satisfy/1 when
the profile results are listed by_calls than by_time. Callers that do
not register any time are not listed in the output when displayed by_time.
Callers are omitted in a similar way for other display modes when the relevant
count is zero.
The profiler can be turned off with the noprofile/0 predicate.