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 that 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 some 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, adding the CPU (or wall) time
elapsed since the previous tick in nanoseconds. On Windows, a MM-timer
in a separate 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.42.3.1 for details.
Using the option exact(true), profile/2
does not sample, but reads a clock each time execution moves to another
node of the call tree and adds the elapsed wall time to the node that
was left. The time spent updating the call tree is reported as
accounting time. This gives exact timings, also for short running goals
and predicates that are called often but run briefly. It uses the
processor's timestamp counter if this is available (the invariant TSC on
x86 or the virtual counter on ARM64) and the operating system's
monotonic clock otherwise.
Reading the CPU time of a thread is too slow to do at every node
switch. For CPU time, the exact mode therefore reads the thread's CPU
time once per sample period, as well as after each interval longer than
10 microseconds. A thread can only spend significant time off the CPU,
e.g., blocked in I/O or sleep/1,
inside a single long interval. The short intervals are considered to
have run on the CPU and the long interval is charged the remaining CPU
time used in the period.
By default (Prolog flag profile_exact is auto),
profile/2
uses exact timing if reading the clock is cheap and, for CPU time, the
thread CPU time can be read precisely. This is typically not the case in
virtual machines, where reading the timestamp counter may trap into the
hypervisor. In that case profile/2
uses sampling.
Profiling in the Windows version is similar, but as profiling is a
statistical process it is good to be aware of the implementation166We
hereby acknowledge Lionel Fourquaux, who suggested the design described
here after a newsnet enquiry. for proper interpretation of
the results.
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 separate 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 CPU time in
milliseconds used by Prolog since the last time it was fired. If this
value is non-zero, active predicates are incremented with this value.
