more timing measurements

1 files changed, 83 insertions, 45 deletions

diff --git a/zenstore/compactcas.cpp b/zenstore/compactcas.cpp
index 8076bbbde..b08475a12 100644
--- a/zenstore/compactcas.cpp
+++ b/zenstore/compactcas.cpp
@@ -182,6 +182,14 @@ namespace {
 		std::filesystem::path		   SidxPath = GetIndexPath(RootDirectory, ContainerBaseName);
 		if (std::filesystem::is_regular_file(SidxPath))
 		{
+			Stopwatch  Timer;
+			const auto _ = MakeGuard([RootDirectory, ContainerBaseName, &Entries, &Timer] {
+				ZEN_INFO("read store {} index containing {} entries in {}",
+						 RootDirectory / ContainerBaseName,
+						 Entries.size(),
+						 NiceTimeSpanMs(Timer.GetElapsedTimeMs()));
+			});
+
 			BasicFile ObjectIndexFile;
 			ObjectIndexFile.Open(SidxPath, BasicFile::EMode::kRead);
 			uint64_t Size = ObjectIndexFile.FileSize();
@@ -208,6 +216,14 @@ namespace {
 		std::filesystem::path		   SlogPath = GetLogPath(RootDirectory, ContainerBaseName);
 		if (std::filesystem::is_regular_file(SlogPath))
 		{
+			Stopwatch  Timer;
+			const auto _ = MakeGuard([RootDirectory, ContainerBaseName, &Entries, &Timer] {
+				ZEN_INFO("read store {} log containing {} entries in {}",
+						 RootDirectory / ContainerBaseName,
+						 Entries.size(),
+						 NiceTimeSpanMs(Timer.GetElapsedTimeMs()));
+			});
+
 			TCasLogFile<CasDiskIndexEntry> CasLog;
 			CasLog.Open(SlogPath, CasLogFile::EMode::kRead);
 			CasLog.Replay([&](const CasDiskIndexEntry& Record) { Entries.push_back(Record); });
@@ -232,7 +248,7 @@ namespace {
 		uint32_t   NewBlockIndex	  = 0;
 		Stopwatch  MigrationTimer;
 		uint64_t   TotalSize = 0;
-		const auto Guard = MakeGuard([RootPath, ContainerBaseName, &MigrationTimer, &MigratedChunkCount, &MigratedBlockCount, &TotalSize] {
+		const auto _ = MakeGuard([RootPath, ContainerBaseName, &MigrationTimer, &MigratedChunkCount, &MigratedBlockCount, &TotalSize] {
 			ZEN_INFO("migrated store {} to {} chunks in {} blocks in {} ({})",
 					 RootPath / ContainerBaseName,
 					 MigratedChunkCount,
@@ -274,23 +290,32 @@ namespace {
 
 		TCasLogFile<LegacyCasDiskIndexEntry> LegacyCasLog;
 		LegacyCasLog.Open(LegacyLogPath, CleanSource ? CasLogFile::EMode::kWrite : CasLogFile::EMode::kRead);
-		LegacyCasLog.Replay([&](const LegacyCasDiskIndexEntry& Record) {
-			if (Record.Flags & LegacyCasDiskIndexEntry::kTombstone)
-			{
-				LegacyDiskIndex.erase(Record.Key);
-				return;
-			}
-			uint64_t EntryEnd = Record.Location.GetOffset() + Record.Location.GetSize();
-			if (EntryEnd > FileSize)
-			{
-				return;
-			}
-			if (ExistingChunks.contains(Record.Key))
-			{
-				return;
-			}
-			LegacyDiskIndex[Record.Key] = Record;
-		});
+		{
+			Stopwatch  Timer;
+			const auto __ = MakeGuard([RootPath, ContainerBaseName, &LegacyDiskIndex, &Timer] {
+				ZEN_INFO("read store {} legacy index containing {} entries in {}",
+						 RootPath / ContainerBaseName,
+						 LegacyDiskIndex.size(),
+						 NiceTimeSpanMs(Timer.GetElapsedTimeMs()));
+			});
+			LegacyCasLog.Replay([&](const LegacyCasDiskIndexEntry& Record) {
+				if (Record.Flags & LegacyCasDiskIndexEntry::kTombstone)
+				{
+					LegacyDiskIndex.erase(Record.Key);
+					return;
+				}
+				uint64_t EntryEnd = Record.Location.GetOffset() + Record.Location.GetSize();
+				if (EntryEnd > FileSize)
+				{
+					return;
+				}
+				if (ExistingChunks.contains(Record.Key))
+				{
+					return;
+				}
+				LegacyDiskIndex[Record.Key] = Record;
+			});
+		}
 
 		if (LegacyDiskIndex.empty())
 		{
@@ -445,19 +470,23 @@ namespace {
 				BlockRanges.push_back(
 					{.Chunks = std::move(Chunks), .BlockOffset = BlockOffset, .BlockSize = BlockSize, .BlockIndex = WriteBlockIndex});
 			}
+			Stopwatch WriteBlockTimer;
 
 			std::reverse(BlockRanges.begin(), BlockRanges.end());
 			std::vector<std::uint8_t> Buffer(1 << 28);
 			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 {} ({})",
+				ZEN_INFO("migrating store {} {}/{} blocks, remaining {} ({}) ETA: {}",
 						 RootPath / ContainerBaseName,
 						 Idx,
 						 BlockRanges.size(),
 						 NiceBytes(BlockRange.BlockOffset),
-						 NiceBytes(TotalSize));
+						 NiceBytes(TotalSize),
+						 NiceTimeSpanMs(ETA));
 
 				auto		   BlockPath = GetBlockPath(BlocksBasePath, BlockRange.BlockIndex);
 				BlockStoreFile ChunkBlock(BlockPath);
@@ -555,10 +584,10 @@ CasContainerStrategy::InsertChunk(const void* ChunkData, size_t ChunkSize, const
 	std::shared_ptr<BlockStoreFile> WriteBlock;
 	uint64_t						InsertOffset;
 	{
-		RwLock::ExclusiveLockScope _i(m_InsertLock);
+		RwLock::ExclusiveLockScope _(m_InsertLock);
 
 		{
-			RwLock::SharedLockScope _l(m_LocationMapLock);
+			RwLock::SharedLockScope __(m_LocationMapLock);
 			if (m_LocationMap.contains(ChunkHash))
 			{
 				return CasStore::InsertResult{.New = false};
@@ -849,15 +878,15 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	std::vector<IoHash> DeletedChunks;
 	uint64_t			MovedCount = 0;
 
-	const auto Guard = MakeGuard([this,
-								  &TotalTimer,
-								  &WriteBlockTimeUs,
-								  &ReadBlockTimeUs,
-								  &TotalChunkCount,
-								  &DeletedChunks,
-								  &MovedCount,
-								  &DeletedSize,
-								  &OldTotalSize] {
+	const auto _ = MakeGuard([this,
+							  &TotalTimer,
+							  &WriteBlockTimeUs,
+							  &ReadBlockTimeUs,
+							  &TotalChunkCount,
+							  &DeletedChunks,
+							  &MovedCount,
+							  &DeletedSize,
+							  &OldTotalSize] {
 		ZEN_INFO(
 			"garbage collect from '{}' DONE after {} (write lock: {}, read lock: {}), collected {} bytes, deleted {} and moved {} of {} "
 			"chunks ({}).",
@@ -876,10 +905,10 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	size_t		  BlockCount;
 	uint64_t	  ExcludeBlockIndex = 0x800000000ull;
 	{
-		RwLock::SharedLockScope _i(m_InsertLock);
-		RwLock::SharedLockScope _l(m_LocationMapLock);
+		RwLock::SharedLockScope __(m_InsertLock);
+		RwLock::SharedLockScope ___(m_LocationMapLock);
 		Stopwatch				Timer;
-		const auto				TimerGuard = MakeGuard([&Timer, &WriteBlockTimeUs] { WriteBlockTimeUs += Timer.GetElapsedTimeUs(); });
+		const auto				____ = MakeGuard([&Timer, &WriteBlockTimeUs] { WriteBlockTimeUs += Timer.GetElapsedTimeUs(); });
 		if (m_WriteBlock)
 		{
 			ExcludeBlockIndex = m_WriteBlockIndex.load(std::memory_order_acquire);
@@ -1008,7 +1037,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 			{
 				RwLock::ExclusiveLockScope _i(m_LocationMapLock);
 				Stopwatch				   Timer;
-				const auto TimerGuard = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+				const auto				   __ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
 				UpdateLocations(LogEntries);
 				m_ChunkBlocks[BlockIndex].reset();
 			}
@@ -1039,9 +1068,9 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 				auto	 LogEntries		= MakeCasDiskEntries(MovedBlockChunks, {});
 				m_CasLog.Append(LogEntries);
 				{
-					RwLock::ExclusiveLockScope _l(m_LocationMapLock);
+					RwLock::ExclusiveLockScope __(m_LocationMapLock);
 					Stopwatch				   Timer;
-					const auto TimerGuard = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+					const auto				   ___ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
 					UpdateLocations(LogEntries);
 					if (m_ChunkBlocks.size() == BlockStoreDiskLocation::MaxBlockIndex)
 					{
@@ -1081,7 +1110,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 								 NiceBytes(Space.Free));
 						RwLock::ExclusiveLockScope _l(m_LocationMapLock);
 						Stopwatch				   Timer;
-						const auto TimerGuard = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+						const auto __ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
 						m_ChunkBlocks.erase(NextBlockIndex);
 						return;
 					}
@@ -1113,9 +1142,9 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 		auto		LogEntries = MakeCasDiskEntries(MovedBlockChunks, DeleteMap);
 		m_CasLog.Append(LogEntries);
 		{
-			RwLock::ExclusiveLockScope _i(m_LocationMapLock);
+			RwLock::ExclusiveLockScope __(m_LocationMapLock);
 			Stopwatch				   Timer;
-			const auto				   TimerGuard = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
+			const auto				   ___ = MakeGuard([&Timer, &ReadBlockTimeUs] { ReadBlockTimeUs += Timer.GetElapsedTimeUs(); });
 			UpdateLocations(LogEntries);
 			m_ChunkBlocks[BlockIndex].reset();
 		}
@@ -1172,7 +1201,15 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 void
 CasContainerStrategy::MakeIndexSnapshot()
 {
-	ZEN_INFO("writing index snapshot for '{}'", m_Config.RootDirectory / m_ContainerBaseName);
+	ZEN_INFO("write store {} snapshot", 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 {}",
+				 m_Config.RootDirectory / m_ContainerBaseName,
+				 EntryCount,
+				 NiceTimeSpanMs(Timer.GetElapsedTimeMs()));
+	});
 
 	namespace fs = std::filesystem;
 
@@ -1194,8 +1231,8 @@ CasContainerStrategy::MakeIndexSnapshot()
 
 	// Move cas away, we keep it if something goes wrong, any new chunks will be added to the new log
 	{
-		RwLock::ExclusiveLockScope _(m_InsertLock);
-		RwLock::ExclusiveLockScope __(m_LocationMapLock);
+		RwLock::ExclusiveLockScope __(m_InsertLock);
+		RwLock::ExclusiveLockScope ___(m_LocationMapLock);
 		m_CasLog.Close();
 
 		if (fs::is_regular_file(STmplogPath))
@@ -1215,7 +1252,7 @@ CasContainerStrategy::MakeIndexSnapshot()
 		std::vector<CasDiskIndexEntry> Entries;
 
 		{
-			RwLock::SharedLockScope _l(m_LocationMapLock);
+			RwLock::SharedLockScope __(m_LocationMapLock);
 			Entries.resize(m_LocationMap.size());
 
 			uint64_t EntryIndex = 0;
@@ -1233,13 +1270,14 @@ CasContainerStrategy::MakeIndexSnapshot()
 		ObjectIndexFile.Write(&Header, sizeof(CasDiskIndexEntry), 0);
 		ObjectIndexFile.Write(Entries.data(), Entries.size() * sizeof(CasDiskIndexEntry), sizeof(CasDiskIndexEntry));
 		ObjectIndexFile.Close();
+		EntryCount = Entries.size();
 	}
 	catch (std::exception& Err)
 	{
 		ZEN_ERROR("snapshot FAILED, reason '{}'", Err.what());
 
 		// Reconstruct the log from old log and any added log entries
-		RwLock::ExclusiveLockScope _(m_LocationMapLock);
+		RwLock::ExclusiveLockScope __(m_LocationMapLock);
 		if (fs::is_regular_file(STmplogPath))
 		{
 			std::vector<CasDiskIndexEntry> Records;