Manual: The Profiler

Quintus Prolog Manual

(PREV) (NEXT)

E-5: The Profiler

The profiling facility makes it possible to analyse the execution of a program and determine where most time was spent, possibly revealing sources of inefficiently. As well as time spent, the profiler maintains information on number of calls, choice points and redos for each predicate. It also records the callers of each predicate, thus building an extensive execution profile.

Note that the profiler shares some low level internal resources with the debugger in the development system and therefore debugging is disallowed when profiling and vice versa.

E-5-1: Use of the Profiler

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.4/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 section L-3-18), 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.

E-5-2: Customized Output

The predicate get_profile_results/4 returns the profiling information as a list of terms, to enable the customized display of profiling results. The first two arguments of get_profile_results/4 are the same as for show_profile_results/2, the third argument returns a list of proc/6 terms described below and the final argument returns a total that depends on the display mode given by the first argument -- for example, if the display mode is by_time then this is the total execution time.

The proc/6 term proc(Name,Ncalls,Nchpts,Nredos,Time,Callers) gives profiling information about one profiled predicate, where Name gives the module, name and arity of the predicate; Ncalls,Nchpts,Nredos,Time give call, choice point and redo counts and the execution time in milliseconds. The Callers argument is a list of calledby/5 terms of the form calledby(Time,Calls,Name,ClauseNo,CallNo) where Time is the percentage of time attributed to this caller, Calls is the number of calls made by this caller and Name,ClauseNo,CallNo identify the actual caller. For example: 


| ?- get_profile_results(by_time,3,List,Total).

List = [proc(user:setof/3,227,0,0,1980,
                        [calledby(61,152,user:satisfy/1,6,1),
                         calledby(20,27,user:satisfy/1,7,1),
                         calledby(18,48,user:seto/3,1,1)]),
        proc(user:satisfy/1,35738,36782,14112,260,
                        [calledby(69,13857,user:satisfy/1,1,2),
                         calledby(15,12137,user:satisfy/1,2,1)]),
        proc(user:write/1,2814,0,0,240,
                        [calledby(33,481,user:reply/1,3,1),
                         calledby(25,608,user:replies/1,3,1),
                         calledby(16,562,user:out/1,2,1),
                         calledby(8,203,user:reply/1,2,5),
                         calledby(8,34,user:replies/1,2,3)])],
Total = 6040

[profile]
| ?-

E-5-3: Performance

There is a performance penalty of about 20% associated with running a program in profile mode. Data structures needed to maintain profiling information are created on demand the first time a profiled goal is called, so this may affect first-run statistics if the run is relatively short. In this case you may wish to profile the same goal at least a second time to verify the results.

E-5-4: Summary of Predicates



     profile/0                                                       profile/1                                                       noprofile/0
     show_profile_results/0                                          show_profile_results/1
     show_profile_results/2                                          get_profile_results/4

F: Glossary

F-1: Glossary

abolish
To abolish a predicate is to retract all the predicate's clauses and to remove all information about it from the Prolog system, to make it as if that predicate had never existed. Built-in predicates cannot be abolished, but user-defined ones always can be, even when static.
alphanumeric
An alphanumeric character is any of the lowercase characters from 'a' to 'z', the uppercase characters from 'A' to 'Z', or the numerals from '0' to '9'.
ancestors
An ancestor of a goal is any goal which the system is trying to solve when it calls that goal. The most distant ancestor is the goal which was typed at the top-level prompt.
anonymous
An anonymous variable is one which has no unique name, and whose value is therefore inaccessible. An anonymous variable is denoted by an underscore (_).
argument
See predicate, structure, and arity.
arity
The arity of a structure is its number of arguments. For example, the structure 'customer(jones, 85)' has an arity of 2.
atom
A character sequence used to uniquely denote some entity in the problem domain. A number is not an atom. Examples of legal atoms are:

                    hello   *   '#$%'   'New York'   'don''t'
