How can I localize the reasons for excessive goal expansion?

Question

The execution profiler of SICStus Prolog 4.5.1 gave me the following output:

| ?- print_profile.
       insns   try/retry      called        name
----------------------------------------------------------------
                             4965857/4965857    prolog:wellformed_body_expand/11
   201383839     4965857     4965857        prolog:call_goal_expansion/6
                            *4860319/4860363    prolog:choice/0
                             4860319/9720726    prolog:in_hook_flag/2
                             4860319/9006266    prolog:prolog_catch/3
----------------------------------------------------------------
                             4965868/4965868    prolog:wellformed_body_iso/11
   178771039    19863439     4965868        prolog:wellformed_body_expand/11
                             4965857/4965857    prolog:call_goal_expansion/6
                             4965857/4965857    prolog:goal_exp/8
                             4965857/4965857    prolog:wf_source_module/2
----------------------------------------------------------------
   165399306     5469803     ...
----------------------------------------------------------------
                             3044459/3044459    prolog:dcg_translate_dcg_safe/8
   163441583    23688395     3044459        prolog:dcg_translate_dcg_atom/6
----------------------------------------------------------------
                             ...

Quite puzzling! It seems that 3/4 of all work (column #1 in the table) is due to goal expansion.

But why? How can I localize the code causing all these goal expansions? Please help!

EDIT: New profiling results

@PerMildner's answer and comments pointed the way to resolving the issue. New execution profiling results of magic_square__no_sym(4) (magic squares of size 4x4 with additional constraints between corner points to eliminate symmetric solutions) using library(clpz) look a lot more reasonable:

| ?- print_profile.
       insns   try/retry      called        name
----------------------------------------------------------------
                             1197973/2041757    clpz:fd_put/3
                              843784/2041757    clpz:fd_put/5
   153514528     5339777     2041757        clpz:put_terminating_q/4
                               34012/8145271    clpz:domain_infimum/2
                               34012/8263457    clpz:domain_supremum/2
                                  16/1224480    clpz:new_queue/1
                               51821/51821      clpz:queue_goal_q/2
                              620022/620022     clpz:trigger_props_q/5
----------------------------------------------------------------
                             1197973/1224480    clpz:fd_put/3
                                  16/1224480    clpz:put_terminating_q/4
                               26357/1224480    clpz:trigger_once/1
                                 134/1224480    clpz:variables_same_queue/1
   113876576           0     1224480        clpz:new_queue/1
----------------------------------------------------------------
                             ...

The performance impact of the changes in goal expansion for this case are very impressive: 2X !

Unlike other systems, SICStus goal expansion is also called when updating dynamic predicates at runtime (IIRC). Could that explain the number of calls you observe? — Paulo Moura, Aug 10 '19 at 14:17
@PauloMoura. I ran `| ?- N=4,statistics(runtime,[T0|_]), (magic_square(N,Zss), append(Zss,Zs), labeling([ff],Zs),write(.),false;true), statistics(runtime,[T1|_]), T is T1-T0, write(t=T),nl,!,false.` using `library(clpz)` and the magic square sample code (slightly modified) and a slightly modified version of the library... — repeat, Aug 10 '19 at 14:22
@PauloMoura. Slightly modified for a simple reason. I wanted to see if some of the auxiliary code that the library implementation uses is in fact free with SICStus. E.g., `A = A ==> [].` that `(=)/4` can be handy and improve code readability, but is it (almost) free? — repeat, Aug 10 '19 at 14:24
SICStus tries to be clever when there is no goal expansion that can be applicable. In that case the call to `call_goal_expansion` can often be avoided. However, if there is a goal expansion visible (e.g. by loading `clpz`) and that goal expansion has poor indexing, then the full goal expansion processing is attempted. The latter may be what happens because of the "defaulty" [last clause](https://github.com/triska/clpz/blob/cf8db7e807078a4c0692ae0f9d6b3dd249a4da53/clpz.pl#L3066) of `clpz:goal_expansion/5`. — Per Mildner, Aug 11 '19 at 08:33
@PerMildner. Brilliant! Looking forward to trying that out! Please put your comment in an answer so I can accept/upvote/reward it. Nice link, btw. Very useful! — repeat, Aug 11 '19 at 19:10
@PerMildner. I added cuts at the end of each goal_expansion clause, but so far no luck:( Will retry tomorrey. — repeat, Aug 11 '19 at 21:04

score 4 · Accepted Answer · answered Aug 12 '19 at 20:42

SICStus tries to be clever when there is no goal expansion that can be applicable. In that case the call to call_goal_expansion can often be avoided. However, if there is a goal expansion visible (e.g. by loading clpz) and that goal expansion has poor indexing, then the full goal expansion processing is attempted. The latter may be what happens because of the "defaulty" last clause of clpz:goal_expansion/5.

Note that "poor indexing" cannot be worked around by adding cuts in this case. Internally, SICStus looks into the indexing data structure for the goal_expansion/5 predicate to determine whether any of its clauses could be applicable. A catch-all clause, like the linked one, makes this test fail and the full, slower, call_goal_expansion will be called.

Interesting! How about rewriting (unrolling) that part of the code to individual goal expansion clauses (for `(in)/2`, one for `(#=)/2`, etc.)? (Plus some additional API for retracting these clauses upon library user request...) — repeat, Aug 12 '19 at 20:55
Yes, if the catch-all-clause is really the problem, then replacing it with individual, indexable, clauses, would probably avoid the slow path. That change has to be done in `clpz`, which is not part of SICStus Prolog. — Per Mildner, Aug 13 '19 at 08:03

How can I localize the reasons for excessive goal expansion?

EDIT: New profiling results

1 Answers1