8.16 Execution Profiling

Execution profiling is a common aid for improving software performance. The SICStus Prolog compiler has the capability of instrumenting compiled code with counters, which are initially zero and incremented whenever the flow of control passes a given point in the compiled code. This way the number of calls, backtracks, choicepoints created, etc., can be counted for the instrumented predicates, and an estimate of the time spent in individual clauses and disjuncts can be calculated.

Gauge is a graphical user interface for inspecting execution profiles. It is available as a library module (see Gauge).

The original version of the profiling package was written by M.M. Gorlick and C.F. Kesselman at the Aerospace Corporation [Gorlick & Kesselman 87].

Only compiled code can be instrumented. To get an execution profile of a program, the compiler must first be told to produce instrumented code. This is done by issuing the query:

     | ?- prolog_flag(compiling,_,profiledcode).

after which the program to be analyzed can be compiled as usual. Any new compiled code will be instrumented while the compiling Prolog flag has the value profiledcode.

The profiling data is generated by simply running the program. The predicate profile_data/4 (see below) makes available a selection of the data as a Prolog term. The predicate profile_reset/1 zeroes the profiling counters for a selection of the currently instrumented predicates.

profile_data(:Spec,?Selection,?Resolution,-Data) development

Data is profiling data collected from the predicates covered by the generalized predicate spec Spec.

The Selection argument determines the kind of profiling data to be collected. If uninstantiated, the predicate will backtrack over its possible values, which are:

calls

All instances of entering a clause by a procedure call are counted. This is equivalent to counting all procedure calls that have not been determined to fail by indexing on the first argument.

backtracks

All instances of entering a clause by backtracking are counted.

choice_points

All instances of creating a choicepoint are counted. This occurs, roughly, when the implementation determines that there are more than one possibly matching clauses for a procedure call, and when a disjunction is entered.

shallow_fails

Failures in the “if” part of if-then-else statements, and in the “guard” part of guarded clauses, are counted as shallow failures. See Conditionals and Disjunction.

deep_fails

Any failures that do not classify as shallow as above are counted as deep failures. The reason for distinguishing shallow and deep failures is that the former are considerably cheaper to execute than the latter.

execution_time

The execution time for the selected predicates, clauses, or disjuncts is estimated in artificial units.

The Resolution argument determines the level of resolution of the profiling data to be collected. If uninstantiated, the predicate will backtrack over its possible values, which are:

predicate

Data is a list of Module:PredName-Count, where Count is a sum of the corresponding counts per clause.

clause

Data is a list of Module:ClauseName-Count, where Count includes counts for any disjunctions occurring inside that clause. Note, however, that the selections calls and backtracks do not include counts for disjunctions.

all

Data is a list of Module:InternalName-Count. This is the finest resolution level, counting individual clauses and disjuncts.

Above, PredName is a predicate spec, ClauseName is a compound term PredName/ClauseNumber, and InternalName is either
ClauseName—corresponding to a clause, or
(ClauseName-DisjNo)/Arity/AltNo—corresponding to a disjunct.

profile_reset(:Spec) development

Zeroes all counters for predicates covered by the generalized predicate spec Spec.