NOTE: An atom may not start with a capital letter or underscore unless that atom is enclosed in single quotes. Character sequences that include spaces must also be enclosed in single quotes. To include a single quote in an atom, print it twice in succession for each single quote which is to appear. See the section G-1-1-3 for a complete definition of an atom.
atomic term
Synonym for simple term or constant.
backtracking
The process of reviewing the goals that have been satisfied and attempting to resatisfy these goals by finding alternative solutions.
binding
The process of assigning a value to a variable; used in unification.
body
The body of a clause consists of the part of a Prolog clause following the ':- ' symbol.
buffer
A temporary workspace in Emacs that contains a file being edited.
built-in predicate
A predicate that comes with the system and which does not have to be explicitly consulted or compiled before it is used.
clauses
A fact or a rule. A rule comprises a head and a body. A fact consists of a head only, and is equivalent to a rule with the body 'true.'.
command
An instruction for the Prolog system to perform an action involving side-effects. If the command is written preceded by a ' :- ', it will be executed as a directive.
compile
Load a program (or a portion thereof) into Prolog through the compiler. Compiled code runs more quickly than interpreted code, but you cannot debug compiled code in as much detail as interpreted code.
compound terms
See structure.
connective
a logical term, or a symbol thereof, that relates components in such a way that the truth or falsity of the resulting statement is determined by the truth or falsity of the components. For example,

                    :-     ;     ,
stand for the connectives 'if', 'or', and 'and'.
constants
An integer (for example: 1, 20, -10), a floating-point number (for example: 12.35), or an atom (for example: 'New York'). Constants are also known as simple terms, and are recognized by the Prolog predicate atomic/1.
consult
Load a program (or a portion thereof) into Prolog through the interpreter. Interpreted code runs more slowly than compiled code, but you can debug interpreted code in more detail than compiled code.
creep
What the debugger does in trace mode, also known as single-stepping. It goes to the next port of a procedure box and prints the goal, then prompts you for input. See Chapter E-1.
cross-reference
A notation in the text of the manual, pointing to another section of the manual containing related information. In the on-line manual, these are of the form {manual(SectionNumber)}, as in "see {manual(B-4-2)}." Typing the text between the braces into the Prolog system will cause the text of the referenced section to be displayed.
cursor
The point on the screen at which typed characters appear. This is usually highlighted by a line or rectangle the size of one space, which may or may not blink.
cut
Written as '!'. A built-in predicate that succeeds when encountered; if backtracking should later return to the cut, the goal that matched the head of the clause containing the cut fails immediately.
database
The Prolog data base comprises all of the clauses which have been loaded into the Prolog system via compile/1, consult/1, or which have been asserted, excepting those clauses which have been removed by retract/1 or abolish/[1,2]
debug
A mode of program execution in which the debugger stops to print the current goal only at procedures which have spypoints set on them (see trace).
determinate
A procedure is determinate if it can supply only one answer.
directives
A directive is a command preceded by the prefix operator ':- ', whose intuitive meaning is "execute this as a command, but do not print out any variable bindings."
disjunction
A series of goals connected by the connective "or" (that is, a series of goals whose principal operator is '|' or ';').
dynamic predicate
A predicate that can be modified while a program is running. A predicate must explicitly be declared to be dynamic or it must be added to the data base via one of the assertion predicates.
export
A module exports a procedure by making that procedure public, so that other modules can import it.
fact
(Also called a unit clause.) A clause with no conditions -- that is, with an empty body. A fact is a statement that a relationship exists between its arguments. Some examples, with possible interpretations, are:

            king(louis, france).   % Louis was king of France.
            have_beaks(birds).     % Birds have beaks.
            employee(nancy, data_processing, 55000).
                                 % Nancy is an employee in the
                                 % data processing department.
first-order logic
A system of logic in which the values of variables may range over the data items in the domain. In Prolog these data items are terms. For comparison, in zero-order logic (also known as propositional logic) there are no variables, and in second-order logic the values of variables are allowed to range both over data items and over functions and relations.
functors
The name and arity of a structure. For example, the structure 'foo(a, b)' is said to have "the functor foo of arity two", which is generally written foo/2.
garbage collection
The freeing up of space for computation by making the space occupied by terms which are no longer available for use by the Prolog system.
goals
A procedure call. When called, it will either succeed or fail. A goal typed at the top level is called a query.
head
The head of a clause is the single goal which will be satisfied if the conditions in the body (if any) are true; the part of a rule before the ':- ' symbol. The head of a list is the first element of the list.
Horn clause
See clause.
import
Public procedures in a module can be imported by other modules. Once a procedure has been imported by a module, it can be called as if it were defined in that module. There are two kinds of importation: procedure-importation, in which only specified procedures are imported from a module; and module-importation, in which all the predicates made public by a module are imported.
instantiation
A variable is instantiated if it is bound to a non-variable term; that is, to an atomic term (see constant) or a compound term.
interpret
Load a program or set of clauses into Prolog through the interpreter (also known as consulting). Interpreted code runs much more slowly than compiled code, but more extensive facilities are available for debugging interpreted code.
leap
What the debugger does in debug mode. The debugger shows only the ports of procedures that have spypoints on them. It then prompts you for input, at which time you may leap again to the next spypoint. See section E-1-3-2.
leashing
Determines how frequently the debugger will stop and prompt you for input when you are tracing. A port at which the debugger stops is called a "leashed port."
list
A list is written as a set of zero or more terms between square brackets. If there are no terms in a list, it is said to be empty, and is written as []. In this first set of examples, all members of each list are explicitly stated.

                    [aa, bb,cc]  [X, Y]  [Name]  [[x, y], z]
