add more trace scopes (#362)

* more trace scopes
* Make sure ReplayLogEntries uses the correct size for oplog buffer
* changelog

6 files changed, 150 insertions, 114 deletions

diff --git a/src/zenstore/blockstore.cpp b/src/zenstore/blockstore.cpp
index cdd7abae7..a16dd4539 100644
--- a/src/zenstore/blockstore.cpp
+++ b/src/zenstore/blockstore.cpp
@@ -66,6 +66,8 @@ BlockStoreFile::Open()
 void
 BlockStoreFile::Create(uint64_t InitialSize)
 {
+	ZEN_TRACE_CPU("BlockStoreFile::Create");
+
 	auto ParentPath = m_Path.parent_path();
 	if (!std::filesystem::is_directory(ParentPath))
 	{
@@ -118,12 +120,14 @@ BlockStoreFile::Read(void* Data, uint64_t Size, uint64_t FileOffset)
 void
 BlockStoreFile::Write(const void* Data, uint64_t Size, uint64_t FileOffset)
 {
+	ZEN_TRACE_CPU("BlockStoreFile::Write");
 	m_File.Write(Data, Size, FileOffset);
 }
 
 void
 BlockStoreFile::Flush()
 {
+	ZEN_TRACE_CPU("BlockStoreFile::Flush");
 	m_File.Flush();
 }
 
@@ -335,6 +339,7 @@ BlockStore::GetReclaimSnapshotState()
 IoBuffer
 BlockStore::TryGetChunk(const BlockStoreLocation& Location) const
 {
+	ZEN_TRACE_CPU("BlockStore::TryGetChunk");
 	RwLock::SharedLockScope InsertLock(m_InsertLock);
 	if (auto BlockIt = m_ChunkBlocks.find(Location.BlockIndex); BlockIt != m_ChunkBlocks.end())
 	{
@@ -499,6 +504,8 @@ BlockStore::ReclaimSpace(const ReclaimSnapshotState&			Snapshot,
 	Ref<BlockStoreFile> NewBlockFile;
 	try
 	{
+		ZEN_TRACE_CPU("BlockStore::ReclaimSpace::Compact");
+
 		uint64_t WriteOffset   = 0;
 		uint32_t NewBlockIndex = 0;
 		for (uint32_t BlockIndex : BlocksToReWrite)
@@ -523,6 +530,8 @@ BlockStore::ReclaimSpace(const ReclaimSnapshotState&			Snapshot,
 			ChunkIndexArray& KeepMap = BlockKeepChunks[ChunkMapIndex];
 			if (KeepMap.empty())
 			{
+				ZEN_TRACE_CPU("BlockStore::ReclaimSpace::DeleteBlock");
+
 				const ChunkIndexArray& DeleteMap = BlockDeleteChunks[ChunkMapIndex];
 				for (size_t DeleteIndex : DeleteMap)
 				{
@@ -561,99 +570,102 @@ BlockStore::ReclaimSpace(const ReclaimSnapshotState&			Snapshot,
 				KeepMap.clear();
 			}
 
-			MovedChunksArray	 MovedChunks;
-			std::vector<uint8_t> Chunk;
-			for (const size_t& ChunkIndex : KeepMap)
+			MovedChunksArray MovedChunks;
 			{
-				const BlockStoreLocation ChunkLocation = ChunkLocations[ChunkIndex];
-				Chunk.resize(ChunkLocation.Size);
-				OldBlockFile->Read(Chunk.data(), Chunk.size(), ChunkLocation.Offset);
-
-				if (!NewBlockFile || (WriteOffset + Chunk.size() > m_MaxBlockSize))
+				ZEN_TRACE_CPU("BlockStore::ReclaimSpace::MoveBlock");
+				std::vector<uint8_t> Chunk;
+				for (const size_t& ChunkIndex : KeepMap)
 				{
-					uint32_t NextBlockIndex = m_WriteBlockIndex.load(std::memory_order_relaxed);
+					const BlockStoreLocation ChunkLocation = ChunkLocations[ChunkIndex];
+					Chunk.resize(ChunkLocation.Size);
+					OldBlockFile->Read(Chunk.data(), Chunk.size(), ChunkLocation.Offset);
 
-					if (NewBlockFile)
+					if (!NewBlockFile || (WriteOffset + Chunk.size() > m_MaxBlockSize))
 					{
-						NewBlockFile->Flush();
-						NewBlockFile = nullptr;
-					}
-					{
-						ChangeCallback(MovedChunks, {});
-						MovedCount += KeepMap.size();
-						MovedChunks.clear();
-						RwLock::ExclusiveLockScope __(m_InsertLock);
-						Stopwatch				   Timer;
-						const auto				   ___ = MakeGuard([&] {
-							uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
-							ReadBlockTimeUs += ElapsedUs;
-							ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
-						});
-						if (m_ChunkBlocks.size() == m_MaxBlockCount)
-						{
-							ZEN_ERROR("unable to allocate a new block in '{}', count limit {} exeeded",
-									  m_BlocksBasePath,
-									  static_cast<uint64_t>(std::numeric_limits<uint32_t>::max()) + 1);
-							return;
-						}
-						while (m_ChunkBlocks.contains(NextBlockIndex))
+						uint32_t NextBlockIndex = m_WriteBlockIndex.load(std::memory_order_relaxed);
+
+						if (NewBlockFile)
 						{
-							NextBlockIndex = (NextBlockIndex + 1) & (m_MaxBlockCount - 1);
+							NewBlockFile->Flush();
+							NewBlockFile = nullptr;
 						}
-						std::filesystem::path NewBlockPath = GetBlockPath(m_BlocksBasePath, NextBlockIndex);
-						NewBlockFile					   = new BlockStoreFile(NewBlockPath);
-						m_ChunkBlocks[NextBlockIndex]	   = NewBlockFile;
-					}
-
-					std::error_code Error;
-					DiskSpace		Space = DiskSpaceInfo(m_BlocksBasePath, Error);
-					if (Error)
-					{
-						ZEN_ERROR("get disk space in '{}' FAILED, reason: '{}'", m_BlocksBasePath, Error.message());
-						return;
-					}
-					if (Space.Free < m_MaxBlockSize)
-					{
-						uint64_t ReclaimedSpace = DiskReserveCallback();
-						if (Space.Free + ReclaimedSpace < m_MaxBlockSize)
 						{
-							ZEN_WARN("garbage collect for '{}' FAILED, required disk space {}, free {}",
-									 m_BlocksBasePath,
-									 m_MaxBlockSize,
-									 NiceBytes(Space.Free + ReclaimedSpace));
-							RwLock::ExclusiveLockScope _l(m_InsertLock);
+							ChangeCallback(MovedChunks, {});
+							MovedCount += KeepMap.size();
+							MovedChunks.clear();
+							RwLock::ExclusiveLockScope __(m_InsertLock);
 							Stopwatch				   Timer;
-							const auto				   __ = MakeGuard([&] {
+							const auto				   ___ = MakeGuard([&] {
 								uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
 								ReadBlockTimeUs += ElapsedUs;
 								ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
 							});
-							ZEN_ASSERT(m_ChunkBlocks[NextBlockIndex] == NewBlockFile);
-							m_ChunkBlocks.erase(NextBlockIndex);
-							NewBlockFile->MarkAsDeleteOnClose();
-							return;
+							if (m_ChunkBlocks.size() == m_MaxBlockCount)
+							{
+								ZEN_ERROR("unable to allocate a new block in '{}', count limit {} exeeded",
+										  m_BlocksBasePath,
+										  static_cast<uint64_t>(std::numeric_limits<uint32_t>::max()) + 1);
+								return;
+							}
+							while (m_ChunkBlocks.contains(NextBlockIndex))
+							{
+								NextBlockIndex = (NextBlockIndex + 1) & (m_MaxBlockCount - 1);
+							}
+							std::filesystem::path NewBlockPath = GetBlockPath(m_BlocksBasePath, NextBlockIndex);
+							NewBlockFile					   = new BlockStoreFile(NewBlockPath);
+							m_ChunkBlocks[NextBlockIndex]	   = NewBlockFile;
 						}
 
-						ZEN_INFO("using gc reserve for '{}', reclaimed {}, disk free {}",
-								 m_BlocksBasePath,
-								 ReclaimedSpace,
-								 NiceBytes(Space.Free + ReclaimedSpace));
+						std::error_code Error;
+						DiskSpace		Space = DiskSpaceInfo(m_BlocksBasePath, Error);
+						if (Error)
+						{
+							ZEN_ERROR("get disk space in '{}' FAILED, reason: '{}'", m_BlocksBasePath, Error.message());
+							return;
+						}
+						if (Space.Free < m_MaxBlockSize)
+						{
+							uint64_t ReclaimedSpace = DiskReserveCallback();
+							if (Space.Free + ReclaimedSpace < m_MaxBlockSize)
+							{
+								ZEN_WARN("garbage collect for '{}' FAILED, required disk space {}, free {}",
+										 m_BlocksBasePath,
+										 m_MaxBlockSize,
+										 NiceBytes(Space.Free + ReclaimedSpace));
+								RwLock::ExclusiveLockScope _l(m_InsertLock);
+								Stopwatch				   Timer;
+								const auto				   __ = MakeGuard([&] {
+									uint64_t ElapsedUs = Timer.GetElapsedTimeUs();
+									ReadBlockTimeUs += ElapsedUs;
+									ReadBlockLongestTimeUs = std::max(ElapsedUs, ReadBlockLongestTimeUs);
+								});
+								ZEN_ASSERT(m_ChunkBlocks[NextBlockIndex] == NewBlockFile);
+								m_ChunkBlocks.erase(NextBlockIndex);
+								NewBlockFile->MarkAsDeleteOnClose();
+								return;
+							}
+
+							ZEN_INFO("using gc reserve for '{}', reclaimed {}, disk free {}",
+									 m_BlocksBasePath,
+									 ReclaimedSpace,
+									 NiceBytes(Space.Free + ReclaimedSpace));
+						}
+						NewBlockFile->Create(m_MaxBlockSize);
+						NewBlockIndex = NextBlockIndex;
+						WriteOffset	  = 0;
 					}
-					NewBlockFile->Create(m_MaxBlockSize);
-					NewBlockIndex = NextBlockIndex;
-					WriteOffset	  = 0;
-				}
 
-				NewBlockFile->Write(Chunk.data(), Chunk.size(), WriteOffset);
-				MovedChunks.push_back({ChunkIndex, {.BlockIndex = NewBlockIndex, .Offset = WriteOffset, .Size = Chunk.size()}});
-				uint64_t OldOffset = WriteOffset;
-				WriteOffset		   = RoundUp(WriteOffset + Chunk.size(), PayloadAlignment);
-				m_TotalSize.fetch_add(WriteOffset - OldOffset, std::memory_order::relaxed);
-			}
-			Chunk.clear();
-			if (NewBlockFile)
-			{
-				NewBlockFile->Flush();
+					NewBlockFile->Write(Chunk.data(), Chunk.size(), WriteOffset);
+					MovedChunks.push_back({ChunkIndex, {.BlockIndex = NewBlockIndex, .Offset = WriteOffset, .Size = Chunk.size()}});
+					uint64_t OldOffset = WriteOffset;
+					WriteOffset		   = RoundUp(WriteOffset + Chunk.size(), PayloadAlignment);
+					m_TotalSize.fetch_add(WriteOffset - OldOffset, std::memory_order::relaxed);
+				}
+				Chunk.clear();
+				if (NewBlockFile)
+				{
+					NewBlockFile->Flush();
+				}
 			}
 
 			const ChunkIndexArray& DeleteMap = BlockDeleteChunks[ChunkMapIndex];
diff --git a/src/zenstore/cas.cpp b/src/zenstore/cas.cpp
index b98f01385..9446e2152 100644
--- a/src/zenstore/cas.cpp
+++ b/src/zenstore/cas.cpp
@@ -243,6 +243,8 @@ CasImpl::FindChunk(const IoHash& ChunkHash)
 bool
 CasImpl::ContainsChunk(const IoHash& ChunkHash)
 {
+	ZEN_TRACE_CPU("CAS::ContainsChunk");
+
 	return m_SmallStrategy.HaveChunk(ChunkHash) || m_TinyStrategy.HaveChunk(ChunkHash) || m_LargeStrategy.HaveChunk(ChunkHash);
 }
 
diff --git a/src/zenstore/compactcas.cpp b/src/zenstore/compactcas.cpp
index fe31ad759..63158f6de 100644
--- a/src/zenstore/compactcas.cpp
+++ b/src/zenstore/compactcas.cpp
@@ -147,6 +147,7 @@ CasContainerStrategy::Initialize(const std::filesystem::path& RootDirectory,
 CasStore::InsertResult
 CasContainerStrategy::InsertChunk(const void* ChunkData, size_t ChunkSize, const IoHash& ChunkHash)
 {
+	ZEN_TRACE_CPU("CasContainer::InsertChunk");
 	{
 		RwLock::SharedLockScope _(m_LocationMapLock);
 		if (m_LocationMap.contains(ChunkHash))
@@ -192,6 +193,8 @@ CasContainerStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash)
 IoBuffer
 CasContainerStrategy::FindChunk(const IoHash& ChunkHash)
 {
+	ZEN_TRACE_CPU("CasContainer::FindChunk");
+
 	RwLock::SharedLockScope _(m_LocationMapLock);
 	auto					KeyIt = m_LocationMap.find(ChunkHash);
 	if (KeyIt == m_LocationMap.end())
@@ -418,6 +421,8 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	LocationMap_t					 LocationMap;
 	BlockStore::ReclaimSnapshotState BlockStoreState;
 	{
+		ZEN_TRACE_CPU("CasContainer::CollectGarbage::State");
+
 		RwLock::SharedLockScope ___(m_LocationMapLock);
 		Stopwatch				Timer;
 		const auto				____ = MakeGuard([&Timer, &WriteBlockTimeUs, &WriteBlockLongestTimeUs] {
@@ -445,19 +450,22 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx)
 	KeepChunkIndexes.reserve(TotalChunkCount);
 	ChunkIndexToChunkHash.reserve(TotalChunkCount);
 
-	GcCtx.FilterCids(TotalChunkHashes, [&](const IoHash& ChunkHash, bool Keep) {
-		auto						  KeyIt		   = LocationMap.find(ChunkHash);
-		const BlockStoreDiskLocation& DiskLocation = KeyIt->second;
-		BlockStoreLocation			  Location	   = DiskLocation.Get(m_PayloadAlignment);
-		size_t						  ChunkIndex   = ChunkLocations.size();
-
-		ChunkLocations.push_back(Location);
-		ChunkIndexToChunkHash[ChunkIndex] = ChunkHash;
-		if (Keep)
-		{
-			KeepChunkIndexes.push_back(ChunkIndex);
-		}
-	});
+	{
+		ZEN_TRACE_CPU("CasContainer::CollectGarbage::Filter");
+		GcCtx.FilterCids(TotalChunkHashes, [&](const IoHash& ChunkHash, bool Keep) {
+			auto						  KeyIt		   = LocationMap.find(ChunkHash);
+			const BlockStoreDiskLocation& DiskLocation = KeyIt->second;
+			BlockStoreLocation			  Location	   = DiskLocation.Get(m_PayloadAlignment);
+			size_t						  ChunkIndex   = ChunkLocations.size();
+
+			ChunkLocations.push_back(Location);
+			ChunkIndexToChunkHash[ChunkIndex] = ChunkHash;
+			if (Keep)
+			{
+				KeepChunkIndexes.push_back(ChunkIndex);
+			}
+		});
+	}
 
 	const bool PerformDelete = GcCtx.IsDeletionMode() && GcCtx.CollectSmallObjects();
 	if (!PerformDelete)
diff --git a/src/zenstore/filecas.cpp b/src/zenstore/filecas.cpp
index 56a840701..ce0dd7ce6 100644
--- a/src/zenstore/filecas.cpp
+++ b/src/zenstore/filecas.cpp
@@ -241,7 +241,7 @@ FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::
 				return CasStore::InsertResult{.New = false};
 			}
 		}
-		return InsertChunk(Chunk.Data(), Chunk.Size(), ChunkHash);
+		return InsertChunkData(Chunk.Data(), Chunk.Size(), ChunkHash);
 	}
 
 	// File-based chunks have special case handling whereby we move the file into
@@ -251,6 +251,8 @@ FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::
 	bool				  IsWholeFile = Chunk.IsWholeFile();
 	if (IsWholeFile && Chunk.GetFileReference(/* out */ FileRef))
 	{
+		ZEN_TRACE_CPU("FileCas::InsertChunk::Move");
+
 		{
 			bool Exists = true;
 			{
@@ -271,6 +273,8 @@ FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::
 		const HANDLE ChunkFileHandle = FileRef.FileHandle;
 		// See if file already exists
 		{
+			ZEN_TRACE_CPU("FileCas::InsertChunk::Exists");
+
 			windows::FileHandle PayloadFile;
 
 			if (HRESULT hRes = PayloadFile.Create(Name.ShardedPath.c_str(), GENERIC_READ, FILE_SHARE_READ, OPEN_EXISTING); SUCCEEDED(hRes))
@@ -486,11 +490,11 @@ FileCasStrategy::InsertChunk(IoBuffer Chunk, const IoHash& ChunkHash, CasStore::
 #endif	// ZEN_PLATFORM_*
 	}
 
-	return InsertChunk(Chunk.Data(), Chunk.Size(), ChunkHash);
+	return InsertChunkData(Chunk.Data(), Chunk.Size(), ChunkHash);
 }
 
 CasStore::InsertResult
-FileCasStrategy::InsertChunk(const void* const ChunkData, const size_t ChunkSize, const IoHash& ChunkHash)
+FileCasStrategy::InsertChunkData(const void* const ChunkData, const size_t ChunkSize, const IoHash& ChunkHash)
 {
 	ZEN_TRACE_CPU("FileCas::InsertChunkData");
 
@@ -504,6 +508,8 @@ FileCasStrategy::InsertChunk(const void* const ChunkData, const size_t ChunkSize
 		}
 	}
 
+	ZEN_TRACE_CPU("FileCas::InsertChunkData::Write");
+
 	ShardingHelper Name(m_RootDirectory.c_str(), ChunkHash);
 
 	// See if file already exists
@@ -696,6 +702,8 @@ FileCasStrategy::InsertChunk(const void* const ChunkData, const size_t ChunkSize
 IoBuffer
 FileCasStrategy::FindChunk(const IoHash& ChunkHash)
 {
+	ZEN_TRACE_CPU("FileCas::FindChunk");
+
 	ZEN_ASSERT(m_IsInitialized);
 
 	{
@@ -706,8 +714,6 @@ FileCasStrategy::FindChunk(const IoHash& ChunkHash)
 		}
 	}
 
-	ZEN_TRACE_CPU("FileCas::FindChunk");
-
 	ShardingHelper Name(m_RootDirectory.c_str(), ChunkHash);
 
 	RwLock::SharedLockScope _(LockForHash(ChunkHash));
@@ -914,25 +920,28 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx)
 				  NiceBytes(OldTotalSize));
 	});
 
-	IterateChunks([&](const IoHash& Hash, IoBuffer&& Payload) {
-		bool KeepThis	= false;
-		CandidateCas[0] = Hash;
-		GcCtx.FilterCids(CandidateCas, [&](const IoHash& Hash) {
-			ZEN_UNUSED(Hash);
-			KeepThis = true;
-		});
-
-		const uint64_t FileSize = Payload.GetSize();
-
-		if (!KeepThis)
-		{
-			ChunksToDelete.push_back(Hash);
-			ChunksToDeleteBytes.fetch_add(FileSize);
-		}
+	{
+		ZEN_TRACE_CPU("FileCas::CollectGarbage::Filter");
+		IterateChunks([&](const IoHash& Hash, IoBuffer&& Payload) {
+			bool KeepThis	= false;
+			CandidateCas[0] = Hash;
+			GcCtx.FilterCids(CandidateCas, [&](const IoHash& Hash) {
+				ZEN_UNUSED(Hash);
+				KeepThis = true;
+			});
+
+			const uint64_t FileSize = Payload.GetSize();
+
+			if (!KeepThis)
+			{
+				ChunksToDelete.push_back(Hash);
+				ChunksToDeleteBytes.fetch_add(FileSize);
+			}
 
-		++ChunkCount;
-		ChunkBytes.fetch_add(FileSize);
-	});
+			++ChunkCount;
+			ChunkBytes.fetch_add(FileSize);
+		});
+	}
 
 	// TODO, any entires we did not encounter during our IterateChunks should be removed from the index
 
diff --git a/src/zenstore/filecas.h b/src/zenstore/filecas.h
index e4eab183a..d9186f05b 100644
--- a/src/zenstore/filecas.h
+++ b/src/zenstore/filecas.h
@@ -55,7 +55,7 @@ private:
 	};
 	using IndexMap = tsl::robin_map<IoHash, IndexEntry, IoHash::Hasher>;
 
-	CasStore::InsertResult InsertChunk(const void* ChunkData, size_t ChunkSize, const IoHash& ChunkHash);
+	CasStore::InsertResult InsertChunkData(const void* ChunkData, size_t ChunkSize, const IoHash& ChunkHash);
 
 	std::filesystem::path m_RootDirectory;
 	RwLock				  m_Lock;
diff --git a/src/zenstore/gc.cpp b/src/zenstore/gc.cpp
index 79aea2752..a3282dde6 100644
--- a/src/zenstore/gc.cpp
+++ b/src/zenstore/gc.cpp
@@ -399,6 +399,7 @@ GcManager::CollectGarbage(GcContext& GcCtx)
 
 	// First gather reference set
 	{
+		ZEN_TRACE_CPU("Gc::CollectGarbage::GatherReferences");
 		Stopwatch  Timer;
 		const auto Guard = MakeGuard([&] { ZEN_INFO("gathered references in {}", NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
 		for (GcContributor* Contributor : m_GcContribs)
@@ -409,6 +410,8 @@ GcManager::CollectGarbage(GcContext& GcCtx)
 
 	// Then trim storage
 	{
+		ZEN_TRACE_CPU("Gc::CollectGarbage::CollectGarbage");
+
 		GcStorageSize GCTotalSizeDiff;
 		Stopwatch	  Timer;
 		const auto	  Guard = MakeGuard([&] {
@@ -989,6 +992,8 @@ GcScheduler::CollectGarbage(const GcClock::TimePoint& CacheExpireTime,
 							bool					  Delete,
 							bool					  CollectSmallObjects)
 {
+	ZEN_TRACE_CPU("GcScheduler::CollectGarbage");
+
 	GcContext GcCtx(CacheExpireTime, ProjectStoreExpireTime);
 	GcCtx.SetDeletionMode(Delete);
 	GcCtx.CollectSmallObjects(CollectSmallObjects);