Why does call_with_time_limit/2 fail to interrupt tight repeat loops with frequent I/O?

General
1

Hi all,

I have been benchmarking several rational tree comparison predicates (including Foreign C implementations) by fuzz-testing them against transitivity: generating random terms and searching for counterexamples (X<Y∧Y<Z∧¬(X<Z)).
Initially, I tried the natural idiom using repeat and call_with_time_limit/2:
Prolog

anti_transitivity(Sec, Pred, X, Y, Z) :-
    catch(
        call_with_time_limit(Sec, search_anti_trans(Pred, X, Y, Z)),
        time_limit_exceeded,
        writeln('Timeout.')
    ).

search_anti_trans(Pred, X, Y, Z) :-
    repeat,
    fuzzy(X),
    fuzzy(Y),
    call(Pred, C, X, Y), C = (<),
    fuzzy(Z),
    call(Pred, D, Y, Z), D = (<),
    call(Pred, E, X, Z),
    write(E), flush_output,
    E \== (<).

However, this frequently failed to stop at the time limit and ran away indefinitely, leaving C-c C-c as the only way to interrupt the process. Occasionally, it would also surface an unhandled time_limit_exceeded exception directly at the top level despite the catch/3 wrapper.
I ended up ditching call_with_time_limit/2 and asynchronous signals altogether, switching to an explicit tail-recursive loop with a get_time/1 deadline check:

:- meta_predicate anti_transitivity(+, 3, _, _, _).

anti_transitivity(Sec, Pred, X, Y, Z) :-
    get_time(T0),
    Deadline is T0 + Sec,
    search_anti_trans(Deadline, Pred, X, Y, Z).

search_anti_trans(_Deadline, Pred, X, Y, Z) :-
    fuzzy(X),
    fuzzy(Y),
    call(Pred, C, X, Y), C = (<),
    fuzzy(Z),
    call(Pred, D, Y, Z), D = (<),
    call(Pred, E, X, Z),
    write(E), flush_output,
    E \== (<),
    !.
search_anti_trans(Deadline, Pred, X, Y, Z) :-
    get_time(Now),
    Now < Deadline,
    !,
    search_anti_trans(Deadline, Pred, X, Y, Z).
search_anti_trans(_Deadline, _Pred, _X, _Y, _Z) :-
    nl,
    writeln('No anti-transitive triples found.').

This completely solved the issue and runs 100% reliably across all my candidate predicates:

?- anti_transitivity(10, raw_comp, X, Y, Z).
?- anti_transitivity(1, ft_compare, X, Y, Z).
?- anti_transitivity(2, comp, X, Y, Z).
?- anti_transitivity(2, rt_ord_by_len, X, Y, Z).
?- anti_transitivity(2, prt_compare, X, Y, Z).
?- anti_transitivity(2, fct_compare, X, Y, Z).
?- anti_transitivity(1, pcft_compare, X, Y, Z).
?- anti_transitivity(5, prt_compare, X, Y, Z).
?- anti_transitivity(2, prt_min_compare, X, Y, Z).
?- anti_transitivity(1, mcoa_compare_with_heap, X, Y, Z).

While the explicit loop works cleanly, I am curious:
What prevents call_with_time_limit/2 from reliably interrupting tight backtracking loops involving frequent write/1 + flush_output/0 and foreign predicates?
Is there an idiomatic way to make call_with_time_limit/2 work predictably in such settings without replacing repeat with explicit recursion?

2

I tried

stop :-
    call_with_time_limit(
        5,
        forall(between(1, infinite, X),
               ( format('This is line ~D', [X]),
                 flush_output
               ))).

Using both swipl and swipl-win, on Linux and MacOS. Both stopped nicely. Can you produce something that reproduces and tell us how you run it?

3

I have already rewritten all the counterexample checking code from the repeat-based version to one using get_time/1.

When the time-limit exception occurred with the repeat-based version, the main issue was that I had to kill the Ediprolog process via M-x kill-process and reconsult everything.

Unfortunately, I am not able to construct a minimal reproducible example right now.

4

Pitty. One possible reason is some foreign predicate that does not act on the exception generated by the signal. I couldn’t reproduce this. If such a predicate is involved it should be fixed. Notably e.g., SWISH relies on signals never being ignored. They may be delivered slowly on expensive foreign predicates. Typically such predicates should call PL_handle_signals() regularly and stop their work, returning false if this call returns -1.

5

Hi Jan,

Thank you for the insight regarding PL_handle_signals().

I manually extracted a reproducible example from past commits. The code is somewhat long, and I omitted the intermediate progressive characters from the run output for brevity.

