improved logging for gc/migration

1 files changed, 62 insertions, 26 deletions

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