I'm trying to benchmark a (SWI-)Prolog program that may take several seconds to finish. I'd like to save CPU-time and memory statistics through time to then be able to show a sort of evolution plot. Something similar to the system monitor, but just with my program.
For that I tried using alarm/4:
stat_start(Id) :-
alarm(0.25,stat_point,Id,[remove(false),install(true)]). % 250 milliseconds
stat_stop(Id) :-
remove_alarm(Id).
stat_point :-
stat_cpu, % calls statistics/2 and appends values to a CSV file
stat_mem. % calls statistics/2 and appends values to a CSV file
I simply can't get proper timing between each stat_point. The timing varies from milliseconds to seconds and I can't do anything about it. And changing alarm/4's time does't make any difference. I also tried a simple query like:
?- alarm(1, write('hello\n'), Id, [remove(false),install(true)]),
repeat,
fail.
And it doesn't work either. I'm just getting a single "hello". I thought that a solution might be to insert calls to stat_point within my code, but it doesn't look rather elegant, does it? Besides, the points wouldn't be equally spaced.
Is there a proper way to monitor a Prolog program in a timed-fashion? Would profile/1 provide this kind of information somehow?
I've come to the conclusion that an alarm can't be configured to fire a predicate periodically, or at least not automatically. Although one of the options in alarm/4 is remove(false), one has to call uninstall_alarm/1 and install_alarm/1 in order to restart the time counter. Not doing so and not calling remove_alarm/1, will produce a resource leak, which will probably be protected somehow and might eventually stop the actual timer.
This would be the proper way to use periodic calls to predicates stat_mem/0 and stat_cpu/0:
stat_start(Id,T) :-
alarm(T,stat_point(Id,T),Id,[remove(false),install(true)]).
stat_point(Id,T) :-
uninstall_alarm(Id),
install_alarm(Id,T),
stat_mem,
stat_cpu.
Note that in this case a call to install_alarm/2 is needed instead of /1. If we don't do that, the time is set to 0 and the alarm will fire the predicate continuously.
Now, more related to the 'determinism' issue of my initial question, I just can say that although my stat_point inserts uncertainty to my time and (less likely) memory measurements, this uncertainty is ultimately determined by the statistics/2 predicate. Since CPU time is affected by this call, the solution suggested by magus --use a "primary standard" sample to find the offset of my measurements-- might be an approach toward reducing this uncertainty.
In fact, since the memory used and execution times were already far greater than those produced by repeated calls to statistics/2 the accuracy of my measurements is "relatively" small.