4.43 Finding Performance Bottlenecks

SWI-Prolog offers a statistical program profiler similar to Unix prof(1) for C and some other languages. A profiler is used as an aid to find performance pigs in programs. It provides information on the time spent in the various Prolog predicates.

The profiler is based on the assumption that if we monitor the functions on the execution stack on time intervals not correlated to the program's execution the number of times we find a procedure on the environment stack is a measure of the time spent in this procedure. It is implemented by calling a procedure each time slice Prolog is active. This procedure scans the local stack and either just counts the procedure on top of this stack (plain profiling) or all procedures on the stack (cumulative profiling). To get accurate results each procedure one is interested in should have a reasonable number of counts. Typically a minute runtime will suffice to get a rough overview of the most expensive procedures.

4.43.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. (43) 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.

4.43.2 Profiling predicates

profile(+Goal, +Style, +Number)

Execute Goal just like time/1. Collect profiling statistics according to style (see profiler/2) and show the top Number procedures on the current output stream (see show_profile/1). 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. profile/3 is the normal way to invoke the profiler. The predicates below are low-level predicates that can be used for special cases.

show_profile(+Number)

Show the collected results of the profiler. Stops the profiler first to avoid interference from show_profile/1. It shows the top Number predicates according the percentage CPU-time used. (44)

profiler(-Old, +New)

Query or change the status of the profiler. The status is one of off, plain or cumulative. plain implies the time used by children of a predicate is not added to the time of the predicate. For status cumulative the time of children is added (except for recursive calls). Cumulative profiling implies the stack is scanned up to the top on each time slice to find all active predicates. This implies the overhead grows with the number of active frames on the stack. Cumulative profiling starts debugging mode to disable tail recursion optimisation, which would otherwise remove the necessary parent environments. Switching status from plain to cumulative resets the profiler. Switching to and from status off does not reset the collected statistics, thus allowing to suspend profiling for certain parts of the program.

reset_profiler

Switches the profiler to off and clears all collected statistics.

profile_count(+Head, -Calls, -Promilage)

Obtain profile statistics of the predicate specified by Head. Head is an atom for predicates with arity 0 or a term with the same name and arity as the predicate required (see current_predicate/2). Calls is unified with the number of `calls' and `redos' while the profiler was active. Promilage is unified with the relative number of counts the predicate was active (cumulative) or on top of the stack (plain). Promilage is an integer between 0 and 1000.