Display the execution times for each goal of a predicate clause

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

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. Start and Stop are measured in milliseconds, but the last time I used it with SICStus it returned only multiple of 10. 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 2

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/2 succeeds twice and T_ms measures total runtime up to this point.