improved logging for gc/migration

3 files changed, 80 insertions, 27 deletions

diff --git a/zenserver/cache/structuredcachestore.cpp b/zenserver/cache/structuredcachestore.cpp
index 10a19f949..95e9e2dba 100644
--- a/zenserver/cache/structuredcachestore.cpp
+++ b/zenserver/cache/structuredcachestore.cpp
@@ -59,7 +59,11 @@ SaveCompactBinaryObject(const fs::path& Path, const CbObject& Object)
 	WriteFile(Path, Object.GetBuffer().AsIoBuffer());
 }
 
-ZenCacheStore::ZenCacheStore(CasGc& Gc, const std::filesystem::path& RootDir) : GcStorage(Gc), GcContributor(Gc), m_DiskLayer(RootDir)
+ZenCacheStore::ZenCacheStore(CasGc& Gc, const std::filesystem::path& RootDir)
+: m_RootDir(RootDir)
+, GcStorage(Gc)
+, GcContributor(Gc)
+, m_DiskLayer(RootDir)
 {
 	ZEN_INFO("initializing structured cache at '{}'", RootDir);
 	CreateDirectories(RootDir);
@@ -188,6 +192,9 @@ ZenCacheStore::Scrub(ScrubContext& Ctx)
 void
 ZenCacheStore::GatherReferences(GcContext& GcCtx)
 {
+	Stopwatch  Timer;
+	const auto Guard = MakeGuard([this, &Timer] { ZEN_INFO("cache gathered all references from '{}' in {}", m_RootDir, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
+
 	access_tracking::AccessTimes AccessTimes;
 	m_MemLayer.GatherAccessTimes(AccessTimes);
 
@@ -757,6 +764,10 @@ ZenCacheDiskLayer::CacheBucket::GatherReferences(GcContext& GcCtx)
 {
 	ZEN_TRACE_CPU("Z$::DiskLayer::CacheBucket::GatherReferences");
 
+	Stopwatch  Timer;
+	const auto Guard = MakeGuard(
+		[this, &Timer] { ZEN_INFO("gathered references from '{}' in {}", m_BucketDir, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
+
 	const GcClock::TimePoint ExpireTime =
 		GcCtx.MaxCacheDuration() == GcClock::Duration::max() ? GcClock::TimePoint::min() : GcCtx.Time() - GcCtx.MaxCacheDuration();
 
diff --git a/zenserver/projectstore.cpp b/zenserver/projectstore.cpp
index f916b2250..6b18bce3f 100644
--- a/zenserver/projectstore.cpp
+++ b/zenserver/projectstore.cpp
@@ -8,6 +8,7 @@
 #include <zencore/filesystem.h>
 #include <zencore/fmtutils.h>
 #include <zencore/logging.h>
+#include <zencore/scopeguard.h>
 #include <zencore/stream.h>
 #include <zencore/string.h>
 #include <zencore/testing.h>
@@ -970,6 +971,11 @@ ProjectStore::Scrub(ScrubContext& Ctx)
 void
 ProjectStore::GatherReferences(GcContext& GcCtx)
 {
+	Stopwatch  Timer;
+	const auto Guard = MakeGuard([this, &Timer] {
+		ZEN_INFO("project store gathered all references in {}", NiceTimeSpanMs(Timer.GetElapsedTimeMs()));
+	});
+
 	DiscoverProjects();
 
 	RwLock::SharedLockScope _(m_ProjectsLock);
diff --git a/zenstore/compactcas.cpp b/zenstore/compactcas.cpp
index 5628ce8c2..9461d7d3a 100644
--- a/zenstore/compactcas.cpp
+++ b/zenstore/compactcas.cpp
@@ -292,6 +292,8 @@ namespace {
 													 bool											   CleanSource,
 													 const std::unordered_set<IoHash, IoHash::Hasher>& ExistingChunks)
 	{
+		ZEN_INFO("migrating store {}", RootPath / ContainerBaseName);
+
 		std::filesystem::path BlocksBasePath = GetBlocksBasePath(RootPath, ContainerBaseName);
 		std::filesystem::path LegacyLogPath	 = GetLegacyLogPath(RootPath, ContainerBaseName);
 		std::filesystem::path LegacySobsPath = GetLegacyUcasPath(RootPath, ContainerBaseName);
@@ -532,16 +534,20 @@ namespace {
 			for (size_t Idx = 0; Idx < BlockRanges.size(); ++Idx)
 			{
 				const BlockData& BlockRange = BlockRanges[Idx];
-				uint64_t		 MSPerBlock = Idx > 0 ? (WriteBlockTimer.GetElapsedTimeMs() / Idx) : 10000;
-				uint64_t		 ETA		= (BlockRanges.size() - Idx) * MSPerBlock;
-
-				ZEN_INFO("migrating store {} {}/{} blocks, remaining {} ({}) ETA: {}",
-						 RootPath / ContainerBaseName,
-						 Idx,
-						 BlockRanges.size(),
-						 NiceBytes(BlockRange.BlockOffset),
-						 NiceBytes(TotalSize),
-						 NiceTimeSpanMs(ETA));
+				if (Idx > 0)
+				{
+					uint64_t Remaining = BlockRange.BlockOffset + BlockRange.BlockSize;
+					uint64_t Completed = BlockOffset + BlockSize - Remaining;
+					uint64_t ETA	   = (WriteBlockTimer.GetElapsedTimeMs() * Remaining) / Completed;
+
+					ZEN_INFO("migrating store {} {}/{} blocks, remaining {} ({}) ETA: {}",
+							 RootPath / ContainerBaseName,
+							 Idx,
+							 BlockRanges.size(),
+							 NiceBytes(BlockRange.BlockOffset + BlockRange.BlockSize),
+							 NiceBytes(BlockOffset + BlockSize),
+							 NiceTimeSpanMs(ETA));
+				}
 
 				std::filesystem::path BlockPath = GetBlockPath(BlocksBasePath, BlockRange.BlockIndex);
 				BlockStoreFile		  ChunkBlock(BlockPath);
@@ -929,11 +935,13 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 
 	ZEN_INFO("collecting garbage from '{}'", m_Config.RootDirectory / m_ContainerBaseName);
 	Stopwatch TotalTimer;
-	uint64_t  WriteBlockTimeUs = 0;
-	uint64_t  ReadBlockTimeUs  = 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;
@@ -941,19 +949,24 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	const auto _ = MakeGuard([this,
 							  &TotalTimer,
 							  &WriteBlockTimeUs,
+							  &WriteBlockLongestTimeUs,
 							  &ReadBlockTimeUs,
+							  &ReadBlockLongestTimeUs,
 							  &TotalChunkCount,
 							  &DeletedChunks,
 							  &MovedCount,
 							  &DeletedSize,
 							  &OldTotalSize] {
 		ZEN_INFO(
-			"garbage collect from '{}' DONE after {} (write lock: {}, read lock: {}), collected {} bytes, deleted {} and moved {} of {} "
+			"garbage collect from '{}' DONE after {}, write lock: {} ({}), read lock: {} ({}), collected {} bytes, deleted {} and moved {} "
+			"of {} "
 			"chunks ({}).",
 			m_Config.RootDirectory / m_ContainerBaseName,
 			NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()),
-			NiceTimeSpanMs(WriteBlockTimeUs / 1000),
-			NiceTimeSpanMs(ReadBlockTimeUs / 1000),
+			NiceLatencyNs(WriteBlockTimeUs),
+			NiceLatencyNs(WriteBlockLongestTimeUs),
+			NiceLatencyNs(ReadBlockTimeUs),
+			NiceLatencyNs(ReadBlockLongestTimeUs),
 			NiceBytes(DeletedSize),
 			DeletedChunks.size(),
 			MovedCount,
@@ -967,11 +980,18 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	{
 		RwLock::SharedLockScope __(m_InsertLock);
 		RwLock::SharedLockScope ___(m_LocationMapLock);
-		Stopwatch				Timer;
-		const auto				____ = MakeGuard([&Timer, &WriteBlockTimeUs] { WriteBlockTimeUs += Timer.GetElapsedTimeUs(); });
-		if (m_WriteBlock)
 		{
-			ExcludeBlockIndex = m_WriteBlockIndex.load(std::memory_order_acquire);
+			Stopwatch  Timer;
+			const auto ____ = MakeGuard([&Timer, &WriteBlockTimeUs, &WriteBlockLongestTimeUs] {
+				uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
+				WriteBlockTimeUs += ElapsedUs;
+				WriteBlockLongestTimeUs = std::max(ElapsedUs, WriteBlockLongestTimeUs);
+			});
+			if (m_WriteBlock)
+			{
+				ExcludeBlockIndex = m_WriteBlockIndex.load(std::memory_order_acquire);
+			}
+			__.ReleaseNow();
 		}
 		LocationMap = m_LocationMap;
 		BlockCount	= m_ChunkBlocks.size();
@@ -1098,7 +1118,11 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 			{
 				RwLock::ExclusiveLockScope _i(m_LocationMapLock);
 				Stopwatch				   Timer;
-				const auto				   __ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+				const auto				   __ = MakeGuard([&Timer, &ReadBlockTimeUs, &ReadBlockLongestTimeUs] {
+					uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
+					ReadBlockTimeUs += ElapsedUs;
+					ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
+				});
 				UpdateLocations(LogEntries);
 				m_ChunkBlocks[BlockIndex] = nullptr;
 			}
@@ -1131,7 +1155,11 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 				{
 					RwLock::ExclusiveLockScope __(m_LocationMapLock);
 					Stopwatch				   Timer;
-					const auto				   ___ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+					const auto				   ___ = MakeGuard([&Timer, &ReadBlockTimeUs, &ReadBlockLongestTimeUs] {
+						uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
+						ReadBlockTimeUs += ElapsedUs;
+						ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
+					});
 					UpdateLocations(LogEntries);
 					if (m_ChunkBlocks.size() == BlockStoreDiskLocation::MaxBlockIndex)
 					{
@@ -1170,7 +1198,11 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 								 NiceBytes(Space.Free));
 						RwLock::ExclusiveLockScope _l(m_LocationMapLock);
 						Stopwatch				   Timer;
-						const auto __ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+						const auto				   __ = MakeGuard([&Timer, &ReadBlockTimeUs, &ReadBlockLongestTimeUs] {
+							uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
+							ReadBlockTimeUs += ElapsedUs;
+							ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
+						});
 						m_ChunkBlocks.erase(NextBlockIndex);
 						return;
 					}
@@ -1205,7 +1237,11 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 		{
 			RwLock::ExclusiveLockScope __(m_LocationMapLock);
 			Stopwatch				   Timer;
-			const auto				   ___ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+			const auto				   ___ = MakeGuard([&Timer, &ReadBlockTimeUs, &ReadBlockLongestTimeUs] {
+				uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
+				ReadBlockTimeUs += ElapsedUs;
+				ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
+			});
 			UpdateLocations(LogEntries);
 			m_ChunkBlocks[BlockIndex] = nullptr;
 		}