Unfortunately, this snippet only reproduces part of the issue. It might also involve Emacs ediprolog mode. Since I have found a safe workaround using get_time/1, this is not urgent for me anymore, but I am sharing the code and query run below for your reference.


% ?- call_with_time_limit(10, problem_mcoa(X, Y, Z)).
%@ <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
=== skip ==
<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<
%@ ERROR: Unhandled exception: Time limit exceeded
%@ ERROR: Unhandled exception: Time limit exceeded
%@  ?ediprolog- 
%@ Action (h for help) ? Options:
%@ a:           abort         b:           break
%@ c:           continue      e:           exit
%@ g:           goals         s:           C-backtrace
%@ t:           trace         p:		  Show PID
%@ h (?):       help
%@ Action (h for help) ? 
%@ Action (h for help) ? abort
%@ EOF: exit (status 4)

problem_mcoa(X, Y, Z) :-
	repeat,
	fuzzy(X),
	fuzzy(Y),
	mcoa_compare(C, X, Y), C = (<),
	fuzzy(Z),
	mcoa_compare(D, Y, Z), D = (<),
	mcoa_compare(E, X, Z),  write(E), flush_output,
	E = (>).

mcoa_compare(C, X, Y):-
	eqd_minimum_coa([X,Y], [I,J], M),
	mcoa_compare(C, I, J, M, []-[]).

mcoa_compare(C, I, J, M, Hl-Hr):-
		arg(I, M, X),
		arg(J, M, Y),
		(	\+ (compound(X), compound(Y) ) -> compare(C, X, Y)
		;  	count_two_tracks(I, J, Hl-Hr, L-R),
			(  ( L > 0; R>0 ) -> compare(C, L, R)
			;	compare_arity(D, X, Y),
				(	D = (=) ->
					(	I = J -> C = (=)
					; 	mcoa_compare_args(1, C, X, Y, M, [I|Hl]-[J|Hr])
					)
				;	C = D
				)
			)
		).

%
mcoa_compare_args(I, C, X, Y, M, H):-
	arg(I, X, A),
	arg(I, Y, B),
	!,
	mcoa_compare(D, A, B, M, H),
	(	D = (=) ->
		I0 is I + 1,
		mcoa_compare_args(I0, C, X, Y, M, H)
	;	C = D
	).
mcoa_compare_args(_ ,= , _, _, _, _).

eqd_minimum_coa(Xs, Is, Mvec) :-
    eqd_collect_subterms(Xs, [], Ts),
    zip(_, Ts, Dict),
    eqd_term_index(Xs, Is, Dict),
    eqd_dict_to_coa(Dict, Dict, Coa),
    coa_vector(Coa, Mvec).

eqd_collect_subterms(Xs, Ts) :-
    eqd_collect_subterms(Xs, [], Ts).

eqd_collect_subterms([], X, X) :-
    !.
eqd_collect_subterms([A|As], X, Y) :-
    (   eqd_term_member(A, X)
    ->  X1=X
    ;   \+ compound(A)
    ->  X1=[A|X]
    ;   X0=[A|X],
        A=..[_|Bs],
        eqd_collect_subterms(Bs, X0, X1)
    ),
    eqd_collect_subterms(As, X1, Y).

eqd_collect_subterms([], X, X, N, N) :-
    !.
eqd_collect_subterms([A|As], X, X0, N, N0) :-
    (   eqd_indexed_term_member(A, X)
    ->  X1=X,
        N1=N
    ;   \+ compound(A)
    ->  N1 is N+1,
        X1=[N1-A|X]
    ;   N2 is N+1,
        X2=[N2-A|X],
        A=..[_|Bs],
        eqd_collect_subterms(Bs, X2, X1, N2, N1)
    ),
    eqd_collect_subterms(As, X1, X0, N1, N0).

eqd_indexed_term_member(X, [_-Y|_]) :-
    X==Y,
    !.
eqd_indexed_term_member(X, [_|R]) :-
    eqd_indexed_term_member(X, R).

eqd_dict_to_coa([], _, []).
eqd_dict_to_coa([I-T|D0], Dict, [I-T0|Coa]) :-
    (   \+ compound(T)
    ->  T0=T
    ;   T=..[F|As],
        eqd_term_index(As, Is, Dict),
        T0=..[F|Is]
    ),
    eqd_dict_to_coa(D0, Dict, Coa).

zip([], [], []).
zip([A|As], [B|Bs], [A-B|Cs]) :-
    zip(As, Bs, Cs).
6

That is not a problem. This is :frowning:

