Add timing stats to garbage collection

1 files changed, 64 insertions, 20 deletions

diff --git a/zenstore/compactcas.cpp b/zenstore/compactcas.cpp
index b951ac0b3..c08676b7a 100644
--- a/zenstore/compactcas.cpp
+++ b/zenstore/compactcas.cpp
@@ -8,6 +8,7 @@
 #include <zencore/filesystem.h>
 #include <zencore/fmtutils.h>
 #include <zencore/logging.h>
+#include <zencore/scopeguard.h>
 #include <zencore/workthreadpool.h>
 #include <gsl/gsl-lite.hpp>
 
@@ -394,11 +395,45 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	// path to the next new block.
 
 	ZEN_INFO("collecting garbage from '{}'", m_Config.RootDirectory / m_ContainerBaseName);
+	Stopwatch TotalTimer;
+	uint64_t  WriteBlockTimeUs = 0;
+	uint64_t  ReadBlockTimeUs  = 0;
+	uint64_t  TotalChunkCount  = {};
+	uint64_t  DeletedSize	   = 0;
+	uint64_t  OldTotalSize	   = m_TotalSize.load(std::memory_order::relaxed);
+
+	std::vector<IoHash> DeletedChunks;
+	std::vector<IoHash> MovedChunks;
+
+	const auto Guard = MakeGuard([this,
+								  &TotalTimer,
+								  &WriteBlockTimeUs,
+								  &ReadBlockTimeUs,
+								  &TotalChunkCount,
+								  &DeletedChunks,
+								  &MovedChunks,
+								  &DeletedSize,
+								  &OldTotalSize] {
+		ZEN_INFO(
+			"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),
+			NiceBytes(DeletedSize),
+			DeletedChunks.size(),
+			MovedChunks.size(),
+			TotalChunkCount,
+			NiceBytes(OldTotalSize));
+	});
+
 	std::unordered_map<IoHash, BlockStoreDiskLocation, IoHash::Hasher> LocationMap;
 	size_t															   BlockCount;
 	{
 		RwLock::SharedLockScope _i(m_InsertLock);
 		RwLock::SharedLockScope _l(m_LocationMapLock);
+		Stopwatch				Timer;
 		LocationMap.reserve(m_LocationMap.size());
 		bool	 IsWriting	  = !m_WriteBlock.expired();
 		uint32_t WritingBlock = m_WriteBlockIndex.load(std::memory_order_acquire);
@@ -411,6 +446,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 			LocationMap.emplace(Entry.first, Entry.second);
 		}
 		BlockCount = m_ChunkBlocks.size();
+		WriteBlockTimeUs += Timer.GetElapsedTimeUs();
 	}
 
 	if (LocationMap.empty())
@@ -419,7 +455,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 		return;
 	}
 
-	const uint64_t TotalChunkCount = LocationMap.size();
+	TotalChunkCount = LocationMap.size();
 
 	std::unordered_set<uint32_t>							BlocksToReWrite;
 	std::unordered_map<uint32_t, size_t>					BlockIndexToChunkMapIndex;
@@ -449,7 +485,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 		DeleteChunks.back().reserve(GuesstimateCountPerBlock);
 	}
 