In the second set of examples, only the first several members of each list are explicitly stated, while the rest of the list is represented by a variable on the right-hand side of the "rest of" operator, '|':

                    [X | Y]  [a, b, c | Y]  [[x, y] | Rest]
'|' is also known as the "list constructor." The first element of the list to the left of '|' is called the head of the list. The rest of the list, including the variable following '|' (which represents a list of any length), is called the tail of the list. For example,

                    list              head        tail
                    [X | Y]           X           Y
                    [a, b, c | y]     a           [b, c | y]
                    [[X, Y] | Rest]   [X, Y]      Rest
load
To compile or consult a Prolog clause or set of clauses.

meta-predicates
A meta-predicate is one which calls one or more of its arguments; more generally, any predicate which needs to assume some module in order to operate is called a meta-predicate. A meta-predicate declaration is a term in a module-file which is associated with a given functor, sharing its name and arity, but having each of its arguments replaced either by one of the mode annotations '+', '-', '*', '+-', '+*', or by ':' or a non-negative integer. ':' or a non-negative integer signifies that the corresponding argument requires module name expansion.
mode line
The information line at the bottom of each Emacs window that is one line long and the width of the screen; often shown in reverse video. The mode line at the bottom of the Prolog window says "Quintus Prolog" plus other information such as the state of the debugger if it is activated. The mode line of the text window(s) states the buffername, the filename, the editor mode ("Prolog" for a file ending in '.pl'), and the percentage of the file that precedes the cursor.
module
A module is a set of procedures in a module-file. Some procedures in a module are public. The default module is 'user'.
module-files
A module-file is a file that is headed with a module declaration of the form

                    :- module(ModuleName, PublicPredList).
which must appear as the first term in the file.
multifile predicate
A predicate whose definition is to be spread over more than one file. Such a predicate must be preceded by an explicit multifile declaration in the first file containing clauses for it.
name clash
A name clash occurs when a module attempts to define or import a procedure that it has already defined or imported.
object code
The machine-executable, as opposed to the human-readable, representation of a program.
operator
A notational convenience that allows you to express any compound term in a different format. For example, if "likes" in

                    | ?- likes(sue, cider).
is declared an infix operator, the query above could be written:

                    | ?- sue likes cider.
An operator does not have to be associated with a predicate. However, certain built-in predicates are declared as operators. For example,

                    | ?- =..(X, Y).
can be written as
                    | ?- X =.. Y.
because '=..' has been declared an infix operator. Those predicates which correspond to built-in operators are written using infix notation in the list of built-in predicates at the beginning of the part that contains the reference pages. Some built-in operators do not correspond to built-in predicates; for example, arithmetic operators. Chapter G-1-4-4 contains a list of built-in operators.
parent
The parent of the current goal is a goal which, in its attempt to obtain a successful solution to itself, is calling the current goal.
port
One of the four key points of interest in the execution of a Prolog procedure. There are four ports: the Call port, representing the initial invocation of the procedure; the Exit Port, representing a successful return from the procedure; the Redo port, representing reinvocation of the procedure through backtracking; and the Fail port, representing an unsuccessful return due to the failure of the initial goal of the procedure.
precedence
A number associated with each Prolog operator, which is used to disambiguate the structure of the term represented by an expression containing a number of operators. Operators of lower precedence are applied before those of higher precedence; the operator with the highest precedence is considered the principal functor of the expression. To disambiguate operators of the same precedence, the associativity type is also necessary. See the syntax chapter (section G-1).
predicates
A functor that specifies some relationship existing in the problem domain. For example, '<'/2 is a built-in predicate specifying the relationship of one number being less than another. In contrast, the functor '+'/2 is not (normally used as) a predicate. A predicate is either built-in or is implemented by a procedure.
procedure
A set of clauses in which the head of each clause has the same predicate. For instance, a group of clauses of the following form:

