v43-walletFactory heap is large and still growing

[warner]

While looking at perf metrics of the mainnet chain, I noticed that v43-walletFactory has a very large XS heap (and thus also has a very large XS heap snapshot), and is still growing.

Here is a graph of the v43 XS heap snapshot size versus deliveryNum (which is not the same as time, but monotonically increases with time):

The piecewise-linear regions are separated by upgrade events. The last time we upgraded v43-walletFactory was in upgrade-17, which both made functional improvements to the walletFactory, and (supposedly) fixed the passStyleOf problem that caused heap growth for every non-retired Presence that traversed the marshalling code (mostly from #8400 and #8401 , which should be flattened by upgrade-18 and eventually drained by slowly deleting the old price-feed vats sometime after upgrade-19) . That upgrade event happened at about deliveryNum/snapPos 21M, and forms the start of the right-most linear segment in that graph.

We don't know why this vat is still growing: either the passStyleOf fix didn't take, or something else is going on. And I have even less ideas about why it might appear to be growing faster than before. Note that the X-axis is deliveries, not time, so I can only say with confidence that our bytes-per-delivery rate is higher. I'm not entirely sure that the bytes-per-time is higher: maybe we're doing fewer deliveries per second, but have more growth per delivery. To get a bytes-per-time slope from my data, we need to use the slogs to extract the blockTime of each sample. (I'll see if I can at least find the endpoints of each sawtooth).

#10493 is about restarting this vat, which would reset the state back down to the bottom of a sawtooth, which would buy us some time to figure out the real problem. And the upgrade-18 fixes that retire QuotePayment objects (and break the Zoe cycles) may help, whether or not the passStyleOf fix is working.

But we need to figure out the root cause. One step would be to take a v43 heap snapshot and use the Moddable tools to dump its contents. I'm going to guess that the CHUNKS section is fairly small (strings and Array backing stores), and the SLOTS section is very large (objects and their properties). With a heap that large, random sampling of the SLOTS section would mostly return the things that we have too much of: if we see more than three samples showing the same kind of object, that's the problem right there, and the second step will be to figure out where it's coming from, and why it's being retained.

[warner]

I made a new graph where date is the x-axis, which shows that the bytes-per-second is in fact higher now:

(this graph doesn't include all the same datapoints as above: I manually extracted a handful of samples, and only went as far back as april-2024 and the end of the upgrade-13 era, but I think it still accurately reflects the growth rate-vs-time for the last eight months)

[warner]

That growth rate is about 9.5MB/day

[warner]

Here's some information I got by dumping a recent v43-walletFactory heap snapshot. The procedure:

• node packages/SwingSet/misc-tools/extract-xs-snapshot.js ~/.agoric/data/agoric v43 : creates v43-${snapPos}-${hash}.xss
• build the xsnap binary (cd packages/xsnap/xsnap-native/xsnap/makefiles/lin && MODDABLE=/PATH/TO/agoric-sdk/packages/xsnap/moddable GOAL=debug CC=cc VERBOSE=1 make -f xsnap.mk, then copy/symlink packages/xsnap/moddable/build/bin/lin/release/xsnap into your $PATH)
• xsnap -d *.xss |gzip >dump.gz (a 700MB heap yields a text dump of maybe 1.5GB, but it compresses very well)
• write up a section-splitting tool:

import sys, re, gzip

# Use 'xsnap -d SNAPSHOT.xss' to dump an XS heap snapshot into a text file,
# then feed that text file into my stdin, along with a prefix. I will create
# ten files with names like "prefix-XS_M.gz" and "prefix-HEAP.gz", each with
# one section of the snapshot dump. This makes it easier to search for specific
# e.g. slots by their index number.

sections = [
    "XS_M",
    "VERS",
    "SIGN",
    "CREA", # sizes and creation parameters
    "BLOC", # the chunks table
    "HEAP", # the slots table
    "STAC",
    "KEYS", # maps ID_nnn to the property-key name
    "NAME", # helps map property-named keys, somehow
    "SYMB", # helps map symbol-named keys
    ]

prefix = sys.argv[1]
fn = None
count = 0

for line in sys.stdin:
    if sections and line.startswith(sections[0]):
        if fn:
            print(" finished %s (%d lines)" % (section, count))
            fn.close()
            count = 0
        section = sections.pop(0)
        fn = gzip.open("%s-%s.gz" % (prefix, section), "w")
        fn.write(line.encode("utf-8"))
    else:
        fn.write(line.encode("utf-8"))
    count += 1

• gzcat dump.gz | python3 split-xs-snapshot-dump.py PREFIX : creates PREFIX-HEAP.gz, etc
• the interesting files are -HEAP (the slots table), -KEYS (the property-name table), and -BLOC (the chunks table, which includes literal strings)

I used wc -l to count the number of slots, then picked one at random, under the theory that 1: the majority of the snapshot is the junk that we're worried about, so 2: any random slot has a very high probability of being junk. I found that most of the entries follow a four-slot pattern. Here are two consecutive instances of that pattern, so we can see their relationship:

        [10273116] [10273117] ________           instance = { .garbage = [        ], .prototype = [00017650] }
        [10273117] [        ] _______I           weakRef = { .target = [        ], .link = [        ] }
        [10273118] [10273119] ________           string = <91888680>
        [10273119] [10273122] ________           reference = [10273120]
        [10273120] [10273121] ________           instance = { .garbage = [        ], .prototype = [00017650] }
        [10273121] [        ] _______I           weakRef = { .target = [        ], .link = [        ] }
        [10273122] [10273123] ________           string = <91888712>
        [10273123] [10273126] ________           reference = [10273124]

The string = can be looked up in the -BLOC table, in this case 91888680 is p+26051869, and 91888712 is p+26051870.

In XS speak, this is probably part of a Map whose keys are locally-allocated promise vref strings (aka "VPID"s), and whose values are WeakRefs whose targets are empty. I'm guessing that means the targets have been garbage collected, but the WeakRef itself is still reachable. That would mean any call to .deref() would return undefined.

I count 3,776,863 -BLOC strings of the form p+NNN, which means we've got nearly four million string literals in memory. These alone account for over 38MB of heap space, just to store the VPIDs.

These are almost certainly entries of the liveslots slotToVal table, which maps vrefs to a WeakRef for each Promise, Presence, Representative, Remotable, or DeviceNode in the vat. There is a companion FinalizationRegistry with which we track all the object-like things (Presence/Representative/Remotable, but not Promises or device nodes).

The idea is that liveslots needs to know when userspace drops the Presence/etc, so it can decrement refcounts and maybe inform the kernel that we're dropping the vref. The WeakRef lets us translate vrefs to objects (e.g. when deserializing the arguments of an inbound dispatch.deliver), but doesn't hold the object strongly, so we can still sense it being dropped by userspace. Engine-level GC might cause the WeakRef to become empty some time before the finalizer callback is run, so there is code to probe the WeakRef and re-populate it with a new Presence if necessary.

For objects, the expected sequence is:

• userspace drops the Presence, moving it from REACHABLE to UNREACHABLE (using the terminology documented in liveslots.js)
• later, engine-level GC happens and the engine notices the lack of references to the Presence. The finalizer is enqueued, and the WeakRef is emptied. We call this state COLLECTED (but not FINALIZED).
• still later, the finalizer callback is run, moving it to FINALIZED
  • for liveslots this is finalizeDroppedObject(), which probes the WeakRef (to guard against objects being re-introduced while in COLLECTED, but the finalizer callback not being cancelled). If it finds the WeakRef is still empty, it deletes the slotToVal Map entry (thus releasing the WeakRef itself), and adds the vref to possiblyDeadSet for refcount examination the next time BOYD is called

Note that we have modified XS to not empty out the WeakRefs or call finalizers during "organic" GC (the kind triggered when the engine exhausts the free-slot table, and does GC first in the hopes of avoiding malloc()). Those consequences are only triggered during a "forced" GC, such as when we call BOYD.

We also put Promises in these WeakRefs, for consistency in our convertSlotToVal() calls (which would otherwise need to examine the vref type to know whether to do slotToVal.get(vref).deref() or just slotToVal.get(vref)). We don't use the FinalizationRegistry for promises: we keep them alive until they are resolved, and then we delete them from the table whether they're still reference or not. (Unlike Presences/etc, we don't provide === -type equality checking for Promises).

My current hypothesis is that these are entries for promises that have been resolved, and dropped by both userspace and liveslots, and collected in a BOYD delivery. But the code in unregisterUnreferencedVPID(), which is supposed to delete the entries from slotToVal, is not deleting them.

I see a check for vrm.getReachablePromiseRefCount(p) === 0 guarding that unregistration: that means we're trying to not delete the entry if a virtual object is referencing a Promise. (Note that it could not be a durable object, because Promises are not durable, and cannot be held by durable objects). However, I don't see any code in removeReachableVref() which would react to this refcount hitting zero by calling unregisterUnreferencedVPID(). I'm wondering if we're missing a cleanup handler on one of the two paths to (settled+unreferenced):

• promise becomes unreferenced first, then becomes settled: correctly removed from slotToVal
• promise becomes settled first, then unreferenced (by vdata): left in slotToVal

We don't use virtual objects very much (we mostly use durable), so we should look for code in v43-walletFactory which creates non-durable BigMapStores or the like.

The fix is likely to be code in removeReachableVref() which reacts to the refcount=0 case by calling unregisterUnreferencedVPID(), except maybe it should only do that if the promise is resolved.

[warner]

v43-walletFactory has no instances of any merely-virtual Kinds (virtual-object vrefs like o+vNN: all are like o+dNN). Nor does it have any merely-virtual collections (the collection KindIDs are all 6, 7, or 8, which correspond to scalarDurableMapStore, scalarDurableWeakMapStore, and scalarDurableSetStore, without any occurrences of the IDs for scalarMapStore or scalarSetStore, etc). So I'm not sure how a vdata refcount could be elevated, to bypass the slotToVal.delete() clause.

[warner]

I sorted the p+NN strings and found the highest one: this should correspond to the most-recently-allocated one in my sample (which I grabbed maybe 6 hours ago). I then grepped the slogfile for my follower for places where it was referenced. Here's the list:

{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":163,"replay":false,"ksc":["vatstoreGet","v43","vc.4.sp+28581604"],"vsc":["vatstoreGet","vc.4.sp+28581604"],"time":1734673268.65444,"monotime":252577.83414744903}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":164,"replay":false,"ksc":["vatstoreGet","v43","vc.4.sp+28581604"],"vsc":["vatstoreGet","vc.4.sp+28581604"],"time":1734673268.654753,"monotime":252577.83446071504}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":167,"replay":false,"ksc":["vatstoreSet","v43","vc.4.sp+28581604","{\"body\":\"#[[\\\"$0.Alleged: VowInternalsKit watchNextStep\\\"]]\",\"slots\":[\"o+d31/1618680:2\"]}"],"vsc":["vatstoreSet","vc.4.sp+28581604","{\"body\":\"#[[\\\"$0.Alleged: VowInternalsKit watchNextStep\\\"]]\",\"slots\":[\"o+d31/1618680:2\"]}"],"time":1734673268.655422,"monotime":252577.835129429}
{"type":"clist","crankNum":281108968,"mode":"export","vatID":"v43","kobj":"kp68948040","vobj":"p+28581604","time":1734673268.656129,"monotime":252577.835836601}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":170,"replay":false,"ksc":["subscribe","v43","kp68948040"],"vsc":["subscribe","p+28581604"],"time":1734673268.656162,"monotime":252577.835869398}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":171,"replay":false,"ksc":["vatstoreGet","v43","vc.11975.sp+28581604"],"vsc":["vatstoreGet","vc.11975.sp+28581604"],"time":1734673268.656431,"monotime":252577.836138006}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":172,"replay":false,"ksc":["vatstoreSet","v43","vc.11975.sp+28581604","{\"body\":\"#\\\"&0\\\"\",\"slots\":[\"p+28581604\"]}"],"vsc":["vatstoreSet","vc.11975.sp+28581604","{\"body\":\"#\\\"&0\\\"\",\"slots\":[\"p+28581604\"]}"],"time":1734673268.861068,"monotime":252578.04077633301}
{"type":"clist","crankNum":281108968,"mode":"drop","vatID":"v43","kobj":"kp68948040","vobj":"p+28581604","time":1734673268.862098,"monotime":252578.041805832}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":175,"replay":false,"ksc":["resolve","v43",[["kp68948040",false,{"body":"#[\"#undefined\",1,{}]","slots":[]}]]],"vsc":["resolve",[["p+28581604",false,{"body":"#[\"#undefined\",1,{}]","slots":[]}]]],"time":1734673268.862172,"monotime":252578.041879294}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":176,"replay":false,"ksc":["vatstoreGet","v43","vc.4.sp+28581604"],"vsc":["vatstoreGet","vc.4.sp+28581604"],"time":1734673268.862821,"monotime":252578.042528082}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":177,"replay":false,"ksc":["vatstoreGet","v43","vc.4.sp+28581604"],"vsc":["vatstoreGet","vc.4.sp+28581604"],"time":1734673268.863224,"monotime":252578.042931784}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":180,"replay":false,"ksc":["vatstoreDelete","v43","vc.4.sp+28581604"],"vsc":["vatstoreDelete","vc.4.sp+28581604"],"time":1734673268.863842,"monotime":252578.04354932503}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":183,"replay":false,"ksc":["vatstoreGet","v43","vc.11975.sp+28581604"],"vsc":["vatstoreGet","vc.11975.sp+28581604"],"time":1734673268.864432,"monotime":252578.04413940702}
{"type":"syscall-result","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":183,"replay":false,"ksr":["ok","{\"body\":\"#\\\"&0\\\"\",\"slots\":[\"p+28581604\"]}"],"vsr":["ok","{\"body\":\"#\\\"&0\\\"\",\"slots\":[\"p+28581604\"]}"],"time":1734673268.864455,"monotime":252578.04416215201}
{"type":"syscall","crankNum":281108968,"vatID":"v43","deliveryNum":27151630,"syscallNum":184,"replay":false,"ksc":["vatstoreDelete","v43","vc.11975.sp+28581604"],"vsc":["vatstoreDelete","vc.11975.sp+28581604"],"time":1734673268.864665,"monotime":252578.044372354}

It looks like the vpid appeared as the key of vc.4 (as a string, not a serialized Promise), which must be the watchedPromises table. The value is marked as VowInternalsKit watchNextStep. Then the kernel subscribes to the promise, which suggests this is an internally-created Promise (not the result of an outbound message, not something which appeared in the arguments of an inbound method, but a local new Promise() that was given to watchPromise without first being serialized or sent off-vat).

The vat also uses this VPID as a string key of vc.11975, with a body that looks like a curious marshalling of the same promise (using &0 instead of $0). I'm not sure what this is. The collection is labelled as promiseRegistrations. I don't see any vrefs for the collection, though, so my tools don't know what it's KindID is (and whether it's durable or merely-virtual: the presence of a Promise in its .slots suggests it's merely-virtual). That might mean the collection is only held ephemerally.

Then, later in the same delivery, the vat does a syscall.resolve() of this promise, to [ undefined, 1, {} ]. The kernel doesn't care, but once the vat mentions a new vpid to the kernel (thus becoming the decider), the vat is responsible for telling the kernel about its resolution. The vat isn't notified by the kernel because the vat was the one who resolved it.

The vat then deletes both the watchedPromises table entry and the promiseRegistrations entry.

@mhofman I'm guessing this is Vows code, watching the Promise somehow. Who is doing the serialization?

[warner]

Oh, this isn't Vows, it's just liveslot's watchedPromises.js. For each incarnation, that code creates a merely-virtual table named promiseRegistrations:

  /**
   * virtual Store (not durable) mapping vpid to Promise objects, to
   * maintain the slotToVal registration until resolution. Without
   * this, slotToVal would forget local Promises that aren't exported.
   *
   * @type {MapStore<string, Promise<unknown>>}
   */
  let promiseRegistrations;
...
    promiseRegistrations = makeScalarBigMapStore('promiseRegistrations');

Every time userspace calls watchPromise(), the Promise gets stashed in the value side of that table. This causes addReachableVref to increment a refcount that exists only in RAM:

  /**
   * Map of all Remotables which are reachable by our virtualized data, e.g.
   * `makeScalarWeakMapStore().set(key, remotable)` or `virtualObject.state.foo =
   * remotable`. The serialization process stores the Remotable's vref to disk,
   * but doesn't actually retain the Remotable. To correctly unserialize that
   * offline data later, we must ensure the Remotable remains alive. This Map
   * keeps a strong reference to the Remotable along with its (virtual) refcount.
   */
  /** @type {Map<object, number>} Remotable->refcount */
  const remotableRefCounts = new Map();
...
  function addReachableVref(vref) {
...
    } else if (type === 'promise') {
      // need to track promises too, maybe in remotableRefCounts
      const p = requiredValForSlot(vref);
      const oldRefCount = remotableRefCounts.get(p) || 0;
      remotableRefCounts.set(p, oldRefCount + 1);
    }

The promise has (at least) two .then handlers. One is in watchedPromises.js, where pseudoThen adds a callback that will do promiseRegistrations.delete(vpid), which will decrement that refcount. The other is in liveslots.js (probably followForKernel, called by maybeExportPromise, called when a promise is watched). The followForKernel handler calls unregisterUnreferencedVPID(), which is supposed to do the slotToVal.delete(), but will refrain from that if the refcount is non-zero.

So it comes down to a race between two callbacks on the same promise. If the pseudoThen fires first, the refcount will be zero and unregisterUnreferencedVPID() will delete the slotToVal entry. If the followForKernel one fires first, the refcount will still be nonzero, and we never check it again. That will result in the slotToVal entry sticking around until a vat upgrade, with a barren WeakRef and the VPID string in RAM.

I think that explains the growth. It doesn't explain the increased rate of growth that we've seen in recent incarnations. We reload the watchedPromise table from durable storage at startVat, but we can't reach the old merely-virtual promiseRegistrations table, so I don't see how that would make things worse. (Although now I'm not sure we're gaining anything by having it be virtual, rather than just ephemeral: both cases would keep the Promises alive, we have to spend the RAM on promises in both cases, and the virtual table just leaves junk in the vatstore after an upgrade which we don't have enough mark+sweep GC to delete).

[warner]

An easy mitigation might be to change watchPromise to swap the order of the thens. Instead of the current:

        // Ensure that this vat's promises are rejected at termination.
        if (maybeExportPromise(vpid)) {
          syscall.subscribe(vpid);
        }

        promiseRegistrations.init(vpid, p);
        pseudoThen(p, vpid);

we do:

        promiseRegistrations.init(vpid, p);
        pseudoThen(p, vpid);
        // Ensure that this vat's promises are rejected at termination.
        if (maybeExportPromise(vpid)) {
          syscall.subscribe(vpid);
        }

If that's enough to get the engine to call the pseudoThen callback first, then we'll decrement the refcount before the maybeExportPromise callback checks it, and we'll delete the entries.

I'd also want to seriously consider changing promiseRegistrations to be a simple Map.

The deeper fix would be to change removeReachableVref to notice the rc=0 case and check if it needs to be removed from slotToVal. It's one of those "if A or B is true, make C true, but when both A and B are false, make C false" situations, where you need a common if (!A && !B) check which must be invoked on both the A just became false and the B just became false pathways. We have the check on one path, but not the other. I'm not optimistic that this can be shoehorned into removeReachableVref easily.

[mhofman]

FYI the increase in slopes are from 13->14 & 16->17, which respectively corresponds to the introduction of watchPromise and vow support (a bunch of watch and when. These would create a lot of watch registrations for locally decided promises.

[warner]

I'll track the workaround efforts in #10756, and the underlying two-pillars bug in #10757.