tweaked verbose output (#351)

1 files changed, 18 insertions, 23 deletions

diff --git a/src/zen/cmds/builds_cmd.cpp b/src/zen/cmds/builds_cmd.cpp
index 7014a6f15..0d2601bd8 100644
--- a/src/zen/cmds/builds_cmd.cpp
+++ b/src/zen/cmds/builds_cmd.cpp
@@ -1910,10 +1910,6 @@ namespace {
 															  uint64_t CompressedSize;
 															  uint64_t DecompressedSize;
 															  ValidateBlob(std::move(Payload), ChunkHash, CompressedSize, DecompressedSize);
-															  ZEN_CONSOLE_VERBOSE("Chunk attachment {} ({} -> {}) is valid",
-																				  ChunkHash,
-																				  NiceBytes(CompressedSize),
-																				  NiceBytes(DecompressedSize));
 															  ValidateStats.VerifiedAttachmentCount++;
 															  ValidateStats.VerifiedByteCount += DecompressedSize;
 															  if (ValidateStats.VerifiedAttachmentCount.load() == AttachmentsToVerifyCount)
@@ -1965,10 +1961,6 @@ namespace {
 										uint64_t CompressedSize;
 										uint64_t DecompressedSize;
 										ValidateChunkBlock(std::move(Payload), BlockAttachment, CompressedSize, DecompressedSize);
-										ZEN_CONSOLE_VERBOSE("Chunk block {} ({} -> {}) is valid",
-															BlockAttachment,
-															NiceBytes(CompressedSize),
-															NiceBytes(DecompressedSize));
 										ValidateStats.VerifiedAttachmentCount++;
 										ValidateStats.VerifiedByteCount += DecompressedSize;
 										if (ValidateStats.VerifiedAttachmentCount.load() == AttachmentsToVerifyCount)
@@ -2258,12 +2250,14 @@ namespace {
 							FilteredGeneratedBytesPerSecond.Start();
 							// TODO: Convert ScheduleWork body to function
 
+							Stopwatch		 GenerateTimer;
 							CompressedBuffer CompressedBlock =
 								GenerateBlock(Path, Content, Lookup, ChunksInBlock, OutBlocks.BlockDescriptions[BlockIndex], DiskStats);
-							ZEN_CONSOLE_VERBOSE("Generated block {} ({}) containing {} chunks",
+							ZEN_CONSOLE_VERBOSE("Generated block {} ({}) containing {} chunks in {}",
 												OutBlocks.BlockDescriptions[BlockIndex].BlockHash,
 												NiceBytes(CompressedBlock.GetCompressedSize()),
-												OutBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size());
+												OutBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size(),
+												NiceTimeSpanMs(GenerateTimer.GetElapsedTimeMs()));
 
 							OutBlocks.BlockSizes[BlockIndex] = CompressedBlock.GetCompressedSize();
 							{
@@ -2657,6 +2651,7 @@ namespace {
 
 								FilteredGenerateBlockBytesPerSecond.Start();
 
+								Stopwatch		GenerateTimer;
 								CompositeBuffer Payload;
 								if (NewBlocks.BlockHeaders[BlockIndex])
 								{
@@ -2687,14 +2682,16 @@ namespace {
 								{
 									FilteredGenerateBlockBytesPerSecond.Stop();
 								}
+								ZEN_CONSOLE_VERBOSE("{} block {} ({}) containing {} chunks in {}",
+													NewBlocks.BlockHeaders[BlockIndex] ? "Regenerated" : "Generated",
+													NewBlocks.BlockDescriptions[BlockIndex].BlockHash,
+													NiceBytes(NewBlocks.BlockSizes[BlockIndex]),
+													NewBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size(),
+													NiceTimeSpanMs(GenerateTimer.GetElapsedTimeMs()));
 								if (!AbortFlag)
 								{
 									AsyncUploadBlock(BlockIndex, BlockHash, std::move(Payload), QueuedPendingInMemoryBlocksForUpload);
 								}
-								ZEN_CONSOLE_VERBOSE("Regenerated block {} ({}) containing {} chunks",
-													NewBlocks.BlockDescriptions[BlockIndex].BlockHash,
-													NiceBytes(NewBlocks.BlockSizes[BlockIndex]),
-													NewBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size());
 							}
 						},
 						Work.DefaultErrorFunction());
@@ -2713,12 +2710,14 @@ namespace {
 							ZEN_TRACE_CPU("UploadPartBlobs_CompressChunk");
 
 							FilteredCompressedBytesPerSecond.Start();
+							Stopwatch		CompressTimer;
 							CompositeBuffer Payload =
 								CompressChunk(Path, Content, Lookup, ChunkIndex, ZenTempChunkFolderPath(ZenFolderPath), LooseChunksStats);
-							ZEN_CONSOLE_VERBOSE("Compressed chunk {} ({} -> {})",
+							ZEN_CONSOLE_VERBOSE("Compressed chunk {} ({} -> {}) in {}",
 												Content.ChunkedContent.ChunkHashes[ChunkIndex],
 												NiceBytes(Content.ChunkedContent.ChunkRawSizes[ChunkIndex]),
-												NiceBytes(Payload.GetSize()));
+												NiceBytes(Payload.GetSize()),
+												NiceTimeSpanMs(CompressTimer.GetElapsedTimeMs()));
 							const uint64_t ChunkRawSize = Content.ChunkedContent.ChunkRawSizes[ChunkIndex];
 							UploadStats.ReadFromDiskBytes += ChunkRawSize;
 							if (LooseChunksStats.CompressedChunkCount == LooseChunkOrderIndexes.size())
@@ -2857,10 +2856,8 @@ namespace {
 						}
 						else if (FoundAttachmentCount > 0)
 						{
-							ZEN_CONSOLE_VERBOSE("Skipping block {}. {} attachments found, usage level: {}%",
-												KnownBlock.BlockHash,
-												FoundAttachmentCount,
-												ReusePercent);
+							// ZEN_CONSOLE_VERBOSE("Skipping block {}. {} attachments found, usage level: {}%", KnownBlock.BlockHash,
+							// FoundAttachmentCount, ReusePercent);
 							FindBlocksStats.RejectedBlockCount++;
 							FindBlocksStats.RejectedChunkCount += FoundAttachmentCount;
 							FindBlocksStats.RejectedByteCount += ReuseSize;
@@ -2920,7 +2917,7 @@ namespace {
 						}
 						else
 						{
-							ZEN_CONSOLE_VERBOSE("Skipping block {}. filtered usage level: {}%", KnownBlock.BlockHash, ReusePercent);
+							// ZEN_CONSOLE_VERBOSE("Skipping block {}. filtered usage level: {}%", KnownBlock.BlockHash, ReusePercent);
 							FindBlocksStats.RejectedBlockCount++;
 							FindBlocksStats.RejectedChunkCount += FoundChunkIndexes.size();
 							FindBlocksStats.RejectedByteCount += AdjustedReuseSize;
@@ -3561,8 +3558,6 @@ namespace {
 		auto UploadAttachments = [&](std::span<IoHash> RawHashes) {
 			if (!AbortFlag)
 			{
-				ZEN_CONSOLE_VERBOSE("Uploading attachments: {}", FormatArray<IoHash>(RawHashes, "\n    "sv));
-
 				UploadStatistics	  TempUploadStats;
 				LooseChunksStatistics TempLooseChunksStats;