101 ?- make.
% /home/jan/src/swipl-devel/build/k compiled 0.00 sec, 0 clauses
Warning: The predicates below are not defined. If these are defined
Warning: at runtime using assert/1, use :- dynamic Name/Arity.
Warning: 
Warning: coa_vector/2, which is referenced by
Warning:        /home/jan/src/swipl-devel/build/k.pl:67:4: 1-st clause of eqd_minimum_coa/3
Warning: compare_arity/3, which is referenced by
Warning:        /home/jan/src/swipl-devel/build/k.pl:39:32: 1-st clause of mcoa_compare/5
Warning: count_two_tracks/4, which is referenced by
Warning:        /home/jan/src/swipl-devel/build/k.pl:37:24: 1-st clause of mcoa_compare/5
Warning: eqd_term_index/3, which is referenced by
Warning:        /home/jan/src/swipl-devel/build/k.pl:112:8: 2-nd clause of eqd_dict_to_coa/3
Warning:        /home/jan/src/swipl-devel/build/k.pl:65:4: 1-st clause of eqd_minimum_coa/3
Warning: eqd_term_member/2, which is referenced by
Warning:        /home/jan/src/swipl-devel/build/k.pl:75:8: 2-nd clause of eqd_collect_subterms/3
Warning: fuzzy/1, which is referenced by
Warning:        /home/jan/src/swipl-devel/build/k.pl:21:8: 1-st clause of problem_mcoa/3
Warning:        /home/jan/src/swipl-devel/build/k.pl:22:8: 1-st clause of problem_mcoa/3
Warning:        /home/jan/src/swipl-devel/build/k.pl:24:8: 1-st clause of problem_mcoa/3
true.
7

Sorry for lot of undefined. Add this.

fuzzy(T) :-
	fuzzy([T], T).

fuzzy(L, T) :-
	random(V), N is truncate(V*3),
	(N = 0 -> T = 1;
     N = 1 -> T = s(P,Q), fuzzy([P|L], P), fuzzy([Q|L], Q);
     length(L, M),
     random(W), I is truncate(W*M),
     nth0(I, L, S), S = T).
	
eqd_term_member(A, [B|_]) :-
    A==B,
    !.
eqd_term_member(A, [_|B]) :-
    eqd_term_member(A, B).

count_two_tracks(A, B, C, D) :-
    count_two_tracks(A, B, C, 1, D).

count_two_tracks(_, A, []-B, C, 0-D) :-
    !,
    count_track(A, B, C, D).
count_two_tracks(A, _, B-[], C, D-0) :-
    !,
    count_track(A, B, C, D).
count_two_tracks(A, B, C-D, E, F-G) :-
    C=[H|I],
    D=[J|K],
    (   A=H
    ->  F=E,
        count_track(B, D, E, G)
    ;   B=J
    ->  G=E,
        L is E+1,
        count_track(A, I, L, F)
    ;   L is E+1,
        count_two_tracks(A,
                         B,
                         I-K,
                         L,
                         F-G)
    ).

compare_arity(A, B, C) :-
    functor(B, D, E),
    functor(C, F, G),
    compare(A, E/D, G/F).

coa_vector(A, B) :-
    zip(C, D, A),
    length(C, E),
    numlist(1, E, C),
    B=..[v|D].

eqd_term_index([], [], _).
eqd_term_index([A|As], [J|Is], Dict):-
	member(J-B, Dict),
	A==B,
	!,
	eqd_term_index(As, Is, Dict).
8

One more: ERROR: Unknown procedure: count_track/4. If you run check/0 or make/0, it tells you :slight_smile:

9 
count_track(_, [], _, 0).
count_track(X, [Y|_], K, K):- X = Y, !.
count_track(X, [_|R], K, N):- K0 is K + 1,
	count_track(X, R, K0, N).
10

Tried 1,000 times in a loop, both on Linux and MacOS. All timed out as they should …

11

Thank you for taking the time to test this despite your busy schedule.

I confirmed that call_with_time_limit/2 works properly in a standard terminal (iTerm2). The issue seems specific to my Emacs + ediprolog setup. Since I already have a workable workaround and lack the deep expertise to investigate the Emacs side further, I will leave it at that.

Thanks again for your help.

12

Your iTerm2 result narrows it usefully: a standard terminal interrupts as expected, so the SWI-Prolog timer machinery itself isn’t the suspect. With Emacs + ediprolog, the top-level query goes through the editor’s process handling, so a tight repeat loop that keeps doing I/O can starve the read side or keep output buffered, and the alarm may only be delivered on the next call to the Prolog engine. If you ever revisit it, testing with plain swipl inside Emacs’s own *shell* buffer would separate ediprolog from Emacs itself. The workaround is reasonable in the meantime.

13

Thanks for the insight. I was just trying to build a quick-and-dirty text progress bar, but doing that with write/1 inside Emacs + ediprolog was definitely asking too much of that setup.