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_redos. This determines how the output is sorted and what the percent
figure that is printed relates to. For example, if the argument is
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.
show_profile_results/1 is equivalent to
show_profile_results/2 with second argument given a value of 10 and
show_profile_results/0 is equivalent to
show_profile_results/1 with the argument
The following example illustrates the output of
| ?- [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
only 5.3% of the execution time was spent in
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
the profile results are listed
by_time. Callers that do
not register any time are not listed in the output when displayed
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