gcAndFinalize might be insufficient on Node.js in test-transcript.js

[warner]

While testing GC (so after #3109 lands), I found that test-transcript.js sometimes fails. The symptoms suggest that my gcAndFinalize() is insufficient to provoke enough GC in some circumstances.

To reproduce, land #3109, then modify test-transcript.js to remove the c.dump().gcActions.length check in the buildTrace while loop. Checking both runQueue.length and gcActions.length is the correct thing to do. The original code (which exhibited the bug) only checked runQueue.length, which means the test would end early (when userspace was done, but there were still GC actions to perform). Adding the proper gcActions.length check made the bug go away, but I can't think of a good reason it. Maybe it provokes more object creation and thus accelerates a more-complete GC pass.

The problem manifests as a failure of either of the two unit tests in that file: transcript-one save (which launches two swingsets from the same starting state, runs both to completion, then compares their full state vector), or transcript-one load (which records the full state vector after each crank, then replays the swingset from each recorded vector, and makes sure all replays emit a matching state at every crank). The problem appears on the 4th(?) crank, which delivers a notify to the bootstrap vat, which finishes its work and allows the entire scope frame to be dropped, which ought to drop all the vat root objects it was given in the vats argument. In some (most?) runs, this delivery emits a syscall.dropImports for all the vat root objects, but there is at least one run which does not. As a result, the gcActions state is different, as is the number of cranks being executed (since without syscall.dropImports the kernel won't schedule the resulting dispatch.dropExports).

The code did not originally do a await c.shutdown() after each run, but adding it did not fix the problem (and is only really necessary when using a non-local worker like xs-worker). Adding the gcActions.length check made the bug go away, as did switching to xs-worker, as did simply duplicating the gcAndFinalize() call in liveslots. The latter is the most disturbing, as it suggests that we need to finalize harder somehow.

I tried augmenting test-gc-and-finalize.js with a cyclic "victim" object graph, with the idea that maybe Node.js is able to notice a refcount dropping to zero immediately (instead of waiting for mark-and-sweep to see it), and so maybe introducing a deliberate cycle would expose an insufficiency in gcAndFinalize. But test-gc-and-finalize continued to pass.

function setup1() {
  // The worst case I can think of is a four-pole counter-rotating cycle,
  // held in place by N and S, with E as our victim/sensor. Dropping N or S
  // does not drop a refcount to zero.
  const N = {};
  const S = {};
  const E = { N, S };
  const W = { N, S };
  N.E = E;
  N.W = W;
  S.E = E;
  S.W = W;
  const finalized = ['finalizer not called'];
  const fr = new FinalizationRegistry(_tag => {
    finalized[0] = 'finalizer was called';
  });
  const wr = new WeakRef(E);
  fr.register(E, 'tag');
  return { N, S, finalized, fr, wr };
}

function setup2() {
  const { N: _ignoreN, S: _ignoreS, finalized, fr, wr } = setup1();
  // I want N and S to be dropped after E and W.
  return { finalized, fr, wr };
}

To experiment with this, comment out the gcActions.length check, and test-transcript.js ought to fail pretty quickly.

[michaelfig]

Consider a gc(true) invocation instead to gc-me-harder on Node.

[michaelfig]

Consider a gc(true) invocation instead to gc-me-harder on Node.

true means "full gc" but without it is just "minor".

(Blah blah blah ephemerons blah blah generational blah blah.)

[warner]

Oh. Oops. Guess I should read the docs :).

thank you !

[warner]

Hm, I tracked down the header file (it doesn't seem to be documented anywhere else), and it appears that no argument is equivalent to { type: 'major' }:

// Provides garbage collection on invoking |fun_name|(options), where
// - options is a dictionary like object. See supported properties below.
// - no parameter refers to options:
//   {type: 'major', execution: 'sync'}.
// - truthy parameter that is not setting any options:
//   {type: 'minor', execution: 'sync'}.
//
// Supported options:
// - type: 'major' or 'minor' for full GC and Scavenge, respectively.
// - execution: 'sync' or 'async' for synchronous and asynchronous execution,
// respectively.
// - Defaults to {type: 'major', execution: 'sync'}.

The implementation seems to match: if args.Length() == 0 then it calls InvokeGC with kFullGarbageCollection.

Rats, I was hoping that would explain it.

[warner]

Experimentally, gc() and gc(false) seem to provoke GC events, but not any of: gc(true), gc({ type: 'major' }), gc({ type: 'major', execution: 'sync' }), gc({}). So.. I have no idea what's going on. I'm adding one pattern in PR #3298 :

// test/basedir-promises-3/bootstrap.js
export function buildRootObject() {
  const pk1 = makePromiseKit();
  return Far('root', {
    bootstrap(vats) {
      const p2 = E(vats.right).one();
      E(p2).four(pk1.promise);
    },
    two() {
      pk1.resolve(3);
    },
  });
}

in which the vats variable is held (under Node.js) until the vat receives notification of the resolution of the unnamed result of E(p2).four(). Under XS, vats is dropped by the end of bootstrap(), as expected. I don't have a theory of what's holding onto it. I think I've seen some hoisting happen, where an inner function doesn't always limit the scope as much as I would have expected, so out of paranoia I've been defining many functions at the top level. But in this case it's an argument that's being held.

[warner]

I also tried the following without success:

    bootstrap({ right } {
      const p2 = E(right).one();
      E(p2).four(pk1.promise);
    },

The other members of vats were retained until the notify.

@michaelfig suggested (maybe in an offline conversation prompted by #3207 (comment)) that a V8 optimization is probably moving the lifetime scope (but not syntactic reachability scope) up a level or two, for some const/let declarations and/or arguments. In general, for the small number of tests that need to specifically exercise the JS engine's ability to collect things, we'll have to be careful about how we write that code, at least when testing under Node.js (XS seems much more thorough when you ask it to gc()).

[warner]

@michaelfig and I experimentally determined that V8 wants one additional setImmediate at the end of gcAndFinalize to allow promises to get collected reliably. So our current contender for an XS+V8-safe gcAndFinalize is:

    // on Node.js, GC seems to work better if the promise queue is empty first
    await new Promise(setImmediate);
    // on xsnap, we must do it twice for some reason
    await new Promise(setImmediate);
    gcPower();
    // this gives finalizers a chance to run
    await new Promise(setImmediate);
    // Node.js needs this to allow all promises to get collected
    await new Promise(setImmediate);

[warner]

@FUDCo determined that AVA-parallelized unit tests on Node.js cause V8 to not run finalizers as soon as they ought to, so some GC-sensitive tests will fail (objects are released late, and/or finalizers are run late, so the syscall.dropImport calls show up in a later crank than expected).

We don't know exactly what's going on, but it seems like a parallel test case interferes with gcAndFinalize.

The fix is to do one of:

• make the test not be sensitive to GC timing, by looking less closely at what happens in each crank
• run the test by itself, using AVA's test.serial() instead of plain test()
• make the test's vat-worker run under XS instead of Node (setting the kernel config's worker-type to xs-worker)

[Tartuffo]

@warner When I first started working on our ZH board, I marked this as being for the Mainnet 1 release because it was already in the Review/QA pipeline. The comment makes it seem like it is an open question, not really In Review or In QA. Should this be moved back to the MN-1 backlog, or taken out of the Mainnet 1 release altogether.

[Tartuffo]

@warner Since this was moved to the Review/QA pipeline "via the connected PR Agoric/agoric-sdk #3431", I'm moving this back to MN-1 Backlog. LMK if you disagree. Also, this needs an estimate.

[warner]

I think we updated enough tests with test.serial to avoid this problem for now, but we still don't understand the root cause. Moving it out of MN-1 because it's not causing problems today.

[warner]

#4617 appears to be another instance of this

[Tartuffo]

@warner Since @michaelfig was able to reproduce this in v16.14.0, presumably this issue needs to go back into MN-1?

[warner]

#5266 is another instance of this problem, but in Node v16.14.2 . The specific test case with the problem had a test.serial on it, but the others in that file did not.

[warner]

This only seems to affect CI, so we're not going to worry about this for MN-1, for sure. This ticket is about keeping an eye on this problem.

[warner]

I'm moving this back to Product Backlog: it is annoying, but doesn't affect product functionality, and certainly doesn't need to be a priority for the Vaults release.