Improved GC logging

3 files changed, 76 insertions, 30 deletions

diff --git a/zenstore/compactcas.cpp b/zenstore/compactcas.cpp
index 300420cea..5f335816c 100644
--- a/zenstore/compactcas.cpp
+++ b/zenstore/compactcas.cpp
@@ -935,18 +935,18 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	// after each new block is written and figuring out the path to the next new block.
 
 	ZEN_INFO("collecting garbage from '{}'", m_Config.RootDirectory / m_ContainerBaseName);
-	Stopwatch TotalTimer;
-	uint64_t  WriteBlockTimeUs		  = 0;
-	uint64_t  WriteBlockLongestTimeUs = 0;
-	uint64_t  ReadBlockTimeUs		  = 0;
-	uint64_t  ReadBlockLongestTimeUs  = 0;
-	uint64_t  TotalChunkCount		  = 0;
-	uint64_t  DeletedSize			  = 0;
-	uint64_t  OldTotalSize			  = m_TotalSize.load(std::memory_order::relaxed);
+	uint64_t WriteBlockTimeUs		 = 0;
+	uint64_t WriteBlockLongestTimeUs = 0;
+	uint64_t ReadBlockTimeUs		 = 0;
+	uint64_t ReadBlockLongestTimeUs	 = 0;
+	uint64_t TotalChunkCount		 = 0;
+	uint64_t DeletedSize			 = 0;
+	uint64_t OldTotalSize			 = m_TotalSize.load(std::memory_order::relaxed);
 
 	std::vector<IoHash> DeletedChunks;
 	uint64_t			MovedCount = 0;
 
