commit 67f4b6cb08ad8053fadf19d37580b3f27c3bdd76
author David Rogers <davidrogers@google.com> Thu Feb 06 16:17:09 2020 -0800
committer CQ Bot Account <commit-bot@chromium.org> Fri Feb 07 00:29:18 2020 +0000
tree 56478fb0c4e9da92d2c8510d3c35357071aeb459
parent 8fff434b64d5bf6a9e143d3e6b0452e9a3baa5df

pw_kvs: Add debug logging for sector find and relocate entry

Add enhanced debug logging for finding sector to write to, relocate
entry, and garbage collection.

Change-Id: I6c82c082a2f0698c83501bac82665815bea2a8e8

pw_kvs/key_value_store.cc

diff --git a/pw_kvs/key_value_store.cc b/pw_kvs/key_value_store.cc
index 9d10d19..b19c163 100644
--- a/pw_kvs/key_value_store.cc
+++ b/pw_kvs/key_value_store.cc
@@ -570,21 +570,31 @@
   SectorDescriptor* first_empty_sector = nullptr;
   bool at_least_two_empty_sectors = bypass_empty_sector_rule;
 
+  DBG("Find sector with %zu bytes available", size);
+  if (sector_to_skip != nullptr) {
+    DBG("  Skip sector %zu", SectorIndex(sector_to_skip));
+  }
+  if (bypass_empty_sector_rule) {
+    DBG("  Bypassing empty sector rule");
+  }
+
   // Look for a partial sector to use with enough space. Immediately use the
   // first one of those that is found. While scanning for a partial sector, keep
   // track of the first empty sector and if a second sector was seen.
   for (size_t i = start; i != last_new_sector_index_;
        i = (i + 1) % sector_map_size_) {
-    DBG("Examining sector %zu", i);
     SectorDescriptor& sector = sector_map_[i];
 
     if (sector_to_skip == &sector) {
-      DBG("Skipping the skip sector");
+      DBG("  Skipping the skip sector %zu", i);
       continue;
     }
 
+    DBG("  Examining sector %zu with %hu bytes available",
+        i,
+        sector.tail_free_bytes);
     if (!SectorEmpty(sector) && sector.HasSpace(size)) {
-      DBG("Partially occupied sector with enough space; done!");
+      DBG("  Partially occupied sector %zu with enough space; done!", i);
       *found_sector = &sector;
       return Status::OK;
     }
@@ -603,7 +613,7 @@
   // sector after the sector found here, but that rule can be bypassed in
   // special circumstances (such as during garbage collection).
   if (at_least_two_empty_sectors) {
-    DBG("Found a usable empty sector; returning the first found (%zu)",
+    DBG("  Found a usable empty sector; returning the first found (%zu)",
         SectorIndex(first_empty_sector));
     last_new_sector_ = first_empty_sector;
     *found_sector = first_empty_sector;
@@ -611,6 +621,7 @@
   }
 
   // No sector was found.
+  DBG("  Unable to find a usable sector");
   *found_sector = nullptr;
   return Status::RESOURCE_EXHAUSTED;
 }
@@ -653,10 +664,15 @@
     }
   }
 
+  DBG("Found sector %zu to Garbage Collect, %zu recoverable bytes",
+      SectorIndex(sector_candidate),
+      RecoverableBytes(*sector_candidate));
   return sector_candidate;
 }
 
 Status KeyValueStore::GarbageCollectOneSector(SectorDescriptor** sector) {
+  DBG("Garbage Collect a single sector");
+
   // Step 1: Find the sector to garbage collect
   SectorDescriptor* sector_to_gc = FindSectorToGarbageCollect();
 
@@ -668,13 +684,16 @@
   if (sector_to_gc->valid_bytes != 0) {
     for (auto& descriptor : key_descriptors()) {
       if (AddressInSector(*sector_to_gc, descriptor.address)) {
+        DBG("  Relocate entry");
         TRY(RelocateEntry(descriptor));
       }
     }
   }
 
   if (sector_to_gc->valid_bytes != 0) {
-    ERR("Failed to relocate valid entries from sector being garbage collected");
+    ERR("  Failed to relocate valid entries from sector being garbage "
+        "collected, %hu valid bytes remain",
+        sector_to_gc->valid_bytes);
     return Status::INTERNAL;
   }
 
@@ -683,6 +702,7 @@
   TRY(partition_.Erase(SectorBaseAddress(sector_to_gc), 1));
   sector_to_gc->tail_free_bytes = partition_.sector_size_bytes();
 
+  DBG("  Garbage Collect complete");
   *sector = sector_to_gc;
   return Status::OK;
 }