-	uint64_t   DeleteCount	 = {};
+	uint64_t DeleteCount = {};
 
 	uint64_t NewTotalSize = 0;
 	GcCtx.FilterCas(TotalChunkHashes, [&](const IoHash& ChunkHash, bool Keep) {
@@ -489,8 +525,6 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	std::shared_ptr<BlockStoreFile> NewBlockFile;
 	uint64_t						WriteOffset	  = {};
 	uint32_t						NewBlockIndex = {};
-	std::vector<IoHash>				DeletedChunks;
-	std::vector<IoHash>				MovedChunks;
 	DeletedChunks.reserve(DeleteCount);
 
 	std::unordered_map<IoHash, BlockStoreDiskLocation> MovedBlockChunks;
@@ -504,8 +538,10 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 			const auto&						DeleteMap = DeleteChunks[ChunkMapIndex];
 			{
 				RwLock::ExclusiveLockScope _i(m_LocationMapLock);
+				Stopwatch				   Timer;
 				UpdateLocationMap({}, DeleteMap);
 				m_ChunkBlocks[BlockIndex].swap(BlockFile);
+				ReadBlockTimeUs += Timer.GetElapsedTimeUs();
 			}
 			DeletedChunks.insert(DeletedChunks.end(), DeleteMap.begin(), DeleteMap.end());
 			ZEN_DEBUG("marking cas store file for delete {}, block {}", m_ContainerBaseName, std::to_string(BlockIndex));
@@ -539,6 +575,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 				uint32_t NextBlockIndex = m_WriteBlockIndex.load(std::memory_order::memory_order_relaxed);
 				{
 					RwLock::ExclusiveLockScope _l(m_LocationMapLock);
+					Stopwatch				   Timer;
 					UpdateLocationMap(MovedBlockChunks, {});
 					if (m_ChunkBlocks.size() == BlockStoreDiskLocation::MaxBlockIndex)
 					{
@@ -554,6 +591,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 					auto NewBlockPath			  = BuildUcasPath(m_BlocksBasePath, NextBlockIndex);
 					NewBlockFile				  = std::make_shared<BlockStoreFile>(NewBlockPath);
 					m_ChunkBlocks[NextBlockIndex] = NewBlockFile;
+					ReadBlockTimeUs += Timer.GetElapsedTimeUs();
 				}
 
 				for (const auto& MovedEntry : MovedBlockChunks)
@@ -580,7 +618,9 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 								 m_MaxBlockSize,
 								 NiceBytes(Space.Free));
 						RwLock::ExclusiveLockScope _l(m_LocationMapLock);
+						Stopwatch				   Timer;
 						m_ChunkBlocks.erase(NextBlockIndex);
+						ReadBlockTimeUs += Timer.GetElapsedTimeUs();
 						return;
 					}
 
@@ -609,8 +649,10 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 		const auto& DeleteMap = DeleteChunks[ChunkMapIndex];
 		{
 			RwLock::ExclusiveLockScope _i(m_LocationMapLock);
+			Stopwatch				   Timer;
 			UpdateLocationMap(MovedBlockChunks, DeleteMap);
 			m_ChunkBlocks[BlockIndex].reset();
+			ReadBlockTimeUs += Timer.GetElapsedTimeUs();
 		}
 		for (const auto& MovedEntry : MovedBlockChunks)
 		{
@@ -629,13 +671,12 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 		OldBlockFile.reset();
 	}
 
-	GcCtx.DeletedCas(DeletedChunks);
+	for (const auto& ChunkHash : DeletedChunks)
+	{
+		DeletedSize += LocationMap[ChunkHash].GetSize();
+	}
 
-	ZEN_INFO("garbage collection complete '{}', deleted {} and moved {} of {} chunks",
-			 m_Config.RootDirectory / m_ContainerBaseName,
-			 DeletedChunks.size(),
-			 MovedChunks.size(),
-			 TotalChunkCount);
+	GcCtx.DeletedCas(DeletedChunks);
 
 	std::filesystem::path GCReservePath = m_Config.RootDirectory / (m_ContainerBaseName + ".gc.reserve.ucas");
 	if (std::filesystem::is_regular_file(GCReservePath))
@@ -662,9 +703,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	GCReserveFile.Open(GCReservePath, true);
 	GCReserveFile.SetFileSize(m_MaxBlockSize);
 
-	ZEN_DEBUG("recreated garbage collect reserve '{}' FAILED, {} bytes",
-			  m_Config.RootDirectory / m_ContainerBaseName,
-			  NiceBytes(Space.Free));
+	ZEN_DEBUG("recreated garbage collect reserve '{}', {} bytes", m_Config.RootDirectory / m_ContainerBaseName, NiceBytes(Space.Free));
 }
 
 void
@@ -864,7 +903,17 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 	{
 		if (std::filesystem::is_regular_file(LegacySobsPath))
 		{
-			ZEN_INFO("migrating store {} from {} to chunks", m_Config.RootDirectory / m_ContainerBaseName, LegacySobsPath);
+			uint32_t NewBlockIndex = {};
+			Stopwatch	   MigrationTimer;
+			uint64_t   TotalSize = 0;
+			const auto Guard = MakeGuard([this, &MigrationTimer, &NewBlockIndex, &TotalSize] {
+				ZEN_INFO("migrated store {} to {} chunks in {} ({})",
+					m_Config.RootDirectory / m_ContainerBaseName,
+					NewBlockIndex + 1,
+						NiceTimeSpanMs(MigrationTimer.GetElapsedTimeMs()),
+						 NiceBytes(TotalSize));
+			});
+
 			std::error_code Error;
 			DiskSpace		Space = DiskSpaceInfo(m_Config.RootDirectory, Error);
 			if (Error)
@@ -928,6 +977,7 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 			for (const auto& Entry : LegacyDiskIndex)
 			{
 				ChunkHashes.push_back(Entry.first);
+				TotalSize += Entry.second.Location.GetSize();
 			}
 			LegacyCasLog.Close();
 
@@ -942,7 +992,6 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 
 			std::unique_ptr<BlockStoreFile> NewBlockFile;
 			uint64_t						WriteOffset	  = {};
-			uint32_t						NewBlockIndex = {};
 
 			std::vector<uint8_t> Chunk;
 			for (const auto& ChunkHash : ChunkHashes)
@@ -976,8 +1025,6 @@ CasContainerStrategy::OpenContainer(bool IsNewStore)
 
 			BlockFile.Close();
 			std::filesystem::remove(LegacySobsPath);
-
-			ZEN_INFO("migrated store {} to {} to chunks", m_Config.RootDirectory / m_ContainerBaseName, NewBlockIndex + 1);
 			CasLogEmpty = false;
 		}
 
@@ -1250,9 +1297,6 @@ TEST_CASE("compactcas.compact.gc")
 
 			CHECK_EQ(Value["id"].AsInt32(), i);
 		}
-
-		GcContext Ctx;
-		Cas.CollectGarbage(Ctx);
 	}
 }