Looking at the exchangeBenchmark with the Slogulator

What's Going On Here

This page documents analysis of one round of the swingset-runner exchangeBenchmark. In this benchmark, Alice and Bob exchange 1 simolean for 1 moola and then 1 moola for 1 simolean in alternating rounds.

Normally we'd run somewhere between 10 and 10,000 rounds and collect stats, but for this test a single round is sufficient, since what we are measuring are the residual objects left over after a single iteration of the test, to try to get a handle on what objects we are leaking. This test is in service of helping us focus our attention and make decisions about what should be done, in what order, to ensure that things that, in principle at least, shouldn't grow in memory footprint over time actually don't, so that they can be run indefinitely in production. This is a key requirement for operation at scale.

The test documented here was run on 13-November-2020 from the agoric-sdk/packages/swingset-runner directory using the code in commit 53c6e7d179e1ab271bed5c40a64a76d44e83141a. The command used was:

bin/runner --init --slog eslog --benchmark 1 --config demo/exchangeBenchmark/swingset.json --dump run -- --prime

The --prime option causes Alice and Bob to do one exchange in each direction to "prime the pump" before we start making benchmark measurements, to make sure any lazily executed one-time setup isn't happening during the execution being analyzed.

The --dump option causes swingset-runner to dump a snapshot of the kernel database after each crank. By comparing the differences between the snapshot files from the crank immediately prior to the start of the benchmark round to the last crank of the benchmark round, we can see what objects and promises accumulated in the kernel's state.

The --slog eslog option tells swingset-runner to run using the kernel's "slog" feature, which produces a detailed, structured log of important kernel activities (in this case, into the file eslog).

The slog file was run through the Slogulator utility to render it in a readable form, using the command:

node -r esm src/slogulator.js --annotations annot.json eslog > vslog

This translates the slog file eslog into a quasi-human readable log in the file vslog. The annotations file annot.json allows the substitution of meaningful names for the raw identifier strings used internally by the Swingset kernel, as well as allowing names to be given to dynamic vats, to label important cranks in the execution history, and to add other annotations. These annotations help make the output log more readable, allowing easier analysis of what's going on, typically resulting in the choice of further names for things. The analysis process iterates between studying the output file, adding more annotations, and re-running the Slogulator. In practice I automated the mechanical parts of this with an emacs macro, allowing analysis to unfold using two windows, one to edit the annotations file and the other to display the log file and automagically update the view each time changes to the annotations file were saved. Perhaps in the future this kind of interactive analysis may be facilitated by a web utility or a VS Code plugin.

This iteration was repeated until all objects and promises in the run had been named and accounted for. The resulting completed annotation file is checked in alongside the benchmark sources. It may be viewed at annot.json. A copy of the final vslog file can be viewed at vslog. (thanks to Chris Hibbert for helping me understand what was going on inside Zoe and the SimpleExchange contract to make this deconstruction possible).

Analysis

Kernel objects introduced by the benchmark round

Each round leaves behind 23 objects.

• vat v9 (zcf), 6 objects
• vat v3 (zoe), 11 objects
• vat v4 (bootstrap), 6 objects (all payments)

The detailed breakdown of these for the one exchangeBenchmark round is as follows. Each line gives the kernel object identifier ("slot") string, the vat exporting the object, and the name assigned in the annotation phase.

