CODEWITHSUNDEEP
prologdcgsicstus-prolog
repeat
repeat

Reputation: 18726

How can I localize the reasons for excessive goal expansion?

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 !

Upvotes: 3

Views: 144

Answers (1)

Per Mildner
Per Mildner

Reputation: 10487

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.

Upvotes: 4

Related Questions