diff options
| author | Dan Engelbrecht <[email protected]> | 2025-11-06 19:15:41 +0100 |
|---|---|---|
| committer | GitHub Enterprise <[email protected]> | 2025-11-06 19:15:41 +0100 |
| commit | b919cda2e0c065ba556912e9ab404a321362f8ab (patch) | |
| tree | 8192317ebb34469271d58644e942deb9c858d05f /src | |
| parent | merge 5.7.8 minimal release (#635) (diff) | |
| download | zen-b919cda2e0c065ba556912e9ab404a321362f8ab.tar.xz zen-b919cda2e0c065ba556912e9ab404a321362f8ab.zip | |
remotestore op refactorings (#637)
* broke out BuildLogOutput to separate file
* refactored out GetBlockDescriptions
* log progress improvements
* refactorings to accomodate oplog download operations
Diffstat (limited to 'src')
| -rw-r--r-- | src/zen/cmds/builds_cmd.cpp | 207 | ||||
| -rw-r--r-- | src/zenremotestore/builds/buildstorageoperations.cpp | 963 | ||||
| -rw-r--r-- | src/zenremotestore/builds/buildstorageutil.cpp | 210 | ||||
| -rw-r--r-- | src/zenremotestore/include/zenremotestore/builds/buildstorageoperations.h | 113 | ||||
| -rw-r--r-- | src/zenremotestore/include/zenremotestore/builds/buildstorageutil.h | 28 | ||||
| -rw-r--r-- | src/zenremotestore/include/zenremotestore/operationlogoutput.h | 87 | ||||
| -rw-r--r-- | src/zenremotestore/operationlogoutput.cpp | 67 |
7 files changed, 927 insertions, 748 deletions
diff --git a/src/zen/cmds/builds_cmd.cpp b/src/zen/cmds/builds_cmd.cpp index cc1844f71..91eedb756 100644 --- a/src/zen/cmds/builds_cmd.cpp +++ b/src/zen/cmds/builds_cmd.cpp @@ -35,6 +35,7 @@ #include <zenremotestore/chunking/chunkingcontroller.h> #include <zenremotestore/filesystemutils.h> #include <zenremotestore/jupiter/jupiterhost.h> +#include <zenremotestore/operationlogoutput.h> #include <zenutil/wildcard.h> #include <zenutil/workerpools.h> #include <zenutil/zenserverprocess.h> @@ -385,7 +386,7 @@ namespace { ); - class ConsoleOpLogProgressBar : public BuildOpLogOutput::ProgressBar + class ConsoleOpLogProgressBar : public OperationLogOutput::ProgressBar { public: ConsoleOpLogProgressBar(zen::ProgressBar::Mode InMode, std::string_view InSubTask) : m_Inner(InMode, InSubTask) {} @@ -419,7 +420,7 @@ namespace { zen::ProgressBar m_Inner; }; - class ConsoleOpLogOutput : public BuildOpLogOutput + class ConsoleOpLogOutput : public OperationLogOutput { public: ConsoleOpLogOutput(zen::ProgressBar::Mode InMode) : m_Mode(InMode) {} @@ -1376,197 +1377,17 @@ namespace { // TODO: GetBlockDescriptions for all BlockRawHashes in one go - check for local block descriptions when we cache them { - if (!IsQuiet) - { - ZEN_CONSOLE("Fetching metadata for {} blocks", BlockRawHashes.size()); - } - - Stopwatch GetBlockMetadataTimer; - - std::vector<ChunkBlockDescription> UnorderedList; - tsl::robin_map<IoHash, size_t, IoHash::Hasher> BlockDescriptionLookup; - if (Storage.BuildCacheStorage && !BlockRawHashes.empty()) - { - std::vector<CbObject> CacheBlockMetadatas = Storage.BuildCacheStorage->GetBlobMetadatas(BuildId, BlockRawHashes); - UnorderedList.reserve(CacheBlockMetadatas.size()); - for (size_t CacheBlockMetadataIndex = 0; CacheBlockMetadataIndex < CacheBlockMetadatas.size(); - CacheBlockMetadataIndex++) - { - const CbObject& CacheBlockMetadata = CacheBlockMetadatas[CacheBlockMetadataIndex]; - ChunkBlockDescription Description = ParseChunkBlockDescription(CacheBlockMetadata); - if (Description.BlockHash == IoHash::Zero) - { - ZEN_CONSOLE_WARN("Unexpected/invalid block metadata received from remote cache, skipping block"); - } - else - { - UnorderedList.emplace_back(std::move(Description)); - } - } - for (size_t DescriptionIndex = 0; DescriptionIndex < UnorderedList.size(); DescriptionIndex++) - { - const ChunkBlockDescription& Description = UnorderedList[DescriptionIndex]; - BlockDescriptionLookup.insert_or_assign(Description.BlockHash, DescriptionIndex); - } - } - - if (UnorderedList.size() < BlockRawHashes.size()) - { - std::vector<IoHash> RemainingBlockHashes; - RemainingBlockHashes.reserve(BlockRawHashes.size() - UnorderedList.size()); - for (const IoHash& BlockRawHash : BlockRawHashes) - { - if (!BlockDescriptionLookup.contains(BlockRawHash)) - { - RemainingBlockHashes.push_back(BlockRawHash); - } - } - CbObject BlockMetadatas = Storage.BuildStorage->GetBlockMetadatas(BuildId, RemainingBlockHashes); - std::vector<ChunkBlockDescription> RemainingList; - { - CbArrayView BlocksArray = BlockMetadatas["blocks"sv].AsArrayView(); - std::vector<IoHash> FoundBlockHashes; - std::vector<CbObject> FoundBlockMetadatas; - for (CbFieldView Block : BlocksArray) - { - ChunkBlockDescription Description = ParseChunkBlockDescription(Block.AsObjectView()); - - if (Description.BlockHash == IoHash::Zero) - { - ZEN_CONSOLE_WARN("Unexpected/invalid block metadata received from remote store, skipping block"); - } - else - { - if (Storage.BuildCacheStorage) - { - UniqueBuffer MetaBuffer = UniqueBuffer::Alloc(Block.GetSize()); - Block.CopyTo(MetaBuffer.GetMutableView()); - CbObject BlockMetadata(MetaBuffer.MoveToShared()); - - FoundBlockHashes.push_back(Description.BlockHash); - FoundBlockMetadatas.push_back(BlockMetadata); - } - RemainingList.emplace_back(std::move(Description)); - } - } - if (Storage.BuildCacheStorage && !FoundBlockHashes.empty()) - { - Storage.BuildCacheStorage->PutBlobMetadatas(BuildId, FoundBlockHashes, FoundBlockMetadatas); - } - } - - for (size_t DescriptionIndex = 0; DescriptionIndex < RemainingList.size(); DescriptionIndex++) - { - const ChunkBlockDescription& Description = RemainingList[DescriptionIndex]; - BlockDescriptionLookup.insert_or_assign(Description.BlockHash, UnorderedList.size() + DescriptionIndex); - } - UnorderedList.insert(UnorderedList.end(), RemainingList.begin(), RemainingList.end()); - } - - OutBlockDescriptions.reserve(BlockDescriptionLookup.size()); - for (const IoHash& BlockHash : BlockRawHashes) - { - if (auto It = BlockDescriptionLookup.find(BlockHash); It != BlockDescriptionLookup.end()) - { - OutBlockDescriptions.push_back(std::move(UnorderedList[It->second])); - } - } - - if (!IsQuiet) - { - ZEN_CONSOLE("GetBlockMetadata for {} took {}. Found {} blocks", - BuildPartId, - NiceTimeSpanMs(GetBlockMetadataTimer.GetElapsedTimeMs()), - OutBlockDescriptions.size()); - } - } - - if (OutBlockDescriptions.size() != BlockRawHashes.size()) - { - bool AttemptFallback = false; - std::string ErrorDescription = - fmt::format("All required blocks could not be found, {} blocks does not have metadata in this context.", - BlockRawHashes.size() - OutBlockDescriptions.size()); - if (IsVerbose) - { - for (const IoHash& BlockHash : BlockRawHashes) - { - if (auto It = std::find_if( - OutBlockDescriptions.begin(), - OutBlockDescriptions.end(), - [BlockHash](const ChunkBlockDescription& Description) { return Description.BlockHash == BlockHash; }); - It == OutBlockDescriptions.end()) - { - ErrorDescription += fmt::format("\n {}", BlockHash); - } - } - } - if (AttemptFallback) - { - ZEN_CONSOLE_WARN("{} Attemping fallback options.", ErrorDescription); - std::vector<ChunkBlockDescription> AugmentedBlockDescriptions; - AugmentedBlockDescriptions.reserve(BlockRawHashes.size()); - std::vector<ChunkBlockDescription> FoundBlocks = - ParseChunkBlockDescriptionList(Storage.BuildStorage->FindBlocks(BuildId, (uint64_t)-1)); - - for (const IoHash& BlockHash : BlockRawHashes) - { - if (auto It = std::find_if( - OutBlockDescriptions.begin(), - OutBlockDescriptions.end(), - [BlockHash](const ChunkBlockDescription& Description) { return Description.BlockHash == BlockHash; }); - It != OutBlockDescriptions.end()) - { - AugmentedBlockDescriptions.emplace_back(std::move(*It)); - } - else if (auto ListBlocksIt = std::find_if( - FoundBlocks.begin(), - FoundBlocks.end(), - [BlockHash](const ChunkBlockDescription& Description) { return Description.BlockHash == BlockHash; }); - ListBlocksIt != FoundBlocks.end()) - { - ZEN_CONSOLE("Found block {} via context find successfully", BlockHash); - AugmentedBlockDescriptions.emplace_back(std::move(*ListBlocksIt)); - } - else - { - IoBuffer BlockBuffer = Storage.BuildStorage->GetBuildBlob(BuildId, BlockHash); - if (!BlockBuffer) - { - throw std::runtime_error(fmt::format("Block {} could not be found", BlockHash)); - } - IoHash BlockRawHash; - uint64_t BlockRawSize; - CompressedBuffer CompressedBlockBuffer = - CompressedBuffer::FromCompressed(SharedBuffer(std::move(BlockBuffer)), BlockRawHash, BlockRawSize); - if (!CompressedBlockBuffer) - { - throw std::runtime_error(fmt::format("Block {} is not a compressed buffer", BlockHash)); - } - - if (BlockRawHash != BlockHash) - { - throw std::runtime_error( - fmt::format("Block {} header has a mismatching raw hash {}", BlockHash, BlockRawHash)); - } - - CompositeBuffer DecompressedBlockBuffer = CompressedBlockBuffer.DecompressToComposite(); - if (!DecompressedBlockBuffer) - { - throw std::runtime_error(fmt::format("Block {} failed to decompress", BlockHash)); - } - - ChunkBlockDescription MissingChunkDescription = - GetChunkBlockDescription(DecompressedBlockBuffer.Flatten(), BlockHash); - AugmentedBlockDescriptions.emplace_back(std::move(MissingChunkDescription)); - } - } - OutBlockDescriptions.swap(AugmentedBlockDescriptions); - } - else - { - throw std::runtime_error(ErrorDescription); - } + ConsoleLogOutput OperationLogOutput; + bool AttemptFallback = false; + OutBlockDescriptions = GetBlockDescriptions(OperationLogOutput, + *Storage.BuildStorage, + Storage.BuildCacheStorage.get(), + BuildId, + BuildPartId, + BlockRawHashes, + AttemptFallback, + IsQuiet, + IsVerbose); } CalculateLocalChunkOrders(AbsoluteChunkOrders, diff --git a/src/zenremotestore/builds/buildstorageoperations.cpp b/src/zenremotestore/builds/buildstorageoperations.cpp index 2eb6132be..747aa7631 100644 --- a/src/zenremotestore/builds/buildstorageoperations.cpp +++ b/src/zenremotestore/builds/buildstorageoperations.cpp @@ -5,9 +5,11 @@ #include <zenremotestore/builds/buildsavedstate.h> #include <zenremotestore/builds/buildstorage.h> #include <zenremotestore/builds/buildstoragecache.h> +#include <zenremotestore/builds/buildstorageutil.h> #include <zenremotestore/chunking/chunkblock.h> #include <zenremotestore/chunking/chunkingcontroller.h> #include <zenremotestore/filesystemutils.h> +#include <zenremotestore/operationlogoutput.h> #include <zencore/basicfile.h> #include <zencore/compactbinary.h> @@ -34,18 +36,6 @@ namespace zen { using namespace std::literals; -#define DO_LOG_OUTPUT(OutputTarget, InLevel, fmtstr, ...) \ - do \ - { \ - using namespace std::literals; \ - ZEN_CHECK_FORMAT_STRING(fmtstr##sv, ##__VA_ARGS__); \ - OutputTarget.EmitLogMessage(InLevel, fmtstr, zen::logging::LogCaptureArguments(__VA_ARGS__)); \ - } while (false) - -#define LOG_OUTPUT(OutputTarget, fmtstr, ...) DO_LOG_OUTPUT(OutputTarget, zen::logging::level::Info, fmtstr, ##__VA_ARGS__) -#define LOG_OUTPUT_DEBUG(OutputTarget, fmtstr, ...) DO_LOG_OUTPUT(OutputTarget, zen::logging::level::Debug, fmtstr, ##__VA_ARGS__) -#define LOG_OUTPUT_WARN(OutputTarget, fmtstr, ...) DO_LOG_OUTPUT(OutputTarget, zen::logging::level::Warn, fmtstr, ##__VA_ARGS__) - namespace { std::filesystem::path ZenTempCacheFolderPath(const std::filesystem::path& ZenFolderPath) { @@ -79,7 +69,7 @@ namespace { return CacheFolderPath / RawHash.ToHexString(); } - bool CleanDirectory(BuildOpLogOutput& LogOutput, + bool CleanDirectory(OperationLogOutput& OperationLogOutput, WorkerThreadPool& IOWorkerPool, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -90,8 +80,8 @@ namespace { ZEN_TRACE_CPU("CleanDirectory"); Stopwatch Timer; - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(LogOutput.CreateProgressBar("Clean Folder")); - BuildOpLogOutput::ProgressBar& Progress(*ProgressBarPtr); + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(OperationLogOutput.CreateProgressBar("Clean Folder")); + OperationLogOutput::ProgressBar& Progress(*ProgressBarPtr); CleanDirectoryResult Result = CleanDirectory( IOWorkerPool, @@ -104,10 +94,10 @@ namespace { .Details = std::string(Details), .TotalCount = TotalCount, .RemainingCount = RemainingCount, - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }, - LogOutput.GetProgressUpdateDelayMS()); + OperationLogOutput.GetProgressUpdateDelayMS()); Progress.Finish(); @@ -128,17 +118,17 @@ namespace { Result.FailedRemovePaths[FailedPathIndex].second.value(), Result.FailedRemovePaths[FailedPathIndex].second.message()); } - LOG_OUTPUT_WARN(LogOutput, "Clean failed to remove files from '{}': {}", Path, SB.ToView()); + ZEN_OPERATION_LOG_WARN(OperationLogOutput, "Clean failed to remove files from '{}': {}", Path, SB.ToView()); } if (ElapsedTimeMs >= 200 && !IsQuiet) { - LOG_OUTPUT(LogOutput, - "Wiped folder '{}' {} ({}) in {}", - Path, - Result.FoundCount, - NiceBytes(Result.DeletedByteCount), - NiceTimeSpanMs(ElapsedTimeMs)); + ZEN_OPERATION_LOG_INFO(OperationLogOutput, + "Wiped folder '{}' {} ({}) in {}", + Path, + Result.FoundCount, + NiceBytes(Result.DeletedByteCount), + NiceTimeSpanMs(ElapsedTimeMs)); } return Result.FailedRemovePaths.empty(); @@ -516,7 +506,7 @@ ZenTempFolderPath(const std::filesystem::path& ZenFolderPath) ////////////////////// BuildsOperationUpdateFolder -BuildsOperationUpdateFolder::BuildsOperationUpdateFolder(BuildOpLogOutput& LogOutput, +BuildsOperationUpdateFolder::BuildsOperationUpdateFolder(OperationLogOutput& OperationLogOutput, StorageInstance& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -531,7 +521,7 @@ BuildsOperationUpdateFolder::BuildsOperationUpdateFolder(BuildOpLogOutput& const std::vector<ChunkBlockDescription>& BlockDescriptions, const std::vector<IoHash>& LooseChunkHashes, const Options& Options) -: m_LogOutput(LogOutput) +: m_LogOutput(OperationLogOutput) , m_Storage(Storage) , m_AbortFlag(AbortFlag) , m_PauseFlag(PauseFlag) @@ -558,7 +548,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) ZEN_TRACE_CPU("BuildsOperationUpdateFolder::Execute"); try { - enum TaskSteps : uint32_t + enum class TaskSteps : uint32_t { ScanExistingData, WriteChunks, @@ -568,12 +558,13 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) StepCount }; - auto EndProgress = MakeGuard([&]() { m_LogOutput.SetLogOperationProgress(TaskSteps::StepCount, TaskSteps::StepCount); }); + auto EndProgress = + MakeGuard([&]() { m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::StepCount, (uint32_t)TaskSteps::StepCount); }); ZEN_ASSERT((!m_Options.PrimeCacheOnly) || (m_Options.PrimeCacheOnly && (m_Options.PartialBlockRequestMode == EPartialBlockRequestMode::Off))); - m_LogOutput.SetLogOperationProgress(TaskSteps::ScanExistingData, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::ScanExistingData, (uint32_t)TaskSteps::StepCount); CreateDirectories(m_CacheFolderPath); CreateDirectories(m_TempDownloadFolderPath); @@ -583,7 +574,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, "Indexed local and remote content in {}", NiceTimeSpanMs(IndexTimer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Indexed local and remote content in {}", NiceTimeSpanMs(IndexTimer.GetElapsedTimeMs())); } Stopwatch CacheMappingTimer; @@ -658,8 +649,8 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) ScavengedLookups.resize(ScavengePathCount); ScavengedPaths.resize(ScavengePathCount); - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Scavenging")); - BuildOpLogOutput::ProgressBar& ScavengeProgressBar(*ProgressBarPtr); + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Scavenging")); + OperationLogOutput::ProgressBar& ScavengeProgressBar(*ProgressBarPtr); ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); @@ -716,7 +707,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) .Details = Details, .TotalCount = ScavengePathCount, .RemainingCount = ScavengePathCount - PathsScavenged.load(), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); } @@ -962,37 +953,37 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) if (m_CacheMappingStats.CacheSequenceHashesCount > 0 || m_CacheMappingStats.CacheChunkCount > 0 || m_CacheMappingStats.CacheBlockCount > 0) { - LOG_OUTPUT(m_LogOutput, - "Download cache: Found {} ({}) chunk sequences, {} ({}) chunks, {} ({}) blocks in {}", - m_CacheMappingStats.CacheSequenceHashesCount, - NiceBytes(m_CacheMappingStats.CacheSequenceHashesByteCount), - m_CacheMappingStats.CacheChunkCount, - NiceBytes(m_CacheMappingStats.CacheChunkByteCount), - m_CacheMappingStats.CacheBlockCount, - NiceBytes(m_CacheMappingStats.CacheBlocksByteCount), - NiceTimeSpanMs(m_CacheMappingStats.CacheScanElapsedWallTimeUs / 1000)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Download cache: Found {} ({}) chunk sequences, {} ({}) chunks, {} ({}) blocks in {}", + m_CacheMappingStats.CacheSequenceHashesCount, + NiceBytes(m_CacheMappingStats.CacheSequenceHashesByteCount), + m_CacheMappingStats.CacheChunkCount, + NiceBytes(m_CacheMappingStats.CacheChunkByteCount), + m_CacheMappingStats.CacheBlockCount, + NiceBytes(m_CacheMappingStats.CacheBlocksByteCount), + NiceTimeSpanMs(m_CacheMappingStats.CacheScanElapsedWallTimeUs / 1000)); } if (m_CacheMappingStats.LocalPathsMatchingSequencesCount > 0 || m_CacheMappingStats.LocalChunkMatchingRemoteCount > 0) { - LOG_OUTPUT(m_LogOutput, - "Local state : Found {} ({}) chunk sequences, {} ({}) chunks in {}", - m_CacheMappingStats.LocalPathsMatchingSequencesCount, - NiceBytes(m_CacheMappingStats.LocalPathsMatchingSequencesByteCount), - m_CacheMappingStats.LocalChunkMatchingRemoteCount, - NiceBytes(m_CacheMappingStats.LocalChunkMatchingRemoteByteCount), - NiceTimeSpanMs(m_CacheMappingStats.LocalScanElapsedWallTimeUs / 1000)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Local state : Found {} ({}) chunk sequences, {} ({}) chunks in {}", + m_CacheMappingStats.LocalPathsMatchingSequencesCount, + NiceBytes(m_CacheMappingStats.LocalPathsMatchingSequencesByteCount), + m_CacheMappingStats.LocalChunkMatchingRemoteCount, + NiceBytes(m_CacheMappingStats.LocalChunkMatchingRemoteByteCount), + NiceTimeSpanMs(m_CacheMappingStats.LocalScanElapsedWallTimeUs / 1000)); } if (m_CacheMappingStats.ScavengedPathsMatchingSequencesCount > 0 || m_CacheMappingStats.ScavengedChunkMatchingRemoteCount > 0) { - LOG_OUTPUT(m_LogOutput, - "Scavenge of {} paths, found {} ({}) chunk sequences, {} ({}) chunks in {}", - ScavengedPathsCount, - m_CacheMappingStats.ScavengedPathsMatchingSequencesCount, - NiceBytes(m_CacheMappingStats.ScavengedPathsMatchingSequencesByteCount), - m_CacheMappingStats.ScavengedChunkMatchingRemoteCount, - NiceBytes(m_CacheMappingStats.ScavengedChunkMatchingRemoteByteCount), - NiceTimeSpanMs(m_CacheMappingStats.ScavengeElapsedWallTimeUs / 1000)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Scavenge of {} paths, found {} ({}) chunk sequences, {} ({}) chunks in {}", + ScavengedPathsCount, + m_CacheMappingStats.ScavengedPathsMatchingSequencesCount, + NiceBytes(m_CacheMappingStats.ScavengedPathsMatchingSequencesByteCount), + m_CacheMappingStats.ScavengedChunkMatchingRemoteCount, + NiceBytes(m_CacheMappingStats.ScavengedChunkMatchingRemoteByteCount), + NiceTimeSpanMs(m_CacheMappingStats.ScavengeElapsedWallTimeUs / 1000)); } } @@ -1025,17 +1016,17 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) { ZEN_TRACE_CPU("WriteChunks"); - m_LogOutput.SetLogOperationProgress(TaskSteps::WriteChunks, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::WriteChunks, (uint32_t)TaskSteps::StepCount); Stopwatch WriteTimer; FilteredRate FilteredDownloadedBytesPerSecond; FilteredRate FilteredWrittenBytesPerSecond; - std::unique_ptr<BuildOpLogOutput::ProgressBar> WriteProgressBarPtr( + std::unique_ptr<OperationLogOutput::ProgressBar> WriteProgressBarPtr( m_LogOutput.CreateProgressBar(m_Options.PrimeCacheOnly ? "Downloading" : "Writing")); - BuildOpLogOutput::ProgressBar& WriteProgressBar(*WriteProgressBarPtr); - ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); + OperationLogOutput::ProgressBar& WriteProgressBar(*WriteProgressBarPtr); + ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); struct LooseChunkHashWorkData { @@ -1056,7 +1047,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Skipping chunk {} due to cache reuse", ChunkHash); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Skipping chunk {} due to cache reuse", ChunkHash); } continue; } @@ -1070,7 +1061,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Skipping chunk {} due to cache reuse", ChunkHash); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Skipping chunk {} due to cache reuse", ChunkHash); } } else @@ -1187,11 +1178,11 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) ExistsResult.ElapsedTimeMs = Timer.GetElapsedTimeMs(); if (!ExistsResult.ExistingBlobs.empty() && !m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Remote cache : Found {} out of {} needed blobs in {}", - ExistsResult.ExistingBlobs.size(), - BlobHashes.size(), - NiceTimeSpanMs(ExistsResult.ElapsedTimeMs)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Remote cache : Found {} out of {} needed blobs in {}", + ExistsResult.ExistingBlobs.size(), + BlobHashes.size(), + NiceTimeSpanMs(ExistsResult.ElapsedTimeMs)); } } } @@ -1276,14 +1267,15 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Requesting {} chunks ({}) from block {} ({}) using {} requests (extra bytes {})", - BlockChunkIndexNeeded.size(), - NiceBytes(RequestedSize), - BlockDescription.BlockHash, - NiceBytes(TotalBlockSize), - BlockRanges.size(), - NiceBytes(RequestedSize - TotalWantedChunksSize)); + ZEN_OPERATION_LOG_INFO( + m_LogOutput, + "Requesting {} chunks ({}) from block {} ({}) using {} requests (extra bytes {})", + BlockChunkIndexNeeded.size(), + NiceBytes(RequestedSize), + BlockDescription.BlockHash, + NiceBytes(TotalBlockSize), + BlockRanges.size(), + NiceBytes(RequestedSize - TotalWantedChunksSize)); } } } @@ -1343,14 +1335,14 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Analisys of partial block requests saves download of {} out of {} ({:.1f}%) using {} extra " - "requests. Completed in {}", - NiceBytes(TotalSavedBlocksSize), - NiceBytes(NonPartialTotalBlockBytes), - SavedSizePercent, - TotalExtraPartialBlocksRequests, - NiceTimeSpanMs(ExistsResult.ElapsedTimeMs)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Analisys of partial block requests saves download of {} out of {} ({:.1f}%) using {} extra " + "requests. Completed in {}", + NiceBytes(TotalSavedBlocksSize), + NiceBytes(NonPartialTotalBlockBytes), + SavedSizePercent, + TotalExtraPartialBlocksRequests, + NiceTimeSpanMs(ExistsResult.ElapsedTimeMs)); } } } @@ -1563,11 +1555,11 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) std::error_code Ec = TryRemoveFile(BlockChunkPath); if (Ec) { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - BlockChunkPath, - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + BlockChunkPath, + Ec.value(), + Ec.message()); } WritePartsComplete++; @@ -1691,11 +1683,11 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) std::error_code Ec = TryRemoveFile(BlockChunkPath); if (Ec) { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - BlockChunkPath, - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + BlockChunkPath, + Ec.value(), + Ec.message()); } WritePartsComplete++; @@ -1822,77 +1814,77 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) if (!m_AbortFlag) { - Work.ScheduleWork(m_IOWorkerPool, - [this, - &Work, - &RemoteChunkIndexNeedsCopyFromSourceFlags, - &SequenceIndexChunksLeftToWriteCounters, - BlockIndex, - &WriteCache, - &WritePartsComplete, - TotalPartWriteCount, - &FilteredWrittenBytesPerSecond, - BlockChunkPath, - BlockBuffer = std::move(BlockBuffer)](std::atomic<bool>&) mutable { - if (!m_AbortFlag) - { - ZEN_TRACE_CPU("Async_WriteFullBlock"); - - const ChunkBlockDescription& BlockDescription = - m_BlockDescriptions[BlockIndex]; - - if (BlockChunkPath.empty()) - { - ZEN_ASSERT(BlockBuffer); - } - else - { - ZEN_ASSERT(!BlockBuffer); - BlockBuffer = IoBufferBuilder::MakeFromFile(BlockChunkPath); - if (!BlockBuffer) - { - throw std::runtime_error( - fmt::format("Could not open dowloaded block {} from {}", - BlockDescription.BlockHash, - BlockChunkPath)); - } - } - - FilteredWrittenBytesPerSecond.Start(); - if (!WriteChunksBlockToCache(BlockDescription, - SequenceIndexChunksLeftToWriteCounters, - Work, - CompositeBuffer(std::move(BlockBuffer)), - RemoteChunkIndexNeedsCopyFromSourceFlags, - WriteCache)) - { - std::error_code DummyEc; - RemoveFile(BlockChunkPath, DummyEc); - throw std::runtime_error( - fmt::format("Block {} is malformed", BlockDescription.BlockHash)); - } - - if (!BlockChunkPath.empty()) - { - std::error_code Ec = TryRemoveFile(BlockChunkPath); - if (Ec) - { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - BlockChunkPath, - Ec.value(), - Ec.message()); - } - } - - WritePartsComplete++; - - if (WritePartsComplete == TotalPartWriteCount) - { - FilteredWrittenBytesPerSecond.Stop(); - } - } - }); + Work.ScheduleWork( + m_IOWorkerPool, + [this, + &Work, + &RemoteChunkIndexNeedsCopyFromSourceFlags, + &SequenceIndexChunksLeftToWriteCounters, + BlockIndex, + &WriteCache, + &WritePartsComplete, + TotalPartWriteCount, + &FilteredWrittenBytesPerSecond, + BlockChunkPath, + BlockBuffer = std::move(BlockBuffer)](std::atomic<bool>&) mutable { + if (!m_AbortFlag) + { + ZEN_TRACE_CPU("Async_WriteFullBlock"); + + const ChunkBlockDescription& BlockDescription = m_BlockDescriptions[BlockIndex]; + + if (BlockChunkPath.empty()) + { + ZEN_ASSERT(BlockBuffer); + } + else + { + ZEN_ASSERT(!BlockBuffer); + BlockBuffer = IoBufferBuilder::MakeFromFile(BlockChunkPath); + if (!BlockBuffer) + { + throw std::runtime_error( + fmt::format("Could not open dowloaded block {} from {}", + BlockDescription.BlockHash, + BlockChunkPath)); + } + } + + FilteredWrittenBytesPerSecond.Start(); + if (!WriteChunksBlockToCache(BlockDescription, + SequenceIndexChunksLeftToWriteCounters, + Work, + CompositeBuffer(std::move(BlockBuffer)), + RemoteChunkIndexNeedsCopyFromSourceFlags, + WriteCache)) + { + std::error_code DummyEc; + RemoveFile(BlockChunkPath, DummyEc); + throw std::runtime_error( + fmt::format("Block {} is malformed", BlockDescription.BlockHash)); + } + + if (!BlockChunkPath.empty()) + { + std::error_code Ec = TryRemoveFile(BlockChunkPath); + if (Ec) + { + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + BlockChunkPath, + Ec.value(), + Ec.message()); + } + } + + WritePartsComplete++; + + if (WritePartsComplete == TotalPartWriteCount) + { + FilteredWrittenBytesPerSecond.Stop(); + } + } + }); } } } @@ -1954,7 +1946,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) .RemainingCount = m_Options.PrimeCacheOnly ? (TotalRequestCount - m_DownloadStats.RequestsCompleteCount.load()) : ((BytesToWrite + BytesToValidate) - (m_WrittenChunkByteCount.load() + m_ValidatedChunkByteCount.load())), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); } @@ -1988,11 +1980,11 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) const uint32_t ExpectedSequenceCount = m_RemoteContent.ChunkedContent.ChunkCounts[SequenceIndex]; if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "{}: Max count {}, Current count {}", - IncompletePath, - ExpectedSequenceCount, - SequenceIndexChunksLeftToWriteCounter.load()); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "{}: Max count {}, Current count {}", + IncompletePath, + ExpectedSequenceCount, + SequenceIndexChunksLeftToWriteCounter.load()); } ZEN_ASSERT(SequenceIndexChunksLeftToWriteCounter.load() <= ExpectedSequenceCount); } @@ -2010,16 +2002,17 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) { CloneDetails = fmt::format(" ({} cloned)", NiceBytes(m_DiskStats.CloneByteCount.load())); } - LOG_OUTPUT(m_LogOutput, - "Downloaded {} ({}bits/s) in {}. Wrote {} ({}B/s){} in {}. Completed in {}", - NiceBytes(DownloadedBytes), - NiceNum(GetBytesPerSecond(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS(), DownloadedBytes * 8)), - NiceTimeSpanMs(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS() / 1000), - NiceBytes(m_WrittenChunkByteCount.load()), - NiceNum(GetBytesPerSecond(FilteredWrittenBytesPerSecond.GetElapsedTimeUS(), m_DiskStats.WriteByteCount.load())), - CloneDetails, - NiceTimeSpanMs(FilteredWrittenBytesPerSecond.GetElapsedTimeUS() / 1000), - NiceTimeSpanMs(WriteTimer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO( + m_LogOutput, + "Downloaded {} ({}bits/s) in {}. Wrote {} ({}B/s){} in {}. Completed in {}", + NiceBytes(DownloadedBytes), + NiceNum(GetBytesPerSecond(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS(), DownloadedBytes * 8)), + NiceTimeSpanMs(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS() / 1000), + NiceBytes(m_WrittenChunkByteCount.load()), + NiceNum(GetBytesPerSecond(FilteredWrittenBytesPerSecond.GetElapsedTimeUS(), m_DiskStats.WriteByteCount.load())), + CloneDetails, + NiceTimeSpanMs(FilteredWrittenBytesPerSecond.GetElapsedTimeUS() / 1000), + NiceTimeSpanMs(WriteTimer.GetElapsedTimeMs())); } m_WriteChunkStats.WriteChunksElapsedWallTimeUs = WriteTimer.GetElapsedTimeUs(); @@ -2032,7 +2025,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) return; } - m_LogOutput.SetLogOperationProgress(TaskSteps::PrepareTarget, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::PrepareTarget, (uint32_t)TaskSteps::StepCount); tsl::robin_map<uint32_t, uint32_t> RemotePathIndexToLocalPathIndex; RemotePathIndexToLocalPathIndex.reserve(m_RemoteContent.Paths.size()); @@ -2142,9 +2135,10 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) Stopwatch Timer; - std::unique_ptr<BuildOpLogOutput::ProgressBar> CacheLocalProgressBarPtr(m_LogOutput.CreateProgressBar("Cache Local Data")); - BuildOpLogOutput::ProgressBar& CacheLocalProgressBar(*CacheLocalProgressBarPtr); - ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); + std::unique_ptr<OperationLogOutput::ProgressBar> CacheLocalProgressBarPtr( + m_LogOutput.CreateProgressBar("Cache Local Data")); + OperationLogOutput::ProgressBar& CacheLocalProgressBar(*CacheLocalProgressBarPtr); + ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); for (uint32_t LocalPathIndex : FilesToCache) { @@ -2166,12 +2160,12 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) std::error_code Ec = RenameFileWithRetry(LocalFilePath, CacheFilePath); if (Ec) { - LOG_OUTPUT_WARN(m_LogOutput, - "Failed to move file from '{}' to '{}', reason: ({}) {}, retrying...", - LocalFilePath, - CacheFilePath, - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_WARN(m_LogOutput, + "Failed to move file from '{}' to '{}', reason: ({}) {}, retrying...", + LocalFilePath, + CacheFilePath, + Ec.value(), + Ec.message()); Ec = RenameFileWithRetry(LocalFilePath, CacheFilePath); if (Ec) { @@ -2203,7 +2197,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) .Details = Details, .TotalCount = gsl::narrow<uint64_t>(WorkTotal), .RemainingCount = gsl::narrow<uint64_t>(WorkTotal - WorkComplete), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); } @@ -2214,20 +2208,20 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) return; } - LOG_OUTPUT_DEBUG(m_LogOutput, - "Local state prep: Match: {}, PathMismatch: {}, HashMismatch: {}, Cached: {} ({}), Skipped: {}, " - "Delete: {}", - MatchCount, - PathMismatchCount, - HashMismatchCount, - CachedCount.load(), - NiceBytes(CachedByteCount.load()), - SkippedCount, - DeleteCount); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Local state prep: Match: {}, PathMismatch: {}, HashMismatch: {}, Cached: {} ({}), Skipped: {}, " + "Delete: {}", + MatchCount, + PathMismatchCount, + HashMismatchCount, + CachedCount.load(), + NiceBytes(CachedByteCount.load()), + SkippedCount, + DeleteCount); } } - m_LogOutput.SetLogOperationProgress(TaskSteps::FinalizeTarget, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::FinalizeTarget, (uint32_t)TaskSteps::StepCount); if (m_Options.WipeTargetFolder) { @@ -2237,7 +2231,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) // Clean target folder if (!CleanDirectory(m_LogOutput, m_IOWorkerPool, m_AbortFlag, m_PauseFlag, m_Options.IsQuiet, m_Path, m_Options.ExcludeFolders)) { - LOG_OUTPUT_WARN(m_LogOutput, "Some files in {} could not be removed", m_Path); + ZEN_OPERATION_LOG_WARN(m_LogOutput, "Some files in {} could not be removed", m_Path); } m_RebuildFolderStateStats.CleanFolderElapsedWallTimeUs = Timer.GetElapsedTimeUs(); } @@ -2252,9 +2246,9 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) Stopwatch Timer; - std::unique_ptr<BuildOpLogOutput::ProgressBar> RebuildProgressBarPtr(m_LogOutput.CreateProgressBar("Rebuild State")); - BuildOpLogOutput::ProgressBar& RebuildProgressBar(*RebuildProgressBarPtr); - ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); + std::unique_ptr<OperationLogOutput::ProgressBar> RebuildProgressBarPtr(m_LogOutput.CreateProgressBar("Rebuild State")); + OperationLogOutput::ProgressBar& RebuildProgressBar(*RebuildProgressBarPtr); + ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); OutLocalFolderState.Paths.resize(m_RemoteContent.Paths.size()); OutLocalFolderState.RawSizes.resize(m_RemoteContent.Paths.size()); @@ -2411,7 +2405,10 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) std::filesystem::path SourceFilePath = (m_Path / SourcePath).make_preferred(); ZEN_ASSERT_SLOW(IsFileWithRetry(SourceFilePath)); - LOG_OUTPUT_DEBUG(m_LogOutput, "Copying from '{}' -> '{}'", SourceFilePath, FirstTargetFilePath); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Copying from '{}' -> '{}'", + SourceFilePath, + FirstTargetFilePath); const uint64_t RawSize = m_LocalContent.RawSizes[LocalPathIndex]; FastCopyFile(m_Options.AllowFileClone, m_Options.UseSparseFiles, @@ -2435,12 +2432,12 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) std::error_code Ec = RenameFileWithRetry(CacheFilePath, FirstTargetFilePath); if (Ec) { - LOG_OUTPUT_WARN(m_LogOutput, - "Failed to move file from '{}' to '{}', reason: ({}) {}, retrying...", - CacheFilePath, - FirstTargetFilePath, - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_WARN(m_LogOutput, + "Failed to move file from '{}' to '{}', reason: ({}) {}, retrying...", + CacheFilePath, + FirstTargetFilePath, + Ec.value(), + Ec.message()); Ec = RenameFileWithRetry(CacheFilePath, FirstTargetFilePath); if (Ec) { @@ -2498,7 +2495,10 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) } ZEN_ASSERT_SLOW(IsFileWithRetry(FirstTargetFilePath)); - LOG_OUTPUT_DEBUG(m_LogOutput, "Copying from '{}' -> '{}'", FirstTargetFilePath, TargetFilePath); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Copying from '{}' -> '{}'", + FirstTargetFilePath, + TargetFilePath); const uint64_t RawSize = m_RemoteContent.RawSizes[RemotePathIndex]; FastCopyFile(m_Options.AllowFileClone, m_Options.UseSparseFiles, @@ -2546,7 +2546,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) .Details = Details, .TotalCount = gsl::narrow<uint64_t>(WorkTotal), .RemainingCount = gsl::narrow<uint64_t>(WorkTotal - WorkComplete), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); } @@ -2554,7 +2554,7 @@ BuildsOperationUpdateFolder::Execute(FolderContent& OutLocalFolderState) m_RebuildFolderStateStats.FinalizeTreeElapsedWallTimeUs = Timer.GetElapsedTimeUs(); RebuildProgressBar.Finish(); } - m_LogOutput.SetLogOperationProgress(TaskSteps::Cleanup, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::Cleanup, (uint32_t)TaskSteps::StepCount); } catch (const std::exception&) { @@ -2618,11 +2618,11 @@ BuildsOperationUpdateFolder::ScanCacheFolder(tsl::robin_map<IoHash, uint32_t, Io std::error_code Ec = TryRemoveFile(CacheDirContent.Files[Index]); if (Ec) { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - CacheDirContent.Files[Index], - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + CacheDirContent.Files[Index], + Ec.value(), + Ec.message()); } } m_CacheMappingStats.CacheScanElapsedWallTimeUs += CacheTimer.GetElapsedTimeUs(); @@ -2678,11 +2678,11 @@ BuildsOperationUpdateFolder::ScanTempBlocksFolder(tsl::robin_map<IoHash, uint32_ std::error_code Ec = TryRemoveFile(BlockDirContent.Files[Index]); if (Ec) { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - BlockDirContent.Files[Index], - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + BlockDirContent.Files[Index], + Ec.value(), + Ec.message()); } } @@ -2731,7 +2731,7 @@ BuildsOperationUpdateFolder::FindScavengeSources() } else { - LOG_OUTPUT_WARN(m_LogOutput, "Invalid download state file at {}. '{}'", EntryPath, JsonError); + ZEN_OPERATION_LOG_WARN(m_LogOutput, "Invalid download state file at {}. '{}'", EntryPath, JsonError); DeleteEntry = true; } @@ -2767,7 +2767,11 @@ BuildsOperationUpdateFolder::ScanTargetFolder(const tsl::robin_map<IoHash, uint3 ZEN_ASSERT_SLOW(IsFile(CacheFilePath)); if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Found sequence {} at {} ({})", RemoteSequenceRawHash, CacheFilePath, NiceBytes(RemoteRawSize)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Found sequence {} at {} ({})", + RemoteSequenceRawHash, + CacheFilePath, + NiceBytes(RemoteRawSize)); } } else if (auto CacheChunkIt = CachedChunkHashesFound.find(RemoteSequenceRawHash); CacheChunkIt != CachedChunkHashesFound.end()) @@ -2776,7 +2780,11 @@ BuildsOperationUpdateFolder::ScanTargetFolder(const tsl::robin_map<IoHash, uint3 ZEN_ASSERT_SLOW(IsFile(CacheFilePath)); if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Found chunk {} at {} ({})", RemoteSequenceRawHash, CacheFilePath, NiceBytes(RemoteRawSize)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Found chunk {} at {} ({})", + RemoteSequenceRawHash, + CacheFilePath, + NiceBytes(RemoteRawSize)); } } else if (auto It = m_LocalLookup.RawHashToSequenceIndex.find(RemoteSequenceRawHash); @@ -2790,7 +2798,11 @@ BuildsOperationUpdateFolder::ScanTargetFolder(const tsl::robin_map<IoHash, uint3 m_CacheMappingStats.LocalPathsMatchingSequencesByteCount += RemoteRawSize; if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Found sequence {} at {} ({})", RemoteSequenceRawHash, LocalFilePath, NiceBytes(RemoteRawSize)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Found sequence {} at {} ({})", + RemoteSequenceRawHash, + LocalFilePath, + NiceBytes(RemoteRawSize)); } } else @@ -3160,11 +3172,11 @@ BuildsOperationUpdateFolder::WriteLooseChunk(const uint32_t RemoteChunkInd std::error_code Ec = TryRemoveFile(CompressedChunkPath); if (Ec) { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - CompressedChunkPath, - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + CompressedChunkPath, + Ec.value(), + Ec.message()); } std::vector<uint32_t> CompletedSequences = @@ -3484,12 +3496,12 @@ BuildsOperationUpdateFolder::CalculateBlockRanges(uint32_t BlockIndex, { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Range request of {} ({:.2f}%) using single range from block {} ({}) as is", - NiceBytes(OutTotalWantedChunksSize), - RangeWantedPercent, - BlockDescription.BlockHash, - NiceBytes(TotalBlockSize)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Range request of {} ({:.2f}%) using single range from block {} ({}) as is", + NiceBytes(OutTotalWantedChunksSize), + RangeWantedPercent, + BlockDescription.BlockHash, + NiceBytes(TotalBlockSize)); } return BlockRanges; } @@ -3502,7 +3514,7 @@ BuildsOperationUpdateFolder::CalculateBlockRanges(uint32_t BlockIndex, const double RangeRequestedPercent = (MergedRange.RangeLength * 100.0) / TotalBlockSize; const double WastedPercent = ((MergedRange.RangeLength - OutTotalWantedChunksSize) * 100.0) / MergedRange.RangeLength; - LOG_OUTPUT( + ZEN_OPERATION_LOG_INFO( m_LogOutput, "Range request of {} ({:.2f}%) using {} ranges from block {} ({}) limited to single block range {} ({:.2f}%) wasting " "{:.2f}% ({})", @@ -3527,19 +3539,20 @@ BuildsOperationUpdateFolder::CalculateBlockRanges(uint32_t BlockIndex, const double RangeRequestedPercent = (MergedRange.RangeLength * 100.0) / TotalBlockSize; const double WastedPercent = ((MergedRange.RangeLength - OutTotalWantedChunksSize) * 100.0) / MergedRange.RangeLength; - LOG_OUTPUT(m_LogOutput, - "Range request of {} ({:.2f}%) using {} ranges from block {} ({}) exceeds {}%. Merged to single block range {} " - "({:.2f}%) wasting {:.2f}% ({})", - NiceBytes(OutTotalWantedChunksSize), - RangeWantedPercent, - BlockRanges.size(), - BlockDescription.BlockHash, - NiceBytes(TotalBlockSize), - FullBlockRangePercentLimit, - NiceBytes(MergedRange.RangeLength), - RangeRequestedPercent, - WastedPercent, - NiceBytes(MergedRange.RangeLength - OutTotalWantedChunksSize)); + ZEN_OPERATION_LOG_INFO( + m_LogOutput, + "Range request of {} ({:.2f}%) using {} ranges from block {} ({}) exceeds {}%. Merged to single block range {} " + "({:.2f}%) wasting {:.2f}% ({})", + NiceBytes(OutTotalWantedChunksSize), + RangeWantedPercent, + BlockRanges.size(), + BlockDescription.BlockHash, + NiceBytes(TotalBlockSize), + FullBlockRangePercentLimit, + NiceBytes(MergedRange.RangeLength), + RangeRequestedPercent, + WastedPercent, + NiceBytes(MergedRange.RangeLength - OutTotalWantedChunksSize)); } return MakeOptionalBlockRangeVector(TotalBlockSize, MergedRange); } @@ -3562,7 +3575,7 @@ BuildsOperationUpdateFolder::CalculateBlockRanges(uint32_t BlockIndex, { const double WastedPercent = ((WantedCollapsedSize - OutTotalWantedChunksSize) * 100.0) / WantedCollapsedSize; - LOG_OUTPUT( + ZEN_OPERATION_LOG_INFO( m_LogOutput, "Range request of {} ({:.2f}%) using {} ranges from block {} ({}) collapsed to {} {:.2f}% using {} ranges wasting {:.2f}% " "({})", @@ -3876,7 +3889,7 @@ BuildsOperationUpdateFolder::WriteLocalChunkToCache(CloneQueryInterface* C if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Copied {} from {}", NiceBytes(CacheLocalFileBytesRead), SourceFilePath); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Copied {} from {}", NiceBytes(CacheLocalFileBytesRead), SourceFilePath); } std::vector<uint32_t> Result; @@ -4436,11 +4449,11 @@ BuildsOperationUpdateFolder::AsyncWriteDownloadedChunk(const std::filesystem::pa std::error_code Ec = TryRemoveFile(CompressedChunkPath); if (Ec) { - LOG_OUTPUT_DEBUG(m_LogOutput, - "Failed removing file '{}', reason: ({}) {}", - CompressedChunkPath, - Ec.value(), - Ec.message()); + ZEN_OPERATION_LOG_DEBUG(m_LogOutput, + "Failed removing file '{}', reason: ({}) {}", + CompressedChunkPath, + Ec.value(), + Ec.message()); } } @@ -4592,7 +4605,7 @@ BuildsOperationUpdateFolder::VerifySequence(uint32_t RemoteSequenceIndex) ////////////////////// BuildsOperationUploadFolder -BuildsOperationUploadFolder::BuildsOperationUploadFolder(BuildOpLogOutput& LogOutput, +BuildsOperationUploadFolder::BuildsOperationUploadFolder(OperationLogOutput& OperationLogOutput, StorageInstance& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -4606,7 +4619,7 @@ BuildsOperationUploadFolder::BuildsOperationUploadFolder(BuildOpLogOutput& L bool CreateBuild, const CbObject& MetaData, const Options& Options) -: m_LogOutput(LogOutput) +: m_LogOutput(OperationLogOutput) , m_Storage(Storage) , m_AbortFlag(AbortFlag) , m_PauseFlag(PauseFlag) @@ -4634,19 +4647,22 @@ BuildsOperationUploadFolder::Execute() ZEN_TRACE_CPU("BuildsOperationUploadFolder::Execute"); try { - enum TaskSteps : uint32_t + enum class TaskSteps : uint32_t { PrepareBuild, CalculateDelta, GenerateBlocks, BuildPartManifest, - Upload, + UploadBuildPart, + UploadAttachments, FinalizeBuild, + PutBuildPartStats, Cleanup, StepCount }; - auto EndProgress = MakeGuard([&]() { m_LogOutput.SetLogOperationProgress(TaskSteps::StepCount, TaskSteps::StepCount); }); + auto EndProgress = + MakeGuard([&]() { m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::StepCount, (uint32_t)TaskSteps::StepCount); }); Stopwatch ProcessTimer; @@ -4654,7 +4670,7 @@ BuildsOperationUploadFolder::Execute() CreateDirectories(m_Options.TempDir); auto _ = MakeGuard([&]() { CleanAndRemoveDirectory(m_IOWorkerPool, m_AbortFlag, m_PauseFlag, m_Options.TempDir); }); - m_LogOutput.SetLogOperationProgress(TaskSteps::PrepareBuild, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::PrepareBuild, (uint32_t)TaskSteps::StepCount); std::uint64_t TotalRawSize = 0; @@ -4700,9 +4716,9 @@ BuildsOperationUploadFolder::Execute() } else if (m_Options.AllowMultiparts) { - LOG_OUTPUT_WARN(m_LogOutput, - "PreferredMultipartChunkSize is unknown. Defaulting to '{}'", - NiceBytes(Result.PreferredMultipartChunkSize)); + ZEN_OPERATION_LOG_WARN(m_LogOutput, + "PreferredMultipartChunkSize is unknown. Defaulting to '{}'", + NiceBytes(Result.PreferredMultipartChunkSize)); } } @@ -4761,7 +4777,10 @@ BuildsOperationUploadFolder::Execute() m_IOWorkerPool, m_LogOutput.GetProgressUpdateDelayMS(), [&](bool, std::ptrdiff_t) { - LOG_OUTPUT(m_LogOutput, "Found {} files in '{}'...", m_LocalFolderScanStats.AcceptedFileCount.load(), m_Path); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Found {} files in '{}'...", + m_LocalFolderScanStats.AcceptedFileCount.load(), + m_Path); }, m_AbortFlag); } @@ -4814,8 +4833,8 @@ BuildsOperationUploadFolder::Execute() TotalRawSize = std::accumulate(Content.RawSizes.begin(), Content.RawSizes.end(), std::uint64_t(0)); { - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Scan Folder")); - BuildOpLogOutput::ProgressBar& Progress(*ProgressBarPtr); + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Scan Folder")); + OperationLogOutput::ProgressBar& Progress(*ProgressBarPtr); FilteredRate FilteredBytesHashed; FilteredBytesHashed.Start(); @@ -4840,7 +4859,7 @@ BuildsOperationUploadFolder::Execute() .Details = Details, .TotalCount = TotalRawSize, .RemainingCount = TotalRawSize - m_ChunkingStats.BytesHashed.load(), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }, m_AbortFlag, @@ -4855,15 +4874,15 @@ BuildsOperationUploadFolder::Execute() if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Found {} ({}) files divided into {} ({}) unique chunks in '{}' in {}. Average hash rate {}B/sec", - LocalContent.Paths.size(), - NiceBytes(TotalRawSize), - m_ChunkingStats.UniqueChunksFound.load(), - NiceBytes(m_ChunkingStats.UniqueBytesFound.load()), - m_Path, - NiceTimeSpanMs(ScanTimer.GetElapsedTimeMs()), - NiceNum(GetBytesPerSecond(m_ChunkingStats.ElapsedWallTimeUS, m_ChunkingStats.BytesHashed))); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Found {} ({}) files divided into {} ({}) unique chunks in '{}' in {}. Average hash rate {}B/sec", + LocalContent.Paths.size(), + NiceBytes(TotalRawSize), + m_ChunkingStats.UniqueChunksFound.load(), + NiceBytes(m_ChunkingStats.UniqueBytesFound.load()), + m_Path, + NiceTimeSpanMs(ScanTimer.GetElapsedTimeMs()), + NiceNum(GetBytesPerSecond(m_ChunkingStats.ElapsedWallTimeUS, m_ChunkingStats.BytesHashed))); } } @@ -4876,19 +4895,19 @@ BuildsOperationUploadFolder::Execute() if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Build prepare took {}. {} took {}, payload size {}{}", - NiceTimeSpanMs(PrepBuildResult.ElapsedTimeMs), - m_CreateBuild ? "PutBuild" : "GetBuild", - NiceTimeSpanMs(PrepBuildResult.PrepareBuildTimeMs), - NiceBytes(PrepBuildResult.PayloadSize), - m_Options.IgnoreExistingBlocks ? "" - : fmt::format(". Found {} blocks in {}", - PrepBuildResult.KnownBlocks.size(), - NiceTimeSpanMs(PrepBuildResult.FindBlocksTimeMs))); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Build prepare took {}. {} took {}, payload size {}{}", + NiceTimeSpanMs(PrepBuildResult.ElapsedTimeMs), + m_CreateBuild ? "PutBuild" : "GetBuild", + NiceTimeSpanMs(PrepBuildResult.PrepareBuildTimeMs), + NiceBytes(PrepBuildResult.PayloadSize), + m_Options.IgnoreExistingBlocks ? "" + : fmt::format(". Found {} blocks in {}", + PrepBuildResult.KnownBlocks.size(), + NiceTimeSpanMs(PrepBuildResult.FindBlocksTimeMs))); } - m_LogOutput.SetLogOperationProgress(TaskSteps::CalculateDelta, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::CalculateDelta, (uint32_t)TaskSteps::StepCount); const std::uint64_t LargeAttachmentSize = m_Options.AllowMultiparts ? PrepBuildResult.PreferredMultipartChunkSize * 4u : (std::uint64_t)-1; @@ -4920,7 +4939,7 @@ BuildsOperationUploadFolder::Execute() { if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, "Ignoring any existing blocks in store"); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Ignoring any existing blocks in store"); } NewBlockChunkIndexes = std::move(BlockChunkIndexes); } @@ -4965,43 +4984,43 @@ BuildsOperationUploadFolder::Execute() : 0.0; if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Found {} chunks in {} ({}) blocks eligible for reuse in {}\n" - " Reusing {} ({}) matching chunks in {} blocks ({:.1f}%)\n" - " Accepting {} ({}) redundant chunks ({:.1f}%)\n" - " Rejected {} ({}) chunks in {} blocks\n" - " Arranged {} ({}) chunks in {} new blocks\n" - " Keeping {} ({}) chunks as loose chunks\n" - " Discovery completed in {}", - m_FindBlocksStats.FoundBlockChunkCount, - m_FindBlocksStats.FoundBlockCount, - NiceBytes(m_FindBlocksStats.FoundBlockByteCount), - NiceTimeSpanMs(m_FindBlocksStats.FindBlockTimeMS), + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Found {} chunks in {} ({}) blocks eligible for reuse in {}\n" + " Reusing {} ({}) matching chunks in {} blocks ({:.1f}%)\n" + " Accepting {} ({}) redundant chunks ({:.1f}%)\n" + " Rejected {} ({}) chunks in {} blocks\n" + " Arranged {} ({}) chunks in {} new blocks\n" + " Keeping {} ({}) chunks as loose chunks\n" + " Discovery completed in {}", + m_FindBlocksStats.FoundBlockChunkCount, + m_FindBlocksStats.FoundBlockCount, + NiceBytes(m_FindBlocksStats.FoundBlockByteCount), + NiceTimeSpanMs(m_FindBlocksStats.FindBlockTimeMS), - m_FindBlocksStats.AcceptedChunkCount, - NiceBytes(m_FindBlocksStats.AcceptedRawByteCount), - m_FindBlocksStats.AcceptedBlockCount, - AcceptedByteCountPercent, + m_FindBlocksStats.AcceptedChunkCount, + NiceBytes(m_FindBlocksStats.AcceptedRawByteCount), + m_FindBlocksStats.AcceptedBlockCount, + AcceptedByteCountPercent, - m_FindBlocksStats.AcceptedReduntantChunkCount, - NiceBytes(m_FindBlocksStats.AcceptedReduntantByteCount), - AcceptedReduntantByteCountPercent, + m_FindBlocksStats.AcceptedReduntantChunkCount, + NiceBytes(m_FindBlocksStats.AcceptedReduntantByteCount), + AcceptedReduntantByteCountPercent, - m_FindBlocksStats.RejectedChunkCount, - NiceBytes(m_FindBlocksStats.RejectedByteCount), - m_FindBlocksStats.RejectedBlockCount, + m_FindBlocksStats.RejectedChunkCount, + NiceBytes(m_FindBlocksStats.RejectedByteCount), + m_FindBlocksStats.RejectedBlockCount, - m_FindBlocksStats.NewBlocksChunkCount, - NiceBytes(m_FindBlocksStats.NewBlocksChunkByteCount), - m_FindBlocksStats.NewBlocksCount, + m_FindBlocksStats.NewBlocksChunkCount, + NiceBytes(m_FindBlocksStats.NewBlocksChunkByteCount), + m_FindBlocksStats.NewBlocksCount, - m_LooseChunksStats.ChunkCount, - NiceBytes(m_LooseChunksStats.ChunkByteCount), + m_LooseChunksStats.ChunkCount, + NiceBytes(m_LooseChunksStats.ChunkByteCount), - NiceTimeSpanMs(BlockArrangeTimer.GetElapsedTimeMs())); + NiceTimeSpanMs(BlockArrangeTimer.GetElapsedTimeMs())); } - m_LogOutput.SetLogOperationProgress(TaskSteps::GenerateBlocks, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::GenerateBlocks, (uint32_t)TaskSteps::StepCount); GeneratedBlocks NewBlocks; if (!NewBlockChunks.empty()) @@ -5011,22 +5030,23 @@ BuildsOperationUploadFolder::Execute() uint64_t BlockGenerateTimeUs = GenerateBuildBlocksTimer.GetElapsedTimeUs(); if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Generated {} ({}) and uploaded {} ({}) blocks in {}. Generate speed: {}B/sec. Transfer speed {}bits/sec.", - m_GenerateBlocksStats.GeneratedBlockCount.load(), - NiceBytes(m_GenerateBlocksStats.GeneratedBlockByteCount), - m_UploadStats.BlockCount.load(), - NiceBytes(m_UploadStats.BlocksBytes.load()), - NiceTimeSpanMs(BlockGenerateTimeUs / 1000), - NiceNum(GetBytesPerSecond(m_GenerateBlocksStats.GenerateBlocksElapsedWallTimeUS, - m_GenerateBlocksStats.GeneratedBlockByteCount)), - NiceNum(GetBytesPerSecond(m_UploadStats.ElapsedWallTimeUS, m_UploadStats.BlocksBytes * 8))); + ZEN_OPERATION_LOG_INFO( + m_LogOutput, + "Generated {} ({}) and uploaded {} ({}) blocks in {}. Generate speed: {}B/sec. Transfer speed {}bits/sec.", + m_GenerateBlocksStats.GeneratedBlockCount.load(), + NiceBytes(m_GenerateBlocksStats.GeneratedBlockByteCount), + m_UploadStats.BlockCount.load(), + NiceBytes(m_UploadStats.BlocksBytes.load()), + NiceTimeSpanMs(BlockGenerateTimeUs / 1000), + NiceNum(GetBytesPerSecond(m_GenerateBlocksStats.GenerateBlocksElapsedWallTimeUS, + m_GenerateBlocksStats.GeneratedBlockByteCount)), + NiceNum(GetBytesPerSecond(m_UploadStats.ElapsedWallTimeUS, m_UploadStats.BlocksBytes * 8))); } }); GenerateBuildBlocks(LocalContent, LocalLookup, NewBlockChunks, NewBlocks); } - m_LogOutput.SetLogOperationProgress(TaskSteps::BuildPartManifest, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::BuildPartManifest, (uint32_t)TaskSteps::StepCount); CbObject PartManifest; { @@ -5035,10 +5055,10 @@ BuildsOperationUploadFolder::Execute() auto __ = MakeGuard([&]() { if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Generated build part manifest in {} ({})", - NiceTimeSpanMs(ManifestGenerationTimer.GetElapsedTimeMs()), - NiceBytes(PartManifestWriter.GetSaveSize())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Generated build part manifest in {} ({})", + NiceTimeSpanMs(ManifestGenerationTimer.GetElapsedTimeMs()), + NiceBytes(PartManifestWriter.GetSaveSize())); } }); PartManifestWriter.AddObject("chunker"sv, ChunkerParameters); @@ -5185,18 +5205,18 @@ BuildsOperationUploadFolder::Execute() PartManifest = PartManifestWriter.Save(); } - m_LogOutput.SetLogOperationProgress(TaskSteps::Upload, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::UploadBuildPart, (uint32_t)TaskSteps::StepCount); Stopwatch PutBuildPartResultTimer; std::pair<IoHash, std::vector<IoHash>> PutBuildPartResult = m_Storage.BuildStorage->PutBuildPart(m_BuildId, m_BuildPartId, m_BuildPartName, PartManifest); if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "PutBuildPart took {}, payload size {}. {} attachments are needed.", - NiceTimeSpanMs(PutBuildPartResultTimer.GetElapsedTimeMs()), - NiceBytes(PartManifest.GetSize()), - PutBuildPartResult.second.size()); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "PutBuildPart took {}, payload size {}. {} attachments are needed.", + NiceTimeSpanMs(PutBuildPartResultTimer.GetElapsedTimeMs()), + NiceBytes(PartManifest.GetSize()), + PutBuildPartResult.second.size()); } IoHash PartHash = PutBuildPartResult.first; @@ -5213,23 +5233,24 @@ BuildsOperationUploadFolder::Execute() if (!m_Options.IsQuiet) { uint64_t TempChunkUploadTimeUs = TempUploadTimer.GetElapsedTimeUs(); - LOG_OUTPUT(m_LogOutput, - "Uploaded {} ({}) blocks. " - "Compressed {} ({} {}B/s) and uploaded {} ({}) chunks. " - "Transferred {} ({}bits/s) in {}", - TempUploadStats.BlockCount.load(), - NiceBytes(TempUploadStats.BlocksBytes), - - TempLooseChunksStats.CompressedChunkCount.load(), - NiceBytes(TempLooseChunksStats.CompressedChunkBytes.load()), - NiceNum(GetBytesPerSecond(TempLooseChunksStats.CompressChunksElapsedWallTimeUS, - TempLooseChunksStats.ChunkByteCount)), - TempUploadStats.ChunkCount.load(), - NiceBytes(TempUploadStats.ChunksBytes), - - NiceBytes(TempUploadStats.BlocksBytes + TempUploadStats.ChunksBytes), - NiceNum(GetBytesPerSecond(TempUploadStats.ElapsedWallTimeUS, TempUploadStats.ChunksBytes * 8)), - NiceTimeSpanMs(TempChunkUploadTimeUs / 1000)); + ZEN_OPERATION_LOG_INFO( + m_LogOutput, + "Uploaded {} ({}) blocks. " + "Compressed {} ({} {}B/s) and uploaded {} ({}) chunks. " + "Transferred {} ({}bits/s) in {}", + TempUploadStats.BlockCount.load(), + NiceBytes(TempUploadStats.BlocksBytes), + + TempLooseChunksStats.CompressedChunkCount.load(), + NiceBytes(TempLooseChunksStats.CompressedChunkBytes.load()), + NiceNum(GetBytesPerSecond(TempLooseChunksStats.CompressChunksElapsedWallTimeUS, + TempLooseChunksStats.ChunkByteCount)), + TempUploadStats.ChunkCount.load(), + NiceBytes(TempUploadStats.ChunksBytes), + + NiceBytes(TempUploadStats.BlocksBytes + TempUploadStats.ChunksBytes), + NiceNum(GetBytesPerSecond(TempUploadStats.ElapsedWallTimeUS, TempUploadStats.ChunksBytes * 8)), + NiceTimeSpanMs(TempChunkUploadTimeUs / 1000)); } }); UploadPartBlobs(LocalContent, @@ -5247,14 +5268,16 @@ BuildsOperationUploadFolder::Execute() } }; + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::UploadAttachments, (uint32_t)TaskSteps::StepCount); + std::vector<IoHash> UnknownChunks; if (m_Options.IgnoreExistingBlocks) { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "PutBuildPart uploading all attachments, needs are: {}", - FormatArray<IoHash>(PutBuildPartResult.second, "\n "sv)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "PutBuildPart uploading all attachments, needs are: {}", + FormatArray<IoHash>(PutBuildPartResult.second, "\n "sv)); } std::vector<IoHash> ForceUploadChunkHashes; @@ -5279,7 +5302,9 @@ BuildsOperationUploadFolder::Execute() { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "PutBuildPart needs attachments: {}", FormatArray<IoHash>(PutBuildPartResult.second, "\n "sv)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "PutBuildPart needs attachments: {}", + FormatArray<IoHash>(PutBuildPartResult.second, "\n "sv)); } UploadAttachments(PutBuildPartResult.second, UnknownChunks); } @@ -5304,10 +5329,10 @@ BuildsOperationUploadFolder::Execute() std::vector<IoHash> Needs = m_Storage.BuildStorage->FinalizeBuildPart(m_BuildId, m_BuildPartId, PartHash); if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "FinalizeBuildPart took {}. {} attachments are missing.", - NiceTimeSpanMs(FinalizeBuildPartTimer.GetElapsedTimeMs()), - Needs.size()); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "FinalizeBuildPart took {}. {} attachments are missing.", + NiceTimeSpanMs(FinalizeBuildPartTimer.GetElapsedTimeMs()), + Needs.size()); } if (Needs.empty()) { @@ -5315,7 +5340,7 @@ BuildsOperationUploadFolder::Execute() } if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "FinalizeBuildPart needs attachments: {}", FormatArray<IoHash>(Needs, "\n "sv)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "FinalizeBuildPart needs attachments: {}", FormatArray<IoHash>(Needs, "\n "sv)); } std::vector<IoHash> RetryUnknownChunks; @@ -5340,7 +5365,7 @@ BuildsOperationUploadFolder::Execute() throw std::runtime_error(BuildUnkownChunksResponse(UnknownChunks, /*WillRetry*/ false)); } - m_LogOutput.SetLogOperationProgress(TaskSteps::FinalizeBuild, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::FinalizeBuild, (uint32_t)TaskSteps::StepCount); if (m_CreateBuild && !m_AbortFlag) { @@ -5348,7 +5373,7 @@ BuildsOperationUploadFolder::Execute() m_Storage.BuildStorage->FinalizeBuild(m_BuildId); if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, "FinalizeBuild took {}", NiceTimeSpanMs(FinalizeBuildTimer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "FinalizeBuild took {}", NiceTimeSpanMs(FinalizeBuildTimer.GetElapsedTimeMs())); } } @@ -5399,14 +5424,16 @@ BuildsOperationUploadFolder::Execute() m_UploadStats.ElapsedWallTimeUS += ElapsedUS; if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Uploaded metadata for {} blocks in {}", - UploadBlockMetadataCount, - NiceTimeSpanMs(ElapsedUS / 1000)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Uploaded metadata for {} blocks in {}", + UploadBlockMetadataCount, + NiceTimeSpanMs(ElapsedUS / 1000)); } } } + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::PutBuildPartStats, (uint32_t)TaskSteps::StepCount); + m_Storage.BuildStorage->PutBuildPartStats( m_BuildId, m_BuildPartId, @@ -5422,7 +5449,7 @@ BuildsOperationUploadFolder::Execute() double(GetBytesPerSecond(m_UploadStats.ElapsedWallTimeUS, m_UploadStats.ChunksBytes + m_UploadStats.BlocksBytes))}, {"elapsedTimeSec", double(ProcessTimer.GetElapsedTimeMs() / 1000.0)}}); - m_LogOutput.SetLogOperationProgress(TaskSteps::Cleanup, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::Cleanup, (uint32_t)TaskSteps::StepCount); } catch (const std::exception&) { @@ -5576,11 +5603,11 @@ BuildsOperationUploadFolder::FindReuseBlocks(const std::vector<ChunkBlockDescrip { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Reusing block {}. {} attachments found, usage level: {}%", - KnownBlock.BlockHash, - FoundAttachmentCount, - ReusePercent); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Reusing block {}. {} attachments found, usage level: {}%", + KnownBlock.BlockHash, + FoundAttachmentCount, + ReusePercent); } ReuseBlockIndexes.push_back(KnownBlockIndex); @@ -5591,7 +5618,8 @@ BuildsOperationUploadFolder::FindReuseBlocks(const std::vector<ChunkBlockDescrip { // if (m_Options.IsVerbose) //{ - // LOG_OUTPUT(m_LogOutput, "Skipping block {}. {} attachments found, usage level: {}%", KnownBlock.BlockHash, + // ZEN_OPERATION_LOG_INFO(m_LogOutput, "Skipping block {}. {} attachments found, usage level: {}%", + // KnownBlock.BlockHash, // FoundAttachmentCount, ReusePercent); //} m_FindBlocksStats.RejectedBlockCount++; @@ -5637,11 +5665,11 @@ BuildsOperationUploadFolder::FindReuseBlocks(const std::vector<ChunkBlockDescrip { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Reusing block {}. {} attachments found, usage level: {}%", - KnownBlock.BlockHash, - FoundChunkIndexes.size(), - ReusePercent); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Reusing block {}. {} attachments found, usage level: {}%", + KnownBlock.BlockHash, + FoundChunkIndexes.size(), + ReusePercent); } FilteredReuseBlockIndexes.push_back(KnownBlockIndex); @@ -5659,7 +5687,8 @@ BuildsOperationUploadFolder::FindReuseBlocks(const std::vector<ChunkBlockDescrip { // if (m_Options.IsVerbose) //{ - // LOG_OUTPUT(m_LogOutput, "Skipping block {}. filtered usage level: {}%", KnownBlock.BlockHash, ReusePercent); + // ZEN_OPERATION_LOG_INFO(m_LogOutput, "Skipping block {}. filtered usage level: {}%", KnownBlock.BlockHash, + // ReusePercent); //} m_FindBlocksStats.RejectedBlockCount++; m_FindBlocksStats.RejectedChunkCount += FoundChunkIndexes.size(); @@ -5784,8 +5813,8 @@ BuildsOperationUploadFolder::GenerateBuildBlocks(const ChunkedFolderContent& const std::size_t NewBlockCount = NewBlockChunks.size(); if (NewBlockCount > 0) { - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Generate Blocks")); - BuildOpLogOutput::ProgressBar& Progress(*ProgressBarPtr); + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Generate Blocks")); + OperationLogOutput::ProgressBar& Progress(*ProgressBarPtr); OutBlocks.BlockDescriptions.resize(NewBlockCount); OutBlocks.BlockSizes.resize(NewBlockCount); @@ -5839,12 +5868,12 @@ BuildsOperationUploadFolder::GenerateBuildBlocks(const ChunkedFolderContent& GenerateBlock(Content, Lookup, ChunksInBlock, OutBlocks.BlockDescriptions[BlockIndex]); if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Generated block {} ({}) containing {} chunks in {}", - OutBlocks.BlockDescriptions[BlockIndex].BlockHash, - NiceBytes(CompressedBlock.GetCompressedSize()), - OutBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size(), - NiceTimeSpanMs(GenerateTimer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Generated block {} ({}) containing {} chunks in {}", + OutBlocks.BlockDescriptions[BlockIndex].BlockHash, + NiceBytes(CompressedBlock.GetCompressedSize()), + OutBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size(), + NiceTimeSpanMs(GenerateTimer.GetElapsedTimeMs())); } OutBlocks.BlockSizes[BlockIndex] = CompressedBlock.GetCompressedSize(); @@ -5933,11 +5962,11 @@ BuildsOperationUploadFolder::GenerateBuildBlocks(const ChunkedFolderContent& if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Uploaded block {} ({}) containing {} chunks", - BlockHash, - NiceBytes(CompressedBlockSize), - OutBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size()); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Uploaded block {} ({}) containing {} chunks", + BlockHash, + NiceBytes(CompressedBlockSize), + OutBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size()); } if (m_Storage.BuildCacheStorage) @@ -5953,10 +5982,10 @@ BuildsOperationUploadFolder::GenerateBuildBlocks(const ChunkedFolderContent& { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Uploaded block {} metadata ({})", - BlockHash, - NiceBytes(BlockMetaData.GetSize())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Uploaded block {} metadata ({})", + BlockHash, + NiceBytes(BlockMetaData.GetSize())); } OutBlocks.MetaDataHasBeenUploaded[BlockIndex] = true; @@ -5997,7 +6026,7 @@ BuildsOperationUploadFolder::GenerateBuildBlocks(const ChunkedFolderContent& .Details = Details, .TotalCount = gsl::narrow<uint64_t>(NewBlockCount), .RemainingCount = gsl::narrow<uint64_t>(NewBlockCount - m_GenerateBlocksStats.GeneratedBlockCount.load()), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); @@ -6274,6 +6303,9 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co { ZEN_TRACE_CPU("UploadPartBlobs"); { + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Upload Blobs")); + OperationLogOutput::ProgressBar& Progress(*ProgressBarPtr); + WorkerThreadPool& ReadChunkPool = m_IOWorkerPool; WorkerThreadPool& UploadChunkPool = m_NetworkPool; @@ -6328,9 +6360,6 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co return; } - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Upload Blobs")); - BuildOpLogOutput::ProgressBar& Progress(*ProgressBarPtr); - uint64_t TotalRawSize = TotalLooseChunksSize + TotalBlocksSize; const size_t UploadBlockCount = BlockIndexes.size(); @@ -6402,11 +6431,11 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co m_Storage.BuildStorage->PutBuildBlob(m_BuildId, BlockHash, ZenContentType::kCompressedBinary, Payload); if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Uploaded block {} ({}) containing {} chunks", - BlockHash, - NiceBytes(PayloadSize), - NewBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size()); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Uploaded block {} ({}) containing {} chunks", + BlockHash, + NiceBytes(PayloadSize), + NewBlocks.BlockDescriptions[BlockIndex].ChunkRawHashes.size()); } UploadedBlockSize += PayloadSize; TempUploadStats.BlocksBytes += PayloadSize; @@ -6422,7 +6451,10 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co { if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Uploaded block {} metadata ({})", BlockHash, NiceBytes(BlockMetaData.GetSize())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Uploaded block {} metadata ({})", + BlockHash, + NiceBytes(BlockMetaData.GetSize())); } NewBlocks.MetaDataHasBeenUploaded[BlockIndex] = true; @@ -6532,7 +6564,7 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co } if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Uploaded multipart chunk {} ({})", RawHash, NiceBytes(PayloadSize)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Uploaded multipart chunk {} ({})", RawHash, NiceBytes(PayloadSize)); } } else @@ -6541,7 +6573,7 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co m_Storage.BuildStorage->PutBuildBlob(m_BuildId, RawHash, ZenContentType::kCompressedBinary, Payload); if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, "Uploaded chunk {} ({})", RawHash, NiceBytes(PayloadSize)); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Uploaded chunk {} ({})", RawHash, NiceBytes(PayloadSize)); } TempUploadStats.ChunksBytes += Payload.GetSize(); TempUploadStats.ChunkCount++; @@ -6620,13 +6652,13 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co } if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "{} 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())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "{} 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 (!m_AbortFlag) { @@ -6661,12 +6693,12 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co CompositeBuffer Payload = CompressChunk(Content, Lookup, ChunkIndex, TempLooseChunksStats); if (m_Options.IsVerbose) { - LOG_OUTPUT(m_LogOutput, - "Compressed chunk {} ({} -> {}) in {}", - Content.ChunkedContent.ChunkHashes[ChunkIndex], - NiceBytes(Content.ChunkedContent.ChunkRawSizes[ChunkIndex]), - NiceBytes(Payload.GetSize()), - NiceTimeSpanMs(CompressTimer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Compressed chunk {} ({} -> {}) in {}", + Content.ChunkedContent.ChunkHashes[ChunkIndex], + NiceBytes(Content.ChunkedContent.ChunkRawSizes[ChunkIndex]), + NiceBytes(Payload.GetSize()), + NiceTimeSpanMs(CompressTimer.GetElapsedTimeMs())); } const uint64_t ChunkRawSize = Content.ChunkedContent.ChunkRawSizes[ChunkIndex]; TempUploadStats.ReadFromDiskBytes += ChunkRawSize; @@ -6716,7 +6748,7 @@ BuildsOperationUploadFolder::UploadPartBlobs(const ChunkedFolderContent& Co .Details = Details, .TotalCount = gsl::narrow<uint64_t>(TotalRawSize), .RemainingCount = gsl::narrow<uint64_t>(TotalRawSize - UploadedRawSize), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); @@ -6841,7 +6873,7 @@ BuildsOperationUploadFolder::CompressChunk(const ChunkedFolderContent& Content, return std::move(CompressedBlob).GetCompressed(); } -BuildsOperationValidateBuildPart::BuildsOperationValidateBuildPart(BuildOpLogOutput& LogOutput, +BuildsOperationValidateBuildPart::BuildsOperationValidateBuildPart(OperationLogOutput& OperationLogOutput, BuildStorageBase& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -6852,7 +6884,7 @@ BuildsOperationValidateBuildPart::BuildsOperationValidateBuildPart(BuildOpLogOut const std::string_view BuildPartName, const Options& Options) -: m_LogOutput(LogOutput) +: m_LogOutput(OperationLogOutput) , m_Storage(Storage) , m_AbortFlag(AbortFlag) , m_PauseFlag(PauseFlag) @@ -6871,7 +6903,7 @@ BuildsOperationValidateBuildPart::Execute() ZEN_TRACE_CPU("ValidateBuildPart"); try { - enum TaskSteps : uint32_t + enum class TaskSteps : uint32_t { FetchBuild, FetchBuildPart, @@ -6880,7 +6912,8 @@ BuildsOperationValidateBuildPart::Execute() StepCount }; - auto EndProgress = MakeGuard([&]() { m_LogOutput.SetLogOperationProgress(TaskSteps::StepCount, TaskSteps::StepCount); }); + auto EndProgress = + MakeGuard([&]() { m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::StepCount, (uint32_t)TaskSteps::StepCount); }); Stopwatch Timer; auto _ = MakeGuard([&]() { @@ -6894,7 +6927,7 @@ BuildsOperationValidateBuildPart::Execute() } }); - m_LogOutput.SetLogOperationProgress(TaskSteps::FetchBuild, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::FetchBuild, (uint32_t)TaskSteps::StepCount); CbObject Build = m_Storage.GetBuild(m_BuildId); if (!m_BuildPartName.empty()) @@ -6912,7 +6945,7 @@ BuildsOperationValidateBuildPart::Execute() PreferredMultipartChunkSize = ChunkSize; } - m_LogOutput.SetLogOperationProgress(TaskSteps::FetchBuildPart, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::FetchBuildPart, (uint32_t)TaskSteps::StepCount); CbObject BuildPart = m_Storage.GetBuildPart(m_BuildId, m_BuildPartId); m_ValidateStats.BuildPartSize = BuildPart.GetSize(); @@ -6957,10 +6990,10 @@ BuildsOperationValidateBuildPart::Execute() CreateDirectories(TempFolder); auto __ = MakeGuard([this, TempFolder]() { CleanAndRemoveDirectory(m_IOWorkerPool, m_AbortFlag, m_PauseFlag, TempFolder); }); - m_LogOutput.SetLogOperationProgress(TaskSteps::ValidateBlobs, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::ValidateBlobs, (uint32_t)TaskSteps::StepCount); - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Validate Blobs")); - BuildOpLogOutput::ProgressBar& Progress(*ProgressBarPtr); + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Validate Blobs")); + OperationLogOutput::ProgressBar& Progress(*ProgressBarPtr); uint64_t AttachmentsToVerifyCount = ChunkAttachments.size() + BlockAttachments.size(); FilteredRate FilteredDownloadedBytesPerSecond; @@ -7124,14 +7157,14 @@ BuildsOperationValidateBuildPart::Execute() .TotalCount = gsl::narrow<uint64_t>(AttachmentsToVerifyCount * 2), .RemainingCount = gsl::narrow<uint64_t>(AttachmentsToVerifyCount * 2 - (DownloadedAttachmentCount + m_ValidateStats.VerifiedAttachmentCount.load())), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); Progress.Finish(); m_ValidateStats.ElapsedWallTimeUS = Timer.GetElapsedTimeUs(); - m_LogOutput.SetLogOperationProgress(TaskSteps::Cleanup, TaskSteps::StepCount); + m_LogOutput.SetLogOperationProgress((uint32_t)TaskSteps::Cleanup, (uint32_t)TaskSteps::StepCount); } catch (const std::exception&) { @@ -7140,7 +7173,7 @@ BuildsOperationValidateBuildPart::Execute() } } -BuildsOperationPrimeCache::BuildsOperationPrimeCache(BuildOpLogOutput& LogOutput, +BuildsOperationPrimeCache::BuildsOperationPrimeCache(OperationLogOutput& OperationLogOutput, StorageInstance& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -7149,7 +7182,7 @@ BuildsOperationPrimeCache::BuildsOperationPrimeCache(BuildOpLogOutput& LogOut std::span<const Oid> BuildPartIds, const Options& Options, BuildStorageCache::Statistics& StorageCacheStats) -: m_LogOutput(LogOutput) +: m_LogOutput(OperationLogOutput) , m_Storage(Storage) , m_AbortFlag(AbortFlag) , m_PauseFlag(PauseFlag) @@ -7203,7 +7236,7 @@ BuildsOperationPrimeCache::Execute() if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, "Found {} referenced blobs", BuildBlobs.size()); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Found {} referenced blobs", BuildBlobs.size()); } if (BuildBlobs.empty()) @@ -7236,11 +7269,11 @@ BuildsOperationPrimeCache::Execute() if (FoundCount > 0 && !m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, - "Remote cache : Found {} out of {} needed blobs in {}", - FoundCount, - BuildBlobs.size(), - NiceTimeSpanMs(Timer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Remote cache : Found {} out of {} needed blobs in {}", + FoundCount, + BuildBlobs.size(), + NiceTimeSpanMs(Timer.GetElapsedTimeMs())); } } } @@ -7259,8 +7292,8 @@ BuildsOperationPrimeCache::Execute() FilteredRate FilteredDownloadedBytesPerSecond; { - std::unique_ptr<BuildOpLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Downloading")); - BuildOpLogOutput::ProgressBar& Progress(*ProgressBarPtr); + std::unique_ptr<OperationLogOutput::ProgressBar> ProgressBarPtr(m_LogOutput.CreateProgressBar("Downloading")); + OperationLogOutput::ProgressBar& Progress(*ProgressBarPtr); ParallelWork Work(m_AbortFlag, m_PauseFlag, WorkerThreadPool::EMode::EnableBacklog); @@ -7376,7 +7409,7 @@ BuildsOperationPrimeCache::Execute() .Details = Details, .TotalCount = BlobCount, .RemainingCount = BlobCount - CompletedDownloadCount.load(), - .Status = BuildOpLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, + .Status = OperationLogOutput::ProgressBar::State::CalculateStatus(IsAborted, IsPaused)}, false); }); @@ -7395,7 +7428,7 @@ BuildsOperationPrimeCache::Execute() ZEN_UNUSED(Remaining); if (!m_Options.IsQuiet) { - LOG_OUTPUT(m_LogOutput, "Waiting for {} blobs to finish upload to '{}'", Remaining, m_Storage.CacheName); + ZEN_OPERATION_LOG_INFO(m_LogOutput, "Waiting for {} blobs to finish upload to '{}'", Remaining, m_Storage.CacheName); } return !m_AbortFlag; }); @@ -7404,13 +7437,13 @@ BuildsOperationPrimeCache::Execute() if (!m_Options.IsQuiet) { uint64_t DownloadedBytes = m_DownloadStats.DownloadedChunkByteCount.load() + m_DownloadStats.DownloadedBlockByteCount.load(); - LOG_OUTPUT(m_LogOutput, - "Downloaded {} ({}bits/s) in {}. {} as multipart. Completed in {}", - NiceBytes(DownloadedBytes), - NiceNum(GetBytesPerSecond(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS(), DownloadedBytes * 8)), - NiceTimeSpanMs(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS() / 1000), - MultipartAttachmentCount.load(), - NiceTimeSpanMs(PrimeTimer.GetElapsedTimeMs())); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "Downloaded {} ({}bits/s) in {}. {} as multipart. Completed in {}", + NiceBytes(DownloadedBytes), + NiceNum(GetBytesPerSecond(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS(), DownloadedBytes * 8)), + NiceTimeSpanMs(FilteredDownloadedBytesPerSecond.GetElapsedTimeUS() / 1000), + MultipartAttachmentCount.load(), + NiceTimeSpanMs(PrimeTimer.GetElapsedTimeMs())); } } diff --git a/src/zenremotestore/builds/buildstorageutil.cpp b/src/zenremotestore/builds/buildstorageutil.cpp index 998529714..3680d1d83 100644 --- a/src/zenremotestore/builds/buildstorageutil.cpp +++ b/src/zenremotestore/builds/buildstorageutil.cpp @@ -2,9 +2,14 @@ #include <zenremotestore/builds/buildstorageutil.h> +#include <zencore/fmtutils.h> +#include <zencore/timer.h> +#include <zenremotestore/builds/buildstorage.h> #include <zenremotestore/builds/buildstoragecache.h> #include <zenremotestore/builds/jupiterbuildstorage.h> +#include <zenremotestore/chunking/chunkblock.h> #include <zenremotestore/jupiter/jupiterhost.h> +#include <zenremotestore/operationlogoutput.h> #include <zenutil/zenserverprocess.h> namespace zen { @@ -154,4 +159,209 @@ ResolveBuildStorage(const HttpClientSettings& ClientSettings, .CacheName = CacheName, .CacheAssumeHttp2 = CacheAssumeHttp2}; } + +std::vector<ChunkBlockDescription> +GetBlockDescriptions(OperationLogOutput& Output, + BuildStorageBase& Storage, + BuildStorageCache* OptionalCacheStorage, + const Oid& BuildId, + const Oid& BuildPartId, + std::span<const IoHash> BlockRawHashes, + bool AttemptFallback, + bool IsQuiet, + bool IsVerbose) +{ + using namespace std::literals; + + if (!IsQuiet) + { + ZEN_CONSOLE("Fetching metadata for {} blocks", BlockRawHashes.size()); + } + + Stopwatch GetBlockMetadataTimer; + + std::vector<ChunkBlockDescription> UnorderedList; + tsl::robin_map<IoHash, size_t, IoHash::Hasher> BlockDescriptionLookup; + if (OptionalCacheStorage && !BlockRawHashes.empty()) + { + std::vector<CbObject> CacheBlockMetadatas = OptionalCacheStorage->GetBlobMetadatas(BuildId, BlockRawHashes); + UnorderedList.reserve(CacheBlockMetadatas.size()); + for (size_t CacheBlockMetadataIndex = 0; CacheBlockMetadataIndex < CacheBlockMetadatas.size(); CacheBlockMetadataIndex++) + { + const CbObject& CacheBlockMetadata = CacheBlockMetadatas[CacheBlockMetadataIndex]; + ChunkBlockDescription Description = ParseChunkBlockDescription(CacheBlockMetadata); + if (Description.BlockHash == IoHash::Zero) + { + ZEN_OPERATION_LOG_WARN(Output, "Unexpected/invalid block metadata received from remote cache, skipping block"); + } + else + { + UnorderedList.emplace_back(std::move(Description)); + } + } + for (size_t DescriptionIndex = 0; DescriptionIndex < UnorderedList.size(); DescriptionIndex++) + { + const ChunkBlockDescription& Description = UnorderedList[DescriptionIndex]; + BlockDescriptionLookup.insert_or_assign(Description.BlockHash, DescriptionIndex); + } + } + + if (UnorderedList.size() < BlockRawHashes.size()) + { + std::vector<IoHash> RemainingBlockHashes; + RemainingBlockHashes.reserve(BlockRawHashes.size() - UnorderedList.size()); + for (const IoHash& BlockRawHash : BlockRawHashes) + { + if (!BlockDescriptionLookup.contains(BlockRawHash)) + { + RemainingBlockHashes.push_back(BlockRawHash); + } + } + CbObject BlockMetadatas = Storage.GetBlockMetadatas(BuildId, RemainingBlockHashes); + std::vector<ChunkBlockDescription> RemainingList; + { + CbArrayView BlocksArray = BlockMetadatas["blocks"sv].AsArrayView(); + std::vector<IoHash> FoundBlockHashes; + std::vector<CbObject> FoundBlockMetadatas; + for (CbFieldView Block : BlocksArray) + { + ChunkBlockDescription Description = ParseChunkBlockDescription(Block.AsObjectView()); + + if (Description.BlockHash == IoHash::Zero) + { + ZEN_OPERATION_LOG_WARN(Output, "Unexpected/invalid block metadata received from remote store, skipping block"); + } + else + { + if (OptionalCacheStorage) + { + UniqueBuffer MetaBuffer = UniqueBuffer::Alloc(Block.GetSize()); + Block.CopyTo(MetaBuffer.GetMutableView()); + CbObject BlockMetadata(MetaBuffer.MoveToShared()); + + FoundBlockHashes.push_back(Description.BlockHash); + FoundBlockMetadatas.push_back(BlockMetadata); + } + RemainingList.emplace_back(std::move(Description)); + } + } + if (OptionalCacheStorage && !FoundBlockHashes.empty()) + { + OptionalCacheStorage->PutBlobMetadatas(BuildId, FoundBlockHashes, FoundBlockMetadatas); + } + } + + for (size_t DescriptionIndex = 0; DescriptionIndex < RemainingList.size(); DescriptionIndex++) + { + const ChunkBlockDescription& Description = RemainingList[DescriptionIndex]; + BlockDescriptionLookup.insert_or_assign(Description.BlockHash, UnorderedList.size() + DescriptionIndex); + } + UnorderedList.insert(UnorderedList.end(), RemainingList.begin(), RemainingList.end()); + } + + std::vector<ChunkBlockDescription> Result; + Result.reserve(BlockDescriptionLookup.size()); + for (const IoHash& BlockHash : BlockRawHashes) + { + if (auto It = BlockDescriptionLookup.find(BlockHash); It != BlockDescriptionLookup.end()) + { + Result.push_back(std::move(UnorderedList[It->second])); + } + } + + if (!IsQuiet) + { + ZEN_OPERATION_LOG_INFO(Output, + "GetBlockMetadata for {} took {}. Found {} blocks", + BuildPartId, + NiceTimeSpanMs(GetBlockMetadataTimer.GetElapsedTimeMs()), + Result.size()); + } + + if (Result.size() != BlockRawHashes.size()) + { + std::string ErrorDescription = + fmt::format("All required blocks could not be found, {} blocks does not have metadata in this context.", + BlockRawHashes.size() - Result.size()); + if (IsVerbose) + { + for (const IoHash& BlockHash : BlockRawHashes) + { + if (auto It = + std::find_if(Result.begin(), + Result.end(), + [BlockHash](const ChunkBlockDescription& Description) { return Description.BlockHash == BlockHash; }); + It == Result.end()) + { + ErrorDescription += fmt::format("\n {}", BlockHash); + } + } + } + if (AttemptFallback) + { + ZEN_OPERATION_LOG_WARN(Output, "{} Attemping fallback options.", ErrorDescription); + std::vector<ChunkBlockDescription> AugmentedBlockDescriptions; + AugmentedBlockDescriptions.reserve(BlockRawHashes.size()); + std::vector<ChunkBlockDescription> FoundBlocks = ParseChunkBlockDescriptionList(Storage.FindBlocks(BuildId, (uint64_t)-1)); + + for (const IoHash& BlockHash : BlockRawHashes) + { + if (auto It = + std::find_if(Result.begin(), + Result.end(), + [BlockHash](const ChunkBlockDescription& Description) { return Description.BlockHash == BlockHash; }); + It != Result.end()) + { + AugmentedBlockDescriptions.emplace_back(std::move(*It)); + } + else if (auto ListBlocksIt = std::find_if( + FoundBlocks.begin(), + FoundBlocks.end(), + [BlockHash](const ChunkBlockDescription& Description) { return Description.BlockHash == BlockHash; }); + ListBlocksIt != FoundBlocks.end()) + { + ZEN_OPERATION_LOG_INFO(Output, "Found block {} via context find successfully", BlockHash); + AugmentedBlockDescriptions.emplace_back(std::move(*ListBlocksIt)); + } + else + { + IoBuffer BlockBuffer = Storage.GetBuildBlob(BuildId, BlockHash); + if (!BlockBuffer) + { + throw std::runtime_error(fmt::format("Block {} could not be found", BlockHash)); + } + IoHash BlockRawHash; + uint64_t BlockRawSize; + CompressedBuffer CompressedBlockBuffer = + CompressedBuffer::FromCompressed(SharedBuffer(std::move(BlockBuffer)), BlockRawHash, BlockRawSize); + if (!CompressedBlockBuffer) + { + throw std::runtime_error(fmt::format("Block {} is not a compressed buffer", BlockHash)); + } + + if (BlockRawHash != BlockHash) + { + throw std::runtime_error(fmt::format("Block {} header has a mismatching raw hash {}", BlockHash, BlockRawHash)); + } + + CompositeBuffer DecompressedBlockBuffer = CompressedBlockBuffer.DecompressToComposite(); + if (!DecompressedBlockBuffer) + { + throw std::runtime_error(fmt::format("Block {} failed to decompress", BlockHash)); + } + + ChunkBlockDescription MissingChunkDescription = GetChunkBlockDescription(DecompressedBlockBuffer.Flatten(), BlockHash); + AugmentedBlockDescriptions.emplace_back(std::move(MissingChunkDescription)); + } + } + Result.swap(AugmentedBlockDescriptions); + } + else + { + throw std::runtime_error(ErrorDescription); + } + } + return Result; +} + } // namespace zen diff --git a/src/zenremotestore/include/zenremotestore/builds/buildstorageoperations.h b/src/zenremotestore/include/zenremotestore/builds/buildstorageoperations.h index a409d08ec..6eef794fd 100644 --- a/src/zenremotestore/include/zenremotestore/builds/buildstorageoperations.h +++ b/src/zenremotestore/include/zenremotestore/builds/buildstorageoperations.h @@ -21,13 +21,14 @@ namespace zen { class CloneQueryInterface; +class OperationLogOutput; class BuildStorageBase; -class BuildStorageCache; class HttpClient; class ParallelWork; class WorkerThreadPool; class FilteredRate; class ReadFileCache; +struct StorageInstance; class BufferedWriteFileCache; struct ChunkBlockDescription; @@ -106,16 +107,6 @@ struct RebuildFolderStateStatistics uint64_t FinalizeTreeElapsedWallTimeUs = 0; }; -struct StorageInstance -{ - std::unique_ptr<HttpClient> BuildStorageHttp; - std::unique_ptr<BuildStorageBase> BuildStorage; - std::string StorageName; - std::unique_ptr<HttpClient> CacheHttp; - std::unique_ptr<BuildStorageCache> BuildCacheStorage; - std::string CacheName; -}; - enum EPartialBlockRequestMode { Off, @@ -130,56 +121,6 @@ EPartialBlockRequestMode PartialBlockRequestModeFromString(const std::string_vie std::filesystem::path ZenStateFilePath(const std::filesystem::path& ZenFolderPath); std::filesystem::path ZenTempFolderPath(const std::filesystem::path& ZenFolderPath); -class BuildOpLogOutput -{ -public: - virtual void EmitLogMessage(int LogLevel, std::string_view Format, fmt::format_args Args) = 0; - - virtual void SetLogOperationName(std::string_view Name) = 0; - virtual void SetLogOperationProgress(uint32_t StepIndex, uint32_t StepCount) = 0; - virtual uint32_t GetProgressUpdateDelayMS() = 0; - - class ProgressBar - { - public: - struct State - { - bool operator==(const State&) const = default; - std::string Task; - std::string Details; - uint64_t TotalCount = 0; - uint64_t RemainingCount = 0; - enum class EStatus - { - Running, - Aborted, - Paused - }; - EStatus Status = EStatus::Running; - - static EStatus CalculateStatus(bool IsAborted, bool IsPaused) - { - if (IsAborted) - { - return EStatus::Aborted; - } - if (IsPaused) - { - return EStatus::Paused; - } - return EStatus::Running; - } - }; - - virtual ~ProgressBar() {} - - virtual void UpdateState(const State& NewState, bool DoLinebreak) = 0; - virtual void Finish() = 0; - }; - - virtual ProgressBar* CreateProgressBar(std::string_view InSubTask) = 0; -}; - class BuildsOperationUpdateFolder { public: @@ -203,7 +144,7 @@ public: std::vector<std::string> ExcludeExtensions; }; - BuildsOperationUpdateFolder(BuildOpLogOutput& LogOutput, + BuildsOperationUpdateFolder(OperationLogOutput& OperationLogOutput, StorageInstance& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -437,7 +378,7 @@ private: void FinalizeChunkSequences(std::span<const uint32_t> RemoteSequenceIndexes); void VerifySequence(uint32_t RemoteSequenceIndex); - BuildOpLogOutput& m_LogOutput; + OperationLogOutput& m_LogOutput; StorageInstance& m_Storage; std::atomic<bool>& m_AbortFlag; std::atomic<bool>& m_PauseFlag; @@ -572,7 +513,7 @@ public: std::vector<std::string> NonCompressableExtensions; }; - BuildsOperationUploadFolder(BuildOpLogOutput& LogOutput, + BuildsOperationUploadFolder(OperationLogOutput& OperationLogOutput, StorageInstance& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -685,15 +626,15 @@ private: uint32_t ChunkIndex, LooseChunksStatistics& TempLooseChunksStats); - BuildOpLogOutput& m_LogOutput; - StorageInstance& m_Storage; - std::atomic<bool>& m_AbortFlag; - std::atomic<bool>& m_PauseFlag; - WorkerThreadPool& m_IOWorkerPool; - WorkerThreadPool& m_NetworkPool; - const Oid m_BuildId; - const Oid m_BuildPartId; - const std::string m_BuildPartName; + OperationLogOutput& m_LogOutput; + StorageInstance& m_Storage; + std::atomic<bool>& m_AbortFlag; + std::atomic<bool>& m_PauseFlag; + WorkerThreadPool& m_IOWorkerPool; + WorkerThreadPool& m_NetworkPool; + const Oid m_BuildId; + const Oid m_BuildPartId; + const std::string m_BuildPartName; const std::filesystem::path m_Path; const std::filesystem::path m_ManifestPath; @@ -723,7 +664,7 @@ public: bool IsQuiet = false; bool IsVerbose = false; }; - BuildsOperationValidateBuildPart(BuildOpLogOutput& LogOutput, + BuildsOperationValidateBuildPart(OperationLogOutput& OperationLogOutput, BuildStorageBase& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -745,16 +686,16 @@ private: uint64_t& OutCompressedSize, uint64_t& OutDecompressedSize); - BuildOpLogOutput& m_LogOutput; - BuildStorageBase& m_Storage; - std::atomic<bool>& m_AbortFlag; - std::atomic<bool>& m_PauseFlag; - WorkerThreadPool& m_IOWorkerPool; - WorkerThreadPool& m_NetworkPool; - const Oid m_BuildId; - Oid m_BuildPartId; - const std::string m_BuildPartName; - const Options m_Options; + OperationLogOutput& m_LogOutput; + BuildStorageBase& m_Storage; + std::atomic<bool>& m_AbortFlag; + std::atomic<bool>& m_PauseFlag; + WorkerThreadPool& m_IOWorkerPool; + WorkerThreadPool& m_NetworkPool; + const Oid m_BuildId; + Oid m_BuildPartId; + const std::string m_BuildPartName; + const Options m_Options; }; class BuildsOperationPrimeCache @@ -770,7 +711,7 @@ public: bool ForceUpload = false; }; - BuildsOperationPrimeCache(BuildOpLogOutput& LogOutput, + BuildsOperationPrimeCache(OperationLogOutput& OperationLogOutput, StorageInstance& Storage, std::atomic<bool>& AbortFlag, std::atomic<bool>& PauseFlag, @@ -785,7 +726,7 @@ public: DownloadStatistics m_DownloadStats; private: - BuildOpLogOutput& m_LogOutput; + OperationLogOutput& m_LogOutput; StorageInstance& m_Storage; std::atomic<bool>& m_AbortFlag; std::atomic<bool>& m_PauseFlag; diff --git a/src/zenremotestore/include/zenremotestore/builds/buildstorageutil.h b/src/zenremotestore/include/zenremotestore/builds/buildstorageutil.h index 258266a6a..3816822be 100644 --- a/src/zenremotestore/include/zenremotestore/builds/buildstorageutil.h +++ b/src/zenremotestore/include/zenremotestore/builds/buildstorageutil.h @@ -6,12 +6,12 @@ #include <zenhttp/httpclient.h> #include <zenremotestore/builds/buildstorage.h> -namespace cxxopts { -class Options; -} - namespace zen { +class OperationLogOutput; +class BuildStorageBase; +class BuildStorageCache; + struct BuildStorageResolveResult { std::string HostUrl; @@ -37,4 +37,24 @@ BuildStorageResolveResult ResolveBuildStorage(const HttpClientSettings& ClientSe std::string_view ZenCacheHost, ZenCacheResolveMode ZenResolveMode); +std::vector<ChunkBlockDescription> GetBlockDescriptions(OperationLogOutput& Output, + BuildStorageBase& Storage, + BuildStorageCache* OptionalCacheStorage, + const Oid& BuildId, + const Oid& BuildPartId, + std::span<const IoHash> BlockRawHashes, + bool AttemptFallback, + bool IsQuiet, + bool IsVerbose); + +struct StorageInstance +{ + std::unique_ptr<HttpClient> BuildStorageHttp; + std::unique_ptr<BuildStorageBase> BuildStorage; + std::string StorageName; + std::unique_ptr<HttpClient> CacheHttp; + std::unique_ptr<BuildStorageCache> BuildCacheStorage; + std::string CacheName; +}; + } // namespace zen diff --git a/src/zenremotestore/include/zenremotestore/operationlogoutput.h b/src/zenremotestore/include/zenremotestore/operationlogoutput.h new file mode 100644 index 000000000..b84d77703 --- /dev/null +++ b/src/zenremotestore/include/zenremotestore/operationlogoutput.h @@ -0,0 +1,87 @@ +// Copyright Epic Games, Inc. All Rights Reserved. + +#pragma once + +#include <zencore/fmtutils.h> + +namespace zen { + +class OperationLogOutput +{ +public: + virtual void EmitLogMessage(int LogLevel, std::string_view Format, fmt::format_args Args) = 0; + + virtual void SetLogOperationName(std::string_view Name) = 0; + virtual void SetLogOperationProgress(uint32_t StepIndex, uint32_t StepCount) = 0; + virtual uint32_t GetProgressUpdateDelayMS() = 0; + + class ProgressBar + { + public: + struct State + { + bool operator==(const State&) const = default; + std::string Task; + std::string Details; + uint64_t TotalCount = 0; + uint64_t RemainingCount = 0; + enum class EStatus + { + Running, + Aborted, + Paused + }; + EStatus Status = EStatus::Running; + + static EStatus CalculateStatus(bool IsAborted, bool IsPaused) + { + if (IsAborted) + { + return EStatus::Aborted; + } + if (IsPaused) + { + return EStatus::Paused; + } + return EStatus::Running; + } + }; + + virtual ~ProgressBar() {} + + virtual void UpdateState(const State& NewState, bool DoLinebreak) = 0; + virtual void Finish() = 0; + }; + + virtual ProgressBar* CreateProgressBar(std::string_view InSubTask) = 0; +}; + +#define ZEN_OPERATION_LOG(OutputTarget, InLevel, fmtstr, ...) \ + do \ + { \ + using namespace std::literals; \ + ZEN_CHECK_FORMAT_STRING(fmtstr##sv, ##__VA_ARGS__); \ + OutputTarget.EmitLogMessage(InLevel, fmtstr, zen::logging::LogCaptureArguments(__VA_ARGS__)); \ + } while (false) + +#define ZEN_OPERATION_LOG_INFO(OutputTarget, fmtstr, ...) \ + ZEN_OPERATION_LOG((OutputTarget), zen::logging::level::Info, fmtstr, ##__VA_ARGS__) +#define ZEN_OPERATION_LOG_DEBUG(OutputTarget, fmtstr, ...) \ + ZEN_OPERATION_LOG((OutputTarget), zen::logging::level::Debug, fmtstr, ##__VA_ARGS__) +#define ZEN_OPERATION_LOG_WARN(OutputTarget, fmtstr, ...) \ + ZEN_OPERATION_LOG((OutputTarget), zen::logging::level::Warn, fmtstr, ##__VA_ARGS__) + +class ConsoleLogOutput : public OperationLogOutput +{ +public: + ConsoleLogOutput(); + virtual void EmitLogMessage(int LogLevel, std::string_view Format, fmt::format_args Args) override; + + virtual void SetLogOperationName(std::string_view Name) override; + virtual void SetLogOperationProgress(uint32_t StepIndex, uint32_t StepCount) override; + virtual uint32_t GetProgressUpdateDelayMS() override; + + virtual ProgressBar* CreateProgressBar(std::string_view InSubTask) override; +}; + +} // namespace zen diff --git a/src/zenremotestore/operationlogoutput.cpp b/src/zenremotestore/operationlogoutput.cpp new file mode 100644 index 000000000..967b8e34e --- /dev/null +++ b/src/zenremotestore/operationlogoutput.cpp @@ -0,0 +1,67 @@ +// Copyright Epic Games, Inc. All Rights Reserved. + +#include <zenremotestore/operationlogoutput.h> + +#include <zencore/logging.h> + +namespace zen { + +using namespace std::literals; + +ConsoleLogOutput::ConsoleLogOutput() +{ +} + +void +ConsoleLogOutput::EmitLogMessage(int LogLevel, std::string_view Format, fmt::format_args Args) +{ + logging::EmitConsoleLogMessage(LogLevel, Format, Args); +} + +void +ConsoleLogOutput::SetLogOperationName(std::string_view Name) +{ + ZEN_OPERATION_LOG_INFO(*this, "{}", Name); +} +void +ConsoleLogOutput::SetLogOperationProgress(uint32_t StepIndex, uint32_t StepCount) +{ + ZEN_OPERATION_LOG_INFO(*this, "{}/{}", StepIndex, StepCount); +} +uint32_t +ConsoleLogOutput::GetProgressUpdateDelayMS() +{ + return 2000; +} + +class ConsoleLogOutputProgress : public OperationLogOutput::ProgressBar +{ +public: + ConsoleLogOutputProgress(OperationLogOutput& OperationLogOutput) : m_LogOutput(OperationLogOutput) {} + virtual void UpdateState(const State& NewState, bool DoLinebreak) + { + ZEN_UNUSED(DoLinebreak); + ZEN_OPERATION_LOG_INFO(m_LogOutput, + "{} {}/{} {}", + NewState.Task, + NewState.TotalCount - NewState.RemainingCount, + NewState.TotalCount, + NewState.Details); + m_CurrentState = NewState; + } + virtual void Finish() + { + ZEN_OPERATION_LOG_INFO(m_LogOutput, "{} {}/{}", m_CurrentState.Task, m_CurrentState.TotalCount, m_CurrentState.TotalCount); + } + State m_CurrentState; + OperationLogOutput& m_LogOutput; +}; + +OperationLogOutput::ProgressBar* +ConsoleLogOutput::CreateProgressBar(std::string_view InSubTask) +{ + ZEN_UNUSED(InSubTask); + return new ConsoleLogOutputProgress(*this); +} + +} // namespace zen |