Home Contents Index Summary Previous Next

4.41 Execution profiling

This section describes the hierarchical execution profiler introduced in SWI-Prolog 5.1.10. This profiler is based on ideas from gprof described in [graham82gprof]. The profiler consists of two parts: the information-gathering is built into the kernel, (59) and a presentation component which is defined in the library(statistics) library. The latter can be hooked, which is used by the XPCE module library(swi/pce_profile) to provide an interactive graphical representation of results.

4.41.1 Profiling predicates

Currently, the interface is kept compatible with the old profiler. As experience grows, it is likely that the old interface is replaced with one that better reflects the new capabilities. Feel free to examine the internal interfaces and report useful application thereof.

profile(:Goal)
Execute Goal just like time/1, collecting profiling statistics and call show_profile(plain, 25). With XPCE installed this opens a graphical interface to the collected profiling data.

profile(:Goal, +Style, +Number)
Execute Goal just like time/1. Collect profiling statistics and show the top Number procedures on the current output stream (see show_profile/1) using Style. The results are kept in the database until reset_profiler/0 or profile/3 is called and can be displayed again with show_profile/1. The profile/1 predicate is a backward compatibility interface to profile/1. The other predicates in this section are low-level predicates for special cases.

show_profile(+Style, +Number)
Show the collected results of the profiler. It shows the top Number predicates according the percentage CPU-time used. If Style is plain the time spent in the predicates itself is displayed. If Style is cumulative the time spent in its siblings (callees) is added to the predicate.

This predicate first calls prolog:show_profile_hook/2. If XPCE is loaded this hook is used to activate a GUI interface to visialise the profile results.

show_profile(+Number)
Compatibility. Same as show_profile(plain, Number).

profiler(-Old, +New)
Query or change the status of the profiler. The status is a boolean (true or false) stating whether or not the profiler is collecting data. It can be used to enable or disable profiling certain parts of the program.

reset_profiler
Switches the profiler to false and clears all collected statistics.

noprofile(+Name/+Arity, ...)
Declares the predicate Name/Arity to be invisible to the profiler. The time spend in the named predicate is added to the caller and the callees are linked directly to the caller. This is particulary useful for simple meta-predicates such as call/1, ignore/1, catch/3, etc.

4.41.2 Visualizing profiling data

Browsing the annotated call-tree as described in section 4.41.3 itself is not very attractive. Therefore, the results are combined per predicate, collecting all callers and and callees as well as the propagation of time and activations in both directions. Figure 3 illustrates this. The central yellowish line is the `current' predicate with counts for time spent in the predicate (`Self'), time spent in its children (`Siblings'), activations through the call and redo ports. Above that are the callers. Here, the two time fields indicate how much time is spent serving each of the callers. The columns sum to the time in the yellowish line. The caller <recursive> are the number of recursive calls. Below the yellowish lines are the callees, with the time spent in the callee itself for serving the current predicate and the time spent in the callees of the callee ('Siblings'), so the whole time-block adds up to the `Siblings' field of the current predicate. The `Access' fields show how many times the current predicate accesses each of the callees.

The predicates have a menu that allows changing the view of the detail window to the given caller or callee, showing the documentation (if it is a built-in) and/or jumping to the source.

Figure 3 : Execution profiler showing the activity of the predicate chat:inv_map_list/5.

The statistics shown in the report-field of figure 3 show the following information:

4.41.3 Information gathering

While the program executes under the profiler, the system builds a dynamic call-tree. It does this using three hooks from the kernel: one that starts a new goal (profCall), one the tells the system which goal is resumed after an exit (profExit) and one that tells the system which goal is resumed after a fail (i.e. which goal is used to retry (profRedo)). The profCall() function finds or creates the subnode for the argument predicate below the current node, increments the call-count of this link and returns the sub-node which is recorded in the Prolog stack-frame. Choice-points are marked with the current profiling node. profExit() and profRedo() pass the profiling node where execution resumes.

Just using the above algorithm would create a much too big tree due to recursion. For this reason the system performs detection of recursion. In the simplest case, recursive procedures increment the `recursive' count on the current node. Mutual recursion however is not easily detected. For example, call/1 can call a predicate that uses call/1 itself. This can be viewed as a recursive invocation, but this is generally not desirable. Recursion is currently assumed if the same predicate with the same parent appears higher in the call-graph. Early experience with a some arbirary non-trivial programs are promising.

The last part of the profiler collects statistics on the CPU-time used in each node. On systems providing setitimer() with SIGPROF, it `ticks' the current node of the call-tree each time the timer fires. On Windows a MM-timer in a seperate thread checks 100 times per second how much time is spent in the profiled thread and adds this to the current node. See section 4.41.3.1 for details.

4.41.3.1 Profiling in the Windows Implementation

Profiling in the Windows version is similar but, especially on Windows 95/98/ME one should be aware of the implementation. (60) Windows does not provide timers that fire asynchronously, frequent and proportional to the CPU time used by the process. Windows does provide multi-media timers that can run at high frequency. Such timers however run in a seperate thread of execution and they are fired on the wall-clock rather than the amount of CPU time used. The profiler installs such a timer running, for saving CPU time, rather inaccurately at about 100 Hz. Each time it is fired, it determines the millisecons CPU time used by Prolog since the last time it was fired. If this value is non-zero, active predicates are incremented with this value.

On Windows 95/98/ME (DOS-based Windows), there is no possibility to get the CPU-time used by a thread or process. Therefore, on these systems profiling results does not count CPU-time, but elapsed time. For sensible results on these systems, ensure the system has no other active tasks and be aware that I/O operations include the time Prolog is blocked waiting for data.