ko104 (v9) exchangeOfferHandler-aliceAddOffer-br1
ko105 (v9) emptyCustomProperties#5
ko106 (v3) aliceBuyOrderInvitation-br1
ko107 (v4) aliceMoolaPayment-br1
ko108 (v3) aliceBuyOrderSeatAdmin-br1
ko109 (v3) aliceBuyOrderSeatNotifier-br1
ko110 (v3) aliceBuyOrderSeatHandle-br1
ko111 (v3) aliceBuyOrderSeat-br1
ko112 (v9) aliceBuyOrderSeatExitObj-br1
ko113 (v9) exchangeOfferHandler-aliceToBob-br1
ko114 (v9) emptyCustomProperties#6
ko115 (v3) aliceToBobInvitation-br1
ko116 (v3) aliceToBobInvitationPayment-br1
ko117 (v4) bobSimoleanPayment-br1
ko118 (v3) bobSellOrderSeatAdmin-br1
ko119 (v3) bobSellOrderSeatNotifier-br1
ko120 (v3) bobSellOrderSeatHandle-br1
ko121 (v3) bobSellOrderSeat-br1
ko122 (v9) bobSellOrderSeatExitObj-br1
ko123 (v4) zoeSimoleanPayment-bob-br1
ko124 (v4) zoeMoolaPayment-bob-br1
ko125 (v4) zoeMoolaPayment-alice-br1
ko126 (v4) zoeSimoleanPayment-alice-br1

Kernel promises left unretired at the end of the benchmark round

During the round, 11 promises were introduced and resolved, but not retired:

// runBenchmarkRound-1/rp -- held by controller
kp160: fulfilled to "round 1 (alice->bob) complete"

// zcfAddSeatObj.addSeat-aliceBuyOrder-br1/rp -- promises in data
kp170: fulfilled to { offerResultP: @kp171, exitObj: @ko112 }

// aliceBuyOrderOfferResult-br1/p -- held by @kp170
kp171: fulfilled to "Order Added"

// aliceSeat.getPayouts-br1/rp -- promises in data
kp172: fulfilled to { Asset: @kp190, Price: @kp191 }

// zcfAddSeatObj.addSeat-bobSellOrder-br1/rp -- promises in data
kp182: fulfilled to { offerResultP: @kp183, exitObj: @ko122 }

// bobSellOrderOfferResult-br1/p -- held by @kp182
kp183: fulfilled to "Order Added"

// bobSellOrderSeat.getPayouts-br1/rp -- promises in data
kp187: fulfilled to { Price: @kp188, Asset: @kp189 }

// zoeSimoleanPurse.withdraw-bob-br1/rp -- held by @kp187
kp188: fulfilled to @ko123

// zoeMoolaPurse.withdraw-bob-br1/rp -- held by @kp187
kp189: fulfilled to @ko124

// zoeMoolaPurse.withdraw-alice-br1/rp -- held by @kp172
kp190: fulfilled to @ko125

// zoeSimoleanPurse.withdraw-alice-br1/rp -- held by @kp172
kp191: fulfilled to @ko126

An additional 29 promises where introduced and resolved, but were retired, leaving no footprint.

Primer debris

The two primer phase trades mirror the benchmark round (i.e., the same sequence of objects and promises was produced, though of course they have distinct kernel IDs). It turns out there really wasn't any additional initialization activity after the first trade was initiated, so if we repeat this test we can probably skip the primer phase.

For the record:

Primer trade #1 produced objects ko58-ko80 and promises kp91 kp92 kp93 kp103 kp104 kp108 kp109 kp110 kp111 kp112

Primer trade #2 produced objects ko81-ko103 and promises kp130 kp131 kp132 kp142 kp143 kp147 kp148 kp149 kp150 kp151

For a given object playing some role in the exchange, the same base name is assigned in the annotation file, with the suffix -pt1, -pt2, or -br1, indicating primer trade 1, primer trade 2, or benchmark round 1, respectively.

Other objects

Kernel objects ko20-ko57 are established by the setup of Zoe, the SimpleExchange contract, and the test framework. These persist for the entire life of the benchmark independent of the number of rounds and do not contribute to the incremental growth of the memory footprint.

In addition, two promises were still extant at the end of the test:

kp40 (bootstrap/rp) -- fulfilled to undefined but not retired because it's still held by controller

kp55 (zcfAdmin.done/rp) -- still unresolved pending termination of the zcf vat

These are one-time objects and so won't increase in number no matter how many rounds are executed, but are mentioned here for completeness.