Display the execution times for each goal of a pre

Question

I want to see the execution time inside goals of predicate with SICStus Prolog.

Example :

pred :-
   goal1,
   time,
   goal2,
   time.

go :-
   call(pred).

time_go :-
   go,
   times(go).

Expected result:

?- time_go.
times_go = 1000ms ,   
times_go_goal1 = 500ms,
times_go_goal2 = 500ms

How to do that ?

I tried time_out(:Goal, +Time, -Result) from library(timeout) but I got this error:

| ?- time_out(char_code(a,N), T, Res).
! Instantiation error in argument 2 of user:time_out/3
! goal:  time_out(user:char_code(a,_193),_179,_181)

| ?- time_out(char_code(a,N), 1000, Res).
N = 97,
Res = success ? ; % Res=timeout in other example

Answer 1

Since nobody mentioned it, if you only want a time display the time/1 predicate can be also useful. It is already supported by a couple of Prolog systems such as SWI-Prolog, Jekejeke Prolog, O-Prolog, etc...:

Welcome to SWI-Prolog (threaded, 64 bits, version 7.7.19)

?- time((between(1,10000000,_), fail; true)).
% 10,000,001 inferences, 0.453 CPU in 0.468 seconds (97% CPU, 22068968 Lips)
true.

Unfortunately Prolog systems such as GNU Prolog, SICStus Prolog dont support it. But its the analog of the Unix time command, in that it is a meta predicate that takes a goal argument. Better than stone age methods.

Answer 2

You can use statistics/2 for that:

statistics(runtime,[Start|_]),
do_something,
statistics(runtime,[Stop|_]),
Runtime is Stop - Start.

Alternatively, you can use total_runtime instead of runtime if you want to include time for garbage collection. I cannot remember the unit which is used for Start and Stop, but it is quite coarse IIRC. In a project we used calls to a custom external C library to retrieve a finer resolution.

A remark to time_out/3: It is used to limit the runtime of a goal, not to measure its runtime. If the goal finishes in time, the result is success, if it needs more time the execution is aborted (internally a timeout exception is thrown) and the result is timeout.

Answer 3

I'd like to add two thoughts:

1. Prolog allows for backtracking, so goals may succeed more than once.

   What's the "runtime" you are interested in?

   • Only the work for computing the previous answer?
   • Or rather the total time?

2. Use statistics/2, but don't do it directly. Instead, use an abstraction like call_time/2.

Sample query:

?- call_time((permutation([a,b,c,d,e,f,g,h,i],Xs),Xs=[_,_,g,f,e,d,c,b,a]), T_ms).
   Xs = [h, i, g, f, e, d, c, b, a], T_ms = 304
;  Xs = [i, h, g, f, e, d, c, b, a], T_ms = 345
;  false.

Notice that call_time/2succeeds twice and T_ms measures total runtime up to this point.