improved block store logging and more gcv2 tests (#659)

* improved gc/blockstore logging
* more gcv2 tests

1 files changed, 52 insertions, 16 deletions

diff --git a/src/zenstore/blockstore.cpp b/src/zenstore/blockstore.cpp
index 5bcb7f5b4..830ad9e55 100644
--- a/src/zenstore/blockstore.cpp
+++ b/src/zenstore/blockstore.cpp
@@ -1069,7 +1069,8 @@ void
 BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 						  uint32_t						  PayloadAlignment,
 						  const CompactCallback&		  ChangeCallback,
-						  const ClaimDiskReserveCallback& DiskReserveCallback)
+						  const ClaimDiskReserveCallback& DiskReserveCallback,
+						  std::string_view				  LogPrefix)
 {
 	ZEN_TRACE_CPU("BlockStore::CompactBlocks");
 
@@ -1079,7 +1080,8 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 
 	Stopwatch  TotalTimer;
 	const auto _ = MakeGuard([&] {
-		ZEN_DEBUG("Compact blocks for '{}' DONE after {}, deleted {} and moved {} chunks ({}) ",
+		ZEN_DEBUG("{}Compact blocks for '{}' DONE after {}, deleted {} and moved {} chunks ({}) ",
+				  LogPrefix,
 				  m_BlocksBasePath,
 				  NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()),
 				  NiceBytes(DeletedSize),
@@ -1107,7 +1109,7 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 			   }
 			   if (NewBlockFile->IsOpen())
 			   {
-				   ZEN_DEBUG("Dropping incomplete cas block store file '{}'", NewBlockFile->GetPath());
+				   ZEN_DEBUG("{}Dropping incomplete cas block store file '{}'", LogPrefix, NewBlockFile->GetPath());
 				   NewBlockFile->MarkAsDeleteOnClose();
 			   }
 		   }
@@ -1138,7 +1140,8 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 			RwLock::SharedLockScope _(m_InsertLock);
 			if ((BlockIndex == m_WriteBlockIndex.load()) && m_WriteBlock)
 			{
-				ZEN_ERROR("Compact Block was requested to rewrite the currently active write block in '{}', Block index {}",
+				ZEN_ERROR("{}compact Block was requested to rewrite the currently active write block in '{}', Block index {}",
+						  LogPrefix,
 						  m_BlocksBasePath,
 						  BlockIndex);
 				return false;
@@ -1146,12 +1149,18 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 			auto It = m_ChunkBlocks.find(BlockIndex);
 			if (It == m_ChunkBlocks.end())
 			{
-				ZEN_WARN("Compact Block was requested to rewrite an unknown block in '{}', Block index {}", m_BlocksBasePath, BlockIndex);
+				ZEN_WARN("{}compact Block was requested to rewrite an unknown block in '{}', Block index {}",
+						 LogPrefix,
+						 m_BlocksBasePath,
+						 BlockIndex);
 				return true;
 			}
 			if (!It->second)
 			{
-				ZEN_WARN("Compact Block was requested to rewrite a deleted block in '{}', Block index {}", m_BlocksBasePath, BlockIndex);
+				ZEN_WARN("{}compact Block was requested to rewrite a deleted block in '{}', Block index {}",
+						 LogPrefix,
+						 m_BlocksBasePath,
+						 BlockIndex);
 				return true;
 			}
 			OldBlockFile = It->second;
@@ -1162,10 +1171,14 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 
 		if (KeepChunkIndexes.empty())
 		{
-			ZEN_INFO("Dropping all chunks from '{}'", GetBlockPath(m_BlocksBasePath, BlockIndex));
+			ZEN_INFO("{}dropped all chunks from '{}', freeing {}",
+					 LogPrefix,
+					 GetBlockPath(m_BlocksBasePath, BlockIndex).filename(),
+					 NiceBytes(OldBlockSize));
 		}
 		else
 		{
+			uint64_t			 MovedFromBlock = 0;
 			std::vector<uint8_t> Chunk;
 			for (const size_t& ChunkIndex : KeepChunkIndexes)
 			{
@@ -1173,8 +1186,9 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 				if (ChunkLocation.Offset + ChunkLocation.Size > OldBlockSize)
 				{
 					ZEN_WARN(
-						"Compact Block skipping chunk outside of block range in '{}', Chunk start {}, Chunk size {} in Block {}, Block "
+						"{}compact Block skipping chunk outside of block range in '{}', Chunk start {}, Chunk size {} in Block {}, Block "
 						"size {}",
+						LogPrefix,
 						m_BlocksBasePath,
 						ChunkLocation.Offset,
 						ChunkLocation.Size,
@@ -1192,11 +1206,17 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 					{
 						ZEN_ASSERT_SLOW(NewBlockFile->IsOpen());
 						NewBlockFile->Flush();
-						MovedSize += NewBlockFile->FileSize();
+						uint64_t NewBlockSize = NewBlockFile->FileSize();
+						MovedSize += NewBlockSize;
 						NewBlockFile = nullptr;
 
 						ZEN_ASSERT(!MovedChunks.empty() || RemovedSize > 0);  // We should not have a new block if we haven't moved anything
 
+						ZEN_INFO("{}wrote block {} ({})",
+								 LogPrefix,
+								 GetBlockPath(m_BlocksBasePath, NewBlockIndex).filename(),
+								 NiceBytes(NewBlockSize));
+
 						if (!ReportChanges())
 						{
 							return false;
@@ -1210,7 +1230,8 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 						NextBlockIndex = GetFreeBlockIndex(NextBlockIndex, InsertLock, NewBlockPath);
 						if (NextBlockIndex == (uint32_t)m_MaxBlockCount)
 						{
-							ZEN_ERROR("unable to allocate a new block in '{}', count limit {} exeeded",
+							ZEN_ERROR("{}unable to allocate a new block in '{}', count limit {} exeeded",
+									  LogPrefix,
 									  m_BlocksBasePath,
 									  static_cast<uint64_t>(std::numeric_limits<uint32_t>::max()) + 1);
 							return false;
@@ -1224,7 +1245,7 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 					DiskSpace		Space = DiskSpaceInfo(m_BlocksBasePath, Error);
 					if (Error)
 					{
-						ZEN_ERROR("get disk space in '{}' FAILED, reason: '{}'", m_BlocksBasePath, Error.message());
+						ZEN_ERROR("{}get disk space in '{}' FAILED, reason: '{}'", LogPrefix, m_BlocksBasePath, Error.message());
 						{
 							RwLock::ExclusiveLockScope _l(m_InsertLock);
 							ZEN_ASSERT(m_ChunkBlocks[NextBlockIndex] == NewBlockFile);
@@ -1240,7 +1261,8 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 						uint64_t ReclaimedSpace = DiskReserveCallback();
 						if (Space.Free + ReclaimedSpace < m_MaxBlockSize)
 						{
-							ZEN_WARN("garbage collect for '{}' FAILED, required disk space {}, free {}",
+							ZEN_WARN("{}garbage collect for '{}' FAILED, required disk space {}, free {}",
+									 LogPrefix,
 									 m_BlocksBasePath,
 									 m_MaxBlockSize,
 									 NiceBytes(Space.Free + ReclaimedSpace));
@@ -1254,7 +1276,8 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 							return false;
 						}
 
-						ZEN_INFO("using gc reserve for '{}', reclaimed {}, disk free {}",
+						ZEN_INFO("{}using gc reserve for '{}', reclaimed {}, disk free {}",
+								 LogPrefix,
 								 m_BlocksBasePath,
 								 ReclaimedSpace,
 								 NiceBytes(Space.Free + ReclaimedSpace));
@@ -1267,9 +1290,17 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 				NewBlockFile->Write(Chunk.data(), ChunkLocation.Size, WriteOffset);
 				MovedChunks.push_back(
 					{ChunkIndex, {.BlockIndex = NewBlockIndex, .Offset = gsl::narrow<uint32_t>(WriteOffset), .Size = ChunkLocation.Size}});
-				WriteOffset = RoundUp(WriteOffset + ChunkLocation.Size, PayloadAlignment);
+				uint64_t WriteEndOffset = WriteOffset + ChunkLocation.Size;
+				MovedFromBlock += (WriteEndOffset - WriteOffset);
+				WriteOffset = RoundUp(WriteEndOffset, PayloadAlignment);
 				AddedSize += Chunk.size();
 			}
+			ZEN_INFO("{}moved {} chunks ({}) from '{}' to new block, freeing {}",
+					 LogPrefix,
+					 KeepChunkIndexes.size(),
+					 NiceBytes(MovedFromBlock),
+					 GetBlockPath(m_BlocksBasePath, BlockIndex).filename(),
+					 NiceBytes(OldBlockSize - MovedFromBlock));
 		}
 
 		if (!ReportChanges())
@@ -1279,7 +1310,10 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 
 		{
 			RwLock::ExclusiveLockScope InsertLock(m_InsertLock);
-			ZEN_DEBUG("marking cas block store file '{}' for delete, block #{}", OldBlockFile->GetPath(), BlockIndex);
+			ZEN_DEBUG("{}marking cas block store file '{}' for delete ({})",
+					  LogPrefix,
+					  OldBlockFile->GetPath().filename(),
+					  NiceBytes(OldBlockSize));
 			OldBlockFile->MarkAsDeleteOnClose();
 			m_ChunkBlocks.erase(BlockIndex);
 			m_TotalSize.fetch_sub(OldBlockSize);
@@ -1292,8 +1326,10 @@ BlockStore::CompactBlocks(const BlockStoreCompactState&	  CompactState,
 	{
 		ZEN_ASSERT_SLOW(NewBlockFile->IsOpen());
 		NewBlockFile->Flush();
-		MovedSize += NewBlockFile->FileSize();
+		uint64_t NewBlockSize = NewBlockFile->FileSize();
+		MovedSize += NewBlockSize;
 		NewBlockFile = nullptr;
+		ZEN_INFO("{}wrote block {} ({})", LogPrefix, GetBlockPath(m_BlocksBasePath, NewBlockIndex).filename(), NiceBytes(NewBlockSize));
 	}
 
 	ReportChanges();