improve debug() logs

lib/index.js

@@ -76,7 +76,8 @@ function initGC(peer, config) {
   function cleanup(cb) {
     assertDBPlugin(peer)
     assertGoalsPlugin(peer)
-    debug('cleanup-per-purpose started')
+    debug('Cleanup started')
+    const startTime = Date.now()
 
     const done = multicb({ pluck: 1 })
     let waiting = false
@@ -104,16 +105,68 @@ function initGC(peer, config) {
     }
     /** @param {Error=} err */
     function whenEnded(err) {
-      // prettier-ignore
+      const duration = Date.now() - startTime
-      if (err) debug('cleanup-per-purpose ended with an error %s', err.message ?? err)
+      if (err) debug('Cleanup ended with an error %s', err.message ?? err)
-      else debug('cleanup-per-purpose ended')
+      else debug('Cleanup completed in %sms', duration)
-      assertDBPlugin(peer)
+      cb()
-      peer.db.log.compact(cb)
     }
     if (waiting) done(whenEnded)
     else whenEnded()
   }
 
+  /**
+   * Recreates the log so it has no empty space.
+   * @private
+   * @param {CB<void>} cb
+   */
+  function compact(cb) {
+    assertDBPlugin(peer)
+    debug('Compaction started')
+    const startTime = Date.now()
+    peer.db.log.compact((err) => {
+      const duration = Date.now() - startTime
+      if (err) debug('Compaction ended with an error %s', err.message ?? err)
+      else debug('Compaction completed in %sms', duration)
+      cb()
+    })
+  }
+
+  /**
+   * @param {number} percentUsed
+   * @param {{ totalBytes: number; }} stats
+   */
+  function reportCleanupNeed(percentUsed, stats) {
+    const bytesRemaining = MAX_LOG_BYTES - stats.totalBytes
+    const kbRemaining = bytesRemaining >> 10
+    const mbRemaining = bytesRemaining >> 20
+    const remaining =
+      mbRemaining > 0
+        ? `${mbRemaining}MB`
+        : kbRemaining > 0
+        ? `${kbRemaining}KB`
+        : `${bytesRemaining}B`
+    // prettier-ignore
+    debug('Log is %s% full (only %s of free space), needs cleanup', percentUsed.toFixed(0), remaining)
+  }
+
+  /**
+   * @param {number} percentDeleted
+   * @param {{ deletedBytes: any; }} stats
+   */
+  function reportCompactionNeed(percentDeleted, stats) {
+    const unusedBytes = stats.deletedBytes
+    const kbUnused = unusedBytes >> 10
+    const mbUnused = unusedBytes >> 20
+    const unused =
+      mbUnused > 0
+        ? `${mbUnused}MB`
+        : kbUnused > 0
+        ? `${kbUnused}KB`
+        : `${unusedBytes}B`
+    // prettier-ignore
+    debug('Log is %s% deleted (%s of unused space), needs compaction', percentDeleted.toFixed(0), unused)
+  }
+
   /**
    * Monitor the log size and schedule compaction and/or cleanup.
    */
@@ -130,10 +183,20 @@ function initGC(peer, config) {
 
         // Schedule clean up
         if ((needsCleanup || needsCompaction) && !hasCleanupScheduled) {
+          if (needsCleanup) reportCleanupNeed(percentUsed, stats)
+          if (needsCompaction) reportCompactionNeed(percentDeleted, stats)
           hasCleanupScheduled = true
-          cleanup(() => {
+          if (needsCleanup) {
-            hasCleanupScheduled = false
+            cleanup(() => {
-          })
+              compact(() => {
+                hasCleanupScheduled = false
+              })
+            })
+          } else {
+            compact(() => {
+              hasCleanupScheduled = false
+            })
+          }
         }
       })
     }
@@ -166,7 +229,7 @@ function initGC(peer, config) {
    * @param {CB<void>} cb
    */
   function forceImmediately(cb) {
-    debug('force immediately')
+    debug('Force clean & compact immediately')
     cleanup(cb)
   }