Subject: Re: bug#76505: 31.0.50; igc: M-x project-compile is slow

From: Pip Cet <[email-masked]>
Date: Sun, 23 Feb 2025 17:51:35 +0000

"Ihor Radchenko" <[email-masked]> writes:

> Pip Cet <[email-masked]> writes:
>
>>> Any suggestions, ideas?
>>
>> Many!  First, may I ask you to save a core file (attach gdb, "gcore",
>> shouldn't destroy the session) somewhere along with the emacs binary and
>> .pdmp file that correspond to it?  That way, if we fix your session we
>> can still figure out why it was broken in the first place.  (Of course,
>> you should nevershare the core file).
>
> Oh. It is not broken. I am writing this very email from the same
> session. It is just that running compilation makes Emacs hang for a few
> seconds. Same when switching magit branches (and also calling external
> process).
>
>> The next step would be to set garbage-collection-messages to t to see
>> whether it's indeed MPS that's to blame.
>
> Here is what I see alongside with Emacs hanging when I run M-x
> project-compile on Org mode git repo. The hang only happens while make
> is spawning many subprocesses to compile individual .el files. Once it
> proceeds to testing (and running a single emacs subprocess) the hangs stop.
>
> Garbage collecting...
> Generation 0 of a chain has reached capacity: start a minor collection.
> Garbage collecting...
> Generation 0 of a chain has reached capacity: start a minor collection.
> Garbage collecting...
> Opportunism: client predicts plenty of idle time, so start full collection.

This seems like an IGC bug for very unusual MPS parameters, which we
use.  (I hesitate to call it an MPS bug, but the documentation could be
clearer here).

The relevant code is ArenaStep in global.c:

Bool ArenaStep(Globals globals, double interval, double multiplier)
{
  Bool workWasDone = FALSE;
  Clock start, intervalEnd, availableEnd, now;

  start = now = ClockNow();
  intervalEnd = start + (Clock)(interval * (double)clocks_per_sec);
  availableEnd = start + (Clock)(interval * multiplier * (double)clocks_per_sec);

  /* loop while there is work to do and time on the clock. */
  do {
    Trace trace;
    if (arena->busyTraces != TraceSetEMPTY) {
      trace = ArenaTrace(arena, (TraceId)0);
      /* falls through */
    } else {
      /* No traces are running: consider collecting the world. */
      if (PolicyShouldCollectWorld(arena, (double)(availableEnd - now), now,
                                   clocks_per_sec))
      {
        Res res;
        res = TraceStartCollectAll(&trace, arena, TraceStartWhyOPPORTUNISM);
        if (res != ResOK)
          break;
        arena->lastWorldCollect = now;
      } else {
        /* Not worth collecting the world; consider starting a trace. */
        Bool worldCollected;
        if (!PolicyStartTrace(&trace, &worldCollected, arena, FALSE))
          break;
      }
    }
    TraceAdvance(trace);
    if (trace->state == TraceFINISHED)
      TraceDestroyFinished(trace);
    workWasDone = TRUE;
    now = ClockNow();
  } while (now < intervalEnd);

  ...
}

We call this code with multiplier = 0.  It looks to me like the lowest
useful value for multiplier is 1.0.

The problem, I think, is that the do { ... } while () loop runs (at
least) twice: the first time, a busy trace finishes, the code falls
through, "now" is reset to the *current* clock, which makes
(availableEnd - now) "negative".  But as the types are both unsigned,
the "negative" value will correspond to a large Clock value, which will
make MPS reach the conclusion it's a good time to start a full
collection.

I think the intention was for "multiplier" in the above code always to
be at least 1.0.  The documentation isn't quite clear on what
"multiplier" is supposed to be set to, particularly in our case where we
want to discourage full collections.  1.0 seems to be the lowest safe
value, so let's use that?

> Opportunism: client predicts plenty of idle time, so start full collection.

Two full collections would cause a significant slow-down, yes.

If you want to continue testing before this is fixed, please consider
setting igc-step-interval to 0 (the fixnum, not the float) or 0.0 (which
has different behavior because we have a do { ... } while (...) loop).

Does that analysis make sense?

Pip