From 19fa425da16c37f3f6046e611c8c3ada6b547945 Mon Sep 17 00:00:00 2001
From: Richard Gibson <richard.gibson@gmail.com>
Date: Tue, 13 Sep 2022 05:35:33 -0400
Subject: [PATCH] feat: Write makeSnapshot telemetry to slog

Fixes #6164
---
 packages/SwingSet/src/kernel/state/vatKeeper.js  | 12 +++++++++++-
 .../test/snapshots/test-xsnap-store.js.md        | 12 ++++++------
 packages/swing-store/src/snapStore.js            | 16 ++++++----------
 packages/swing-store/test/test-snapstore.js      |  4 ++--
 4 files changed, 25 insertions(+), 19 deletions(-)

diff --git a/packages/SwingSet/src/kernel/state/vatKeeper.js b/packages/SwingSet/src/kernel/state/vatKeeper.js
index 22960128d92e..878c50de39c3 100644
--- a/packages/SwingSet/src/kernel/state/vatKeeper.js
+++ b/packages/SwingSet/src/kernel/state/vatKeeper.js
@@ -589,7 +589,13 @@ export function makeVatKeeper(
     }
 
     const info = await manager.makeSnapshot(snapStore);
-    const { hash: snapshotID } = info;
+    const {
+      hash: snapshotID,
+      rawByteCount,
+      rawSaveMillisec,
+      compressedByteCount,
+      compressMillisec,
+    } = info;
     const old = getLastSnapshot();
     if (old && old.snapshotID !== snapshotID) {
       if (removeFromSnapshot(old.snapshotID) === 0) {
@@ -606,6 +612,10 @@ export function makeVatKeeper(
       type: 'heap-snapshot-save',
       vatID,
       snapshotID,
+      rawByteCount,
+      rawSaveMillisec,
+      compressedByteCount,
+      compressMillisec,
       endPosition,
     });
     return true;
diff --git a/packages/SwingSet/test/snapshots/test-xsnap-store.js.md b/packages/SwingSet/test/snapshots/test-xsnap-store.js.md
index 4ecc57774585..baea019f0ec0 100644
--- a/packages/SwingSet/test/snapshots/test-xsnap-store.js.md
+++ b/packages/SwingSet/test/snapshots/test-xsnap-store.js.md
@@ -9,29 +9,29 @@ Generated by [AVA](https://avajs.dev).
 > initial snapshot
 
     {
-      compressDuration: 0,
+      compressMillisec: 0,
       compressedByteCount: 27931,
       hash: '8a0e3873976c50462d1b1dac59c912152b0e5cad5eeb9deca0ca64a087b4a873',
       rawByteCount: 167887,
-      rawSaveDuration: 0,
+      rawSaveMillisec: 0,
     }
 
 > after SES boot - sensitive to SES-shim, XS, and supervisor
 
     {
-      compressDuration: 0,
+      compressMillisec: 0,
       compressedByteCount: 168677,
       hash: '432e0a93e70817bacf5723354bf5e92f47ff0122f925540cf1d30dc27f2194f8',
       rawByteCount: 783519,
-      rawSaveDuration: 0,
+      rawSaveMillisec: 0,
     }
 
 > after use of harden() - sensitive to SES-shim, XS, and supervisor
 
     {
-      compressDuration: 0,
+      compressMillisec: 0,
       compressedByteCount: 169165,
       hash: 'c3df25ad46a7863a854ac14eb5d32b73108b695b7e1ab7f203854aaeddf111e9',
       rawByteCount: 785423,
-      rawSaveDuration: 0,
+      rawSaveMillisec: 0,
     }
diff --git a/packages/swing-store/src/snapStore.js b/packages/swing-store/src/snapStore.js
index e2e6de3bd1c8..523a0657a371 100644
--- a/packages/swing-store/src/snapStore.js
+++ b/packages/swing-store/src/snapStore.js
@@ -10,9 +10,9 @@ import { promisify } from 'util';
  * @property {string} filePath absolute path of (compressed) snapshot
  * @property {string} hash sha256 hash of (uncompressed) snapshot
  * @property {number | bigint} rawByteCount size of (uncompressed) snapshot
- * @property {number | bigint} rawSaveDuration time to save (uncompressed) snapshot according to a provided "now" function
+ * @property {number | bigint} rawSaveMillisec time to save (uncompressed) snapshot according to a provided "now" function
  * @property {number | bigint} [compressedByteCount] size of (compressed) snapshot
- * @property {number | bigint} [compressDuration] time to compress and save snapshot according to a provided "now" function
+ * @property {number | bigint} [compressMillisec] time to compress and save snapshot according to a provided "now" function
  */
 
 /**
@@ -214,7 +214,7 @@ export function makeSnapStore(
     return withTempName(async snapFile => {
       const t0 = /** @type {number} */ (now());
       await saveRaw(snapFile);
-      const rawSaveDuration = /** @type {number} */ (now()) - t0;
+      const rawSaveMillisec = /** @type {number} */ (now()) - t0;
       const { size: rawsize } = await stat(snapFile);
       const h = await fileHash(snapFile);
       if (toDelete.has(h)) {
@@ -222,7 +222,7 @@ export function makeSnapStore(
       }
       // console.log('save', { snapFile, h });
       const filePath = hashPath(h);
-      const info = { filePath, hash: h, rawByteCount: rawsize, rawSaveDuration };
+      const info = { filePath, hash: h, rawByteCount: rawsize, rawSaveMillisec };
       const fileStat = await stat(filePath).catch(e => {
         if (e.code === 'ENOENT') {
           return undefined;
@@ -236,12 +236,8 @@ export function makeSnapStore(
       const { size: compressedByteCount } = await atomicWrite(filePath, gztmp =>
         filter(snapFile, createGzip(), gztmp, { flush: true }),
       );
-      const compressDuration = /** @type {number} */ (now()) - t1;
-      // TODO: remove once #5419 is resolved
-      console.log(
-        `XS snapshot written to ${filePath} : ${compressedByteCount} bytes compressed, ${rawsize} raw`,
-      );
-      return freeze({ ...info, compressDuration, compressedByteCount });
+      const compressMillisec = /** @type {number} */ (now()) - t1;
+      return freeze({ ...info, compressMillisec, compressedByteCount });
     }, 'save-raw');
   }
 
diff --git a/packages/swing-store/test/test-snapstore.js b/packages/swing-store/test/test-snapstore.js
index 28ddee405d50..cbf9cd7abfe1 100644
--- a/packages/swing-store/test/test-snapstore.js
+++ b/packages/swing-store/test/test-snapstore.js
@@ -36,8 +36,8 @@ test('build temp file; compress to cache file', async t => {
     hash: expectedHash,
     filePath: path.resolve(pool.name, `${expectedHash}.gz`),
     rawByteCount: 3,
-    rawSaveDuration: 0,
-    compressDuration: 0,
+    rawSaveMillisec: 0,
+    compressMillisec: 0,
   });
   t.is(await store.has(hash), true);
   const zero =