connects(san_francisco, oakland, bart_train).
connects(san_francisco, fremont, bart_train).
connects(concord, daly_city, bart_train).
is identified as belonging to the procedure connects/3.
program
A set of procedures designed to perform a given task.
public
A procedure in a module is public if it can be imported by other modules. The public predicates of a module are listed in the module declaration (see module-file).
QOF files
a fully general way of storing arbitrary Prolog facts and rules in a form that can be quickly and easily used. QOF files contain a machine independent representation of both compiled and dynamic Prolog predicates. This means they are completely portable between different platforms running Quintus Prolog.
query
-- simple query: A query is a question put by the user to the Prolog system. A simple query is written as a goal followed by a full-stop in response to the Prolog system prompt. For example,

                    | ?- father(edward, ralph).
refers to the predicate father/2. If a query has no variables in it, the system will respond either "yes" or "no." If a query contains variables, the system will try to find values of those variables for which the query is true. For example,

                    | ?- father(edward, X).
                    X = ralph
After the system has found one answer, the user can direct the system to look for additional answers to the query by typing ";". -- compound query: A compound query consists of two or more simple queries connected by commas. For a compound query to be true, all of its goals must be true simultaneously. For example, the following compound query will find Ralph's grandfather (G):

                    | ?- father(G, F), father(F, ralph).
F is a shared variable which is constrained by unification to have the same value in each of the two subgoals.
recursion
The process in which a running procedure calls itself, presumably with different arguments and for the purpose of solving some subset of the original problem.
region
The text between the cursor and a previously-set mark in an Emacs buffer.
rule
A clause with one or more conditions. For a rule to be true, all of its conditions must also be true. For example,

                    has_stiff_neck(ralph) :-
                       hacker(ralph).
This rule states that if the individual "ralph" is a hacker, then he must also have a stiff neck. The constant "ralph" is replaced in

                    has_stiff_neck(X) :-
                       hacker(X).
by the variable X. X unifies with anything, so this rule can be used to prove that any hacker has a stiff neck.
saved-states
A snapshot of the state of Prolog saved in a file by save_program/1, save_modules/2, or save_predicates/2. save_program/1 saves the whole Prolog data base, save_modules/2 and save_predicates save a list of modules and predicates respectively.
semantics
The relation between the set of Prolog symbols and their combinations (as Prolog terms and clauses), and their meanings. Compare syntax.
side-effects
A predicate which produces a side-effect is one which has any effect on the "outside world" (the user's terminal, a file, etc.), or which changes the Prolog data base.
simple term
see constant.
source code
The human-readable, as opposed to the machine-executable, representation of a program.
spypoints
A flag placed on a predicate by the command spy/1 and removed by nospy/1 that tells the debugger to stop execution and allow user interaction at goals for that predicate. Any number of predicates can have spypoints set on them.
static predicate
A predicate that can be modified only by being reloaded via the consult or compile facility or by being abolished. (See dynamic predicate.)
stream
An input/output channel.
structures
(Also called a compound term.) A structure is a functor together with zero or more arguments. For example, in the structure

                    father(X)
father/1 is the functor, and X is the first and only argument. The argument to a structure can be another structure, as in

                    father(father(X))
syntax
The part of Prolog grammar dealing with the way in which symbols are put together to form legal Prolog terms. Compare semantics.
term
A basic data object in Prolog. A term can be a constant, a variable, or a structure.
trace
A mode of program execution in which the debugger single-steps to the next port and prints the goal.
unbound
A variable is unbound if it has not yet been instantiated.
unification
The process of matching a goal with the head of a clause during the evaluation of a query, or of matching arbitrary terms with one another during program execution. A goal unifies with the head of a clause if 1) they have the same functor, and 2) all of the argument terms can be unified. The rules governing the unification of terms are:
unit clause
See fact.
variable
Logical variable. A logical variable is a name that stands for objects that may or may not be determined at a specific point in a Prolog program. When the object for which the variable stands is determined in the Prolog program, the variable becomes instantiated (see instantiation). A logical variable may be unified (see unification) with a constant, a structure, or another variable. Variables become uninstantiated when the procedure they occur in backtracks (see backtracking) past the point at which they were instantiated. A variable is written as a single word (with no intervening spaces) beginning either with a capital letter without quotes, or with the character "_". Examples:

            X   Y   Z   Name   Position   _c   _305  One_stop
volatile
Predicate property. The clauses of a volatile predicate are not saved by in QOF files by the Prolog 'save' predicates. However, they are saved by qpc.
window
Under the Emacs interface, a region of the terminal screen. There are two types of window: the Prolog window, of which there is exactly one, and the the text window, of which there are one or more. Each window has a mode line at the bottom, and each text window displays the contents of one file.

G: The Prolog Language

Copyright (C) 1998 SICS
contact: product support sales information