+	Stopwatch  TotalTimer;
 	const auto _ = MakeGuard([this,
 							  &TotalTimer,
 							  &WriteBlockTimeUs,
@@ -957,9 +957,9 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 							  &DeletedChunks,
 							  &MovedCount,
 							  &DeletedSize,
-							  &OldTotalSize] {
+							  OldTotalSize] {
 		ZEN_INFO(
-			"garbage collect from '{}' DONE after {}, write lock: {} ({}), read lock: {} ({}), collected {} bytes, deleted {} and moved {} "
+			"garbage collect for '{}' DONE after {}, write lock: {} ({}), read lock: {} ({}), collected {} bytes, deleted {} and moved {} "
 			"of {} "
 			"chunks ({}).",
 			m_Config.RootDirectory / m_ContainerBaseName,
@@ -1082,7 +1082,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	if (!PerformDelete)
 	{
 		uint64_t TotalSize = m_TotalSize.load(std::memory_order_relaxed);
-		ZEN_INFO("garbage collect from '{}' DISABLED, found #{} {} chunks of total #{} {}",
+		ZEN_INFO("garbage collect for '{}' DISABLED, found #{} {} chunks of total #{} {}",
 				 m_Config.RootDirectory / m_ContainerBaseName,
 				 DeleteCount,
 				 NiceBytes(TotalSize - NewTotalSize),
@@ -1198,7 +1198,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 					std::filesystem::path GCReservePath = GetGCReservePath(m_Config.RootDirectory, m_ContainerBaseName);
 					if (!std::filesystem::is_regular_file(GCReservePath))
 					{
-						ZEN_INFO("garbage collect from '{}' FAILED, required disk space {}, free {}",
+						ZEN_INFO("garbage collect for '{}' FAILED, required disk space {}, free {}",
 								 m_Config.RootDirectory / m_ContainerBaseName,
 								 m_MaxBlockSize,
 								 NiceBytes(Space.Free));
@@ -1293,7 +1293,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	}
 	if (Space.Free < m_MaxBlockSize)
 	{
-		ZEN_INFO("not enough space for garbage collect reserve '{}' FAILED, required disk space {}, free {}",
+		ZEN_INFO("not enough space for garbage collect reserve for '{}' FAILED, required disk space {}, free {}",
 				 m_Config.RootDirectory / m_ContainerBaseName,
 				 m_MaxBlockSize,
 				 NiceBytes(Space.Free));
@@ -1304,17 +1304,17 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	GCReserveFile.Open(GCReservePath, BasicFile::EMode::kTruncate);
 	GCReserveFile.SetFileSize(m_MaxBlockSize);
 
-	ZEN_DEBUG("recreated garbage collect reserve '{}', {} bytes", m_Config.RootDirectory / m_ContainerBaseName, NiceBytes(Space.Free));
+	ZEN_DEBUG("recreated garbage collect reserve for '{}', {} bytes", m_Config.RootDirectory / m_ContainerBaseName, NiceBytes(Space.Free));
 }
 
 void
 CasContainerStrategy::MakeIndexSnapshot()
 {
-	ZEN_INFO("write store {} snapshot", m_Config.RootDirectory / m_ContainerBaseName);
+	ZEN_INFO("write store snapshot for '{}'", m_Config.RootDirectory / m_ContainerBaseName);
 	uint64_t   EntryCount = 0;
 	Stopwatch  Timer;
 	const auto _ = MakeGuard([this, &EntryCount, &Timer] {
-		ZEN_INFO("write store {} snapshot containing {} entries in {}",
+		ZEN_INFO("write store snapshot for '{}' containing {} entries in {}",
 				 m_Config.RootDirectory / m_ContainerBaseName,
 				 EntryCount,
 				 NiceTimeSpanMs(Timer.GetElapsedTimeMs()));
@@ -1552,7 +1552,7 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 					{
 						// Log removing unreferenced block
 						// Clear out unused blocks
-						ZEN_INFO("removing unused block in {} at {}", m_Config.RootDirectory / m_ContainerBaseName, Path);
+						ZEN_INFO("removing unused block for '{}' at '{}'", m_Config.RootDirectory / m_ContainerBaseName, Path);
 						std::error_code Ec;
 						std::filesystem::remove(Path, Ec);
 						if (Ec)
@@ -1594,7 +1594,7 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 		else
 		{
 			// We need it to be the proper size if we are to use it
-			ZEN_WARN("removing gc reserve {}, not enough space free on drive, need {}, have {} ",
+			ZEN_WARN("removing gc reserve for '{}', not enough space free on drive, need {}, have {} ",
 					 m_Config.RootDirectory / m_ContainerBaseName,
 					 NiceBytes(m_MaxBlockSize),
 					 NiceBytes(Space.Free));
@@ -1617,7 +1617,7 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 		}
 		else
 		{
-			ZEN_WARN("can't create gc reserve {}, not enough space free on drive, need {}, have {} ",
+			ZEN_WARN("can't create gc reserve for '{}', not enough space free on drive, need {}, have {} ",
 					 m_Config.RootDirectory / m_ContainerBaseName,
 					 NiceBytes(m_MaxBlockSize),
 					 NiceBytes(Space.Free));
diff --git a/zenstore/filecas.cpp b/zenstore/filecas.cpp
index 247f0806a..929a199af 100644
--- a/zenstore/filecas.cpp
+++ b/zenstore/filecas.cpp
@@ -12,6 +12,7 @@
 #include <zencore/testing.h>
 #include <zencore/testutils.h>
 #include <zencore/thread.h>
+#include <zencore/timer.h>
 #include <zencore/uid.h>
 #include <zenstore/basicfile.h>
 #include <zenstore/gc.h>
@@ -90,13 +91,30 @@ FileCasStrategy::Initialize(bool IsNewStore)
 
 	m_CasLog.Open(m_Config.RootDirectory / "cas.ulog", IsNewStore ? CasLogFile::EMode::kTruncate : CasLogFile::EMode::kWrite);
 
+	Stopwatch  Timer;
+	const auto _ = MakeGuard([this, &Timer] {
+		ZEN_INFO("read log {} containing {}", m_Config.RootDirectory / "cas.ulog", NiceBytes(m_TotalSize.load(std::memory_order::relaxed)));
+	});
+
+	std::unordered_set<IoHash> FoundEntries;
+	FoundEntries.reserve(10000);
 	m_CasLog.Replay([&](const FileCasIndexEntry& Entry) {
 		if (Entry.IsFlagSet(FileCasIndexEntry::kTombStone))
 		{
+			if (!FoundEntries.contains(Entry.Key))
+			{
+				return;
+			}
 			m_TotalSize.fetch_sub(Entry.Size, std::memory_order_relaxed);
+			FoundEntries.erase(Entry.Key);
 		}
 		else
 		{
+			if (FoundEntries.contains(Entry.Key))
+			{
+				return;
+			}
+			FoundEntries.insert(Entry.Key);
 			m_TotalSize.fetch_add(Entry.Size, std::memory_order_relaxed);
 		}
 	});
@@ -668,6 +686,20 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx)
 
 	std::vector<IoHash> CandidateCas;
 
+	uint64_t DeletedCount = 0;
+	uint64_t OldTotalSize = m_TotalSize.load(std::memory_order::relaxed);
+
+	Stopwatch  TotalTimer;
+	const auto _ = MakeGuard([this, &TotalTimer, &DeletedCount, &ChunkCount, OldTotalSize] {
+		ZEN_INFO("garbage collect for '{}' DONE after {}, deleted {} out of {} files, removed {} out of {}",
+				 m_Config.RootDirectory,
+				 NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()),
+				 DeletedCount,
+				 ChunkCount,
+				 NiceBytes(OldTotalSize - m_TotalSize.load(std::memory_order::relaxed)),
+				 NiceBytes(OldTotalSize));
+	});
+
 	IterateChunks([&](const IoHash& Hash, BasicFile& Payload) {
 		bool KeepThis = false;
 		CandidateCas.clear();
@@ -689,16 +721,17 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx)
 		ChunkBytes.fetch_add(FileSize);
 	});
 
-	ZEN_INFO("file CAS gc scanned: {} chunks ({})", ChunkCount.load(), NiceBytes(ChunkBytes));
-
 	if (ChunksToDelete.empty())
 	{
-		ZEN_INFO("nothing to delete");
-
+		ZEN_INFO("gc for '{}' SKIPPED, nothing to delete", m_Config.RootDirectory);
 		return;
 	}
 
-	ZEN_INFO("deleting file CAS garbage: {} chunks ({})", ChunksToDelete.size(), NiceBytes(ChunksToDeleteBytes));
+	ZEN_INFO("deleting file CAS garbage for '{}': {} out of {} chunks ({})",
+			 m_Config.RootDirectory,
+			 ChunksToDelete.size(),
+			 ChunkCount.load(),
+			 NiceBytes(ChunksToDeleteBytes));
 
 	if (GcCtx.IsDeletionMode() == false)
 	{
@@ -716,8 +749,10 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx)
 
 		if (Ec)
 		{
-			ZEN_WARN("failed to delete file for chunk {}: '{}'", Hash, Ec.message());
+			ZEN_WARN("gc for '{}' failed to delete file for chunk {}: '{}'", m_Config.RootDirectory, Hash, Ec.message());
+			continue;
 		}
+		DeletedCount++;
 	}
 
 	GcCtx.DeletedCas(ChunksToDelete);
diff --git a/zenstore/gc.cpp b/zenstore/gc.cpp
index 0f430f61c..dee8c209f 100644
--- a/zenstore/gc.cpp
+++ b/zenstore/gc.cpp
@@ -8,6 +8,7 @@
 #include <zencore/filesystem.h>
 #include <zencore/fmtutils.h>
 #include <zencore/logging.h>
+#include <zencore/scopeguard.h>
 #include <zencore/string.h>
 #include <zencore/testing.h>
 #include <zencore/testutils.h>
@@ -262,10 +263,13 @@ CasGc::CollectGarbage(GcContext& GcCtx)
 	RwLock::SharedLockScope _(m_Lock);
 
 	// First gather reference set
-
-	for (GcContributor* Contributor : m_GcContribs)
 	{
-		Contributor->GatherReferences(GcCtx);
+		Stopwatch  Timer;
+		const auto Guard = MakeGuard([this, &Timer] { ZEN_INFO("gathered references in {}", NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
+		for (GcContributor* Contributor : m_GcContribs)
+		{
+			Contributor->GatherReferences(GcCtx);
+		}
 	}
 
 	// Cache records reference CAS chunks with the uncompressed
@@ -300,15 +304,22 @@ CasGc::CollectGarbage(GcContext& GcCtx)
 
 	// Then trim storage
 
-	for (GcStorage* Storage : m_GcStorage)
 	{
-		Storage->CollectGarbage(GcCtx);
+		Stopwatch  Timer;
+		const auto Guard = MakeGuard([this, &Timer] { ZEN_INFO("collected garbage in {}", NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
+		for (GcStorage* Storage : m_GcStorage)
+		{
+			Storage->CollectGarbage(GcCtx);
+		}
 	}
 
 	// Remove Cid to CAS hash mappings. Scrub?
 
 	if (CidStore* CidStore = m_CidStore)
 	{
+		Stopwatch  Timer;
+		const auto Guard =
+			MakeGuard([this, &Timer] { ZEN_INFO("clean up deleted content ids in {}", NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
 		CidStore->RemoveCids(GcCtx.DeletedCas());
 	}
 }