Improved GC logging

1 files changed, 41 insertions, 6 deletions

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);