# Understanding profiler

**URL:** <https://swi-prolog.discourse.group/t/understanding-profiler/8582>\
**Category:** General\
**Created:** [November 5, 2024, 2:13pm UTC](https://swi-prolog.discourse.group/t/understanding-profiler/8582 "2024-11-05T14:13:30Z")\
**Posts on this page:** 5\
**Page:** 1

<div class="post-metadata">

**Author:** ![tatut](https://yyz2.discourse-cdn.com/free1/user_avatar/swi-prolog.discourse.group/tatut/32/5300_2.png) [@tatut](https://swi-prolog.discourse.group/u/tatut)\
**Post date:** [November 5, 2024, 2:13pm UTC](https://swi-prolog.discourse.group/t/understanding-profiler/8582/1 "2024-11-05T14:13:31Z")

</div>

I’m making a (toy for now) programming language with DCG based parser and evaluator.  
(code is at [GitHub - tatut/elf-lang: Elf Helper programming language](https://github.com/tatut/elf-lang))

I’m trying to keep the evaluation as free of backtracking as possible. So everything is evaluated once and has 1 possible answer.

I was profiling one program in this language and saw that there were huge amounts of “Redos”.

 ![image](https://global.discourse-cdn.com/free1/uploads/swiprolog/original/2X/1/1ffd404f071f7b5a832912fb3c159fb3dbba5669.png)

I then added fail trace to eval\_methods/5 and saw lots of failures:

```prolog
 T [130 +0.0ms] Fail: elf:eval_methods(9, [], _141646, [...ctx...], _141648)

```

In a part that should always match the first clause:

```prolog
eval_methods(In, [], In) --> [].
eval_methods(In, [M|Methods], Out) -->
    eval_method(In, M, Intermediate),
    { ! }, % commit to this method call result (don't leave choicepoints around)
    eval_methods(Intermediate, Methods, Out).

```

Is there a way to add breakpoint for a clause in the gtrace tool _only_ when the clause fails?  
Or what would be the best way to find out the root cause of a particular failure.

---

<div class="post-metadata">

**Author:** ![tatut](https://yyz2.discourse-cdn.com/free1/user_avatar/swi-prolog.discourse.group/tatut/32/5300_2.png) [@tatut](https://swi-prolog.discourse.group/u/tatut)\
**Post date:** [November 5, 2024, 2:58pm UTC](https://swi-prolog.discourse.group/t/understanding-profiler/8582/3 "2024-11-05T14:58:55Z")

</div>

Thanks, that simple reordering actually sped up little bit.

---

<div class="post-metadata">

**Author:** ![ridgeworks](https://yyz2.discourse-cdn.com/free1/user_avatar/swi-prolog.discourse.group/ridgeworks/32/886_2.png) [@ridgeworks](https://swi-prolog.discourse.group/u/ridgeworks)\
**Post date:** [November 5, 2024, 4:38pm UTC](https://swi-prolog.discourse.group/t/understanding-profiler/8582/4 "2024-11-05T16:38:45Z")

</div>

> [@tatut](#):
>
> I was profiling one program in this language and saw that there were huge amounts of “Redos”.

The default (“classic”) settings of the profiler has some incorrect port counts. Some work was done a while ago to fix this but some of the documentation is still sitting in a PR ([Draft updated doc for profiler by ridgeworks · Pull Request #1144 · SWI-Prolog/swipl-devel · GitHub](https://github.com/SWI-Prolog/swipl-devel/pull/1144)).

In any case, if you want accurate port counts include `ports(true)` in the option list of profile/2 .

---

<div class="post-metadata">

**Author:** ![tatut](https://yyz2.discourse-cdn.com/free1/user_avatar/swi-prolog.discourse.group/tatut/32/5300_2.png) [@tatut](https://swi-prolog.discourse.group/u/tatut)\
**Post date:** [November 5, 2024, 6:02pm UTC](https://swi-prolog.discourse.group/t/understanding-profiler/8582/5 "2024-11-05T18:02:21Z")

</div>

Adding `ports(true)` makes the redos almost completely disappear. I guess it makes sense, looking at that discussion, since the evaluator is very very highly recursive code.

---

<div class="post-metadata">

**Author:** ![jan](https://yyz2.discourse-cdn.com/free1/user_avatar/swi-prolog.discourse.group/jan/32/4_2.png) [@jan](https://swi-prolog.discourse.group/u/jan)\
**Post date:** [November 6, 2024, 9:36am UTC](https://swi-prolog.discourse.group/t/understanding-profiler/8582/6 "2024-11-06T09:36:24Z")

</div>

Although the profiler gives some insight in non-determinism, the primary tool for inspecting (un)wanted non-determinism is the graphical debugger. Put a spy point on the predicate you want to investigate and ‘s’(kip) over it. Now the top-right window shows both the call stack and open choice points. You can click on any of the choice frames to see which clause succeeded and left a choice point.

You can also step through some code and see the choice points come and go. It is typically a good idea to avoid the creation of a choice point (for example by ensuring clause indexing does its job) or get rid of them using `->` or `!` as soon as possible.

SWI-Prolog specific tools for creating deterministic and safe code are the _single sided unification_ (SSU, using `Head => Body`) and the `:- det(name/arity)` declaration. Finally, there is `$/0`, which acts as `!/0`, but also declares that the remainder of the clause must succeed deterministically. These tools raise exceptions if anything does not behave as you had it in mind, making debugging a lot easier.

The profiler notably hints at poor clause indexing. Such predicates will show up with a relatively high percentage of the CPU time for the number of calls. And, of course, it points at expensive built-in predicates. It can also give some hint about garbage costs by (1) showing the percentage of the time in GC while (2), the predicates that invoke GC the most often are the predicates that create most (global stack) data (not necessarily garbage).