From a07d68c0aea6cddd966986ad45045087e1cebfea Mon Sep 17 00:00:00 2001 From: Dan Engelbrecht Date: Fri, 2 Dec 2022 16:37:22 +0100 Subject: reduce gc log spam (INFO -> DEBUG) (#199) --- zenserver/cache/structuredcachestore.cpp | 34 ++++++++++++++++---------------- zenserver/projectstore.cpp | 33 ++++++++++++++++--------------- zenstore/blockstore.cpp | 16 +++++++-------- zenstore/compactcas.cpp | 2 +- zenstore/filecas.cpp | 28 +++++++++++++------------- 5 files changed, 57 insertions(+), 56 deletions(-) diff --git a/zenserver/cache/structuredcachestore.cpp b/zenserver/cache/structuredcachestore.cpp index 9773c2ed2..91ae452a8 100644 --- a/zenserver/cache/structuredcachestore.cpp +++ b/zenserver/cache/structuredcachestore.cpp @@ -312,7 +312,7 @@ ZenCacheNamespace::GatherReferences(GcContext& GcCtx) { Stopwatch Timer; const auto Guard = - MakeGuard([&] { ZEN_INFO("cache gathered all references from '{}' in {}", m_RootDir, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); }); + MakeGuard([&] { ZEN_DEBUG("cache gathered all references from '{}' in {}", m_RootDir, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); }); access_tracking::AccessTimes AccessTimes; m_MemLayer.GatherAccessTimes(AccessTimes); @@ -1204,13 +1204,13 @@ ZenCacheDiskLayer::CacheBucket::GatherReferences(GcContext& GcCtx) Stopwatch TotalTimer; const auto _ = MakeGuard([&] { - ZEN_INFO("gathered references from '{}' in {} write lock: {} ({}), read lock: {} ({})", - m_BucketDir / m_BucketName, - NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()), - NiceLatencyNs(WriteBlockTimeUs), - NiceLatencyNs(WriteBlockLongestTimeUs), - NiceLatencyNs(ReadBlockTimeUs), - NiceLatencyNs(ReadBlockLongestTimeUs)); + ZEN_DEBUG("gathered references from '{}' in {} write lock: {} ({}), read lock: {} ({})", + m_BucketDir / m_BucketName, + NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()), + NiceLatencyNs(WriteBlockTimeUs), + NiceLatencyNs(WriteBlockLongestTimeUs), + NiceLatencyNs(ReadBlockTimeUs), + NiceLatencyNs(ReadBlockLongestTimeUs)); }); const GcClock::TimePoint ExpireTime = @@ -1295,7 +1295,7 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) { ZEN_TRACE_CPU("Z$::DiskLayer::CacheBucket::CollectGarbage"); - ZEN_INFO("collecting garbage from '{}'", m_BucketDir / m_BucketName); + ZEN_DEBUG("collecting garbage from '{}'", m_BucketDir / m_BucketName); Stopwatch TotalTimer; uint64_t WriteBlockTimeUs = 0; @@ -1344,7 +1344,7 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) }); if (DeleteCacheKeys.empty()) { - ZEN_INFO("garbage collect SKIPPED, for '{}', no expired cache keys found", m_BucketDir / m_BucketName); + ZEN_DEBUG("garbage collect SKIPPED, for '{}', no expired cache keys found", m_BucketDir / m_BucketName); return; } @@ -1361,7 +1361,7 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) }); if (m_Index.empty()) { - ZEN_INFO("garbage collect SKIPPED, for '{}', container is empty", m_BucketDir / m_BucketName); + ZEN_DEBUG("garbage collect SKIPPED, for '{}', container is empty", m_BucketDir / m_BucketName); return; } BlockStoreState = m_BlockStore.GetReclaimSnapshotState(); @@ -1506,12 +1506,12 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) { m_BlockStore.ReclaimSpace(BlockStoreState, ChunkLocations, KeepChunkIndexes, m_PayloadAlignment, true); uint64_t CurrentTotalSize = TotalSize(); - ZEN_INFO("garbage collect from '{}' DISABLED, found #{} {} chunks of total #{} {}", - m_BucketDir / m_BucketName, - DeleteCount, - 0, // NiceBytes(TotalSize - NewTotalSize), - CurrentTotalSize, - NiceBytes(CurrentTotalSize)); + ZEN_DEBUG("garbage collect from '{}' DISABLED, found #{} {} chunks of total #{} {}", + m_BucketDir / m_BucketName, + DeleteCount, + 0, // NiceBytes(TotalSize - NewTotalSize), + CurrentTotalSize, + NiceBytes(CurrentTotalSize)); return; } diff --git a/zenserver/projectstore.cpp b/zenserver/projectstore.cpp index c60d5b405..c3f10c9cd 100644 --- a/zenserver/projectstore.cpp +++ b/zenserver/projectstore.cpp @@ -919,8 +919,9 @@ ProjectStore::Project::GatherReferences(GcContext& GcCtx) ZEN_TRACE_CPU("ProjectStore::Project::GatherReferences"); Stopwatch Timer; - const auto Guard = MakeGuard( - [&] { ZEN_INFO("gathered references from project store project {} in {}", Identifier, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); }); + const auto Guard = MakeGuard([&] { + ZEN_DEBUG("gathered references from project store project {} in {}", Identifier, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); + }); // GatherReferences needs to check all existing oplogs std::vector OpLogs = ScanForOplogs(); @@ -1084,11 +1085,11 @@ ProjectStore::GatherReferences(GcContext& GcCtx) size_t ExpiredProjectCount = 0; Stopwatch Timer; const auto Guard = MakeGuard([&] { - ZEN_INFO("gathered references from '{}' in {}, found {} active projects and {} expired projects", - m_ProjectBasePath.string(), - NiceTimeSpanMs(Timer.GetElapsedTimeMs()), - ProjectCount, - ExpiredProjectCount); + ZEN_DEBUG("gathered references from '{}' in {}, found {} active projects and {} expired projects", + m_ProjectBasePath.string(), + NiceTimeSpanMs(Timer.GetElapsedTimeMs()), + ProjectCount, + ExpiredProjectCount); }); DiscoverProjects(); @@ -1125,11 +1126,11 @@ ProjectStore::CollectGarbage(GcContext& GcCtx) Stopwatch Timer; const auto Guard = MakeGuard([&] { - ZEN_INFO("garbage collect from '{}' DONE after {}, found {} active projects and {} expired projects", - m_ProjectBasePath.string(), - NiceTimeSpanMs(Timer.GetElapsedTimeMs()), - ProjectCount, - ExpiredProjectCount); + ZEN_DEBUG("garbage collect from '{}' DONE after {}, found {} active projects and {} expired projects", + m_ProjectBasePath.string(), + NiceTimeSpanMs(Timer.GetElapsedTimeMs()), + ProjectCount, + ExpiredProjectCount); }); std::vector> ExpiredProjects; @@ -1149,7 +1150,7 @@ ProjectStore::CollectGarbage(GcContext& GcCtx) if (ExpiredProjects.empty()) { - ZEN_INFO("garbage collect SKIPPED, for '{}', no expired projects found", m_ProjectBasePath.string()); + ZEN_DEBUG("garbage collect SKIPPED, for '{}', no expired projects found", m_ProjectBasePath.string()); return; } @@ -1167,20 +1168,20 @@ ProjectStore::CollectGarbage(GcContext& GcCtx) RwLock::ExclusiveLockScope _(m_ProjectsLock); if (!Project->IsExpired()) { - ZEN_INFO("ProjectStore::CollectGarbage skipped garbage collect of project '{}'. Project no longer expired.", ProjectId); + ZEN_DEBUG("ProjectStore::CollectGarbage skipped garbage collect of project '{}'. Project no longer expired.", ProjectId); continue; } bool Success = Project->PrepareForDelete(PathToRemove); if (!Success) { - ZEN_INFO("ProjectStore::CollectGarbage skipped garbage collect of project '{}'. Project folder is locked.", ProjectId); + ZEN_DEBUG("ProjectStore::CollectGarbage skipped garbage collect of project '{}'. Project folder is locked.", ProjectId); continue; } m_Projects.erase(Project->Identifier); ProjectId = Project->Identifier; } - ZEN_INFO("ProjectStore::CollectGarbage garbage collected project '{}'. Removing storage on disk", ProjectId); + ZEN_DEBUG("ProjectStore::CollectGarbage garbage collected project '{}'. Removing storage on disk", ProjectId); if (PathToRemove.empty()) { continue; diff --git a/zenstore/blockstore.cpp b/zenstore/blockstore.cpp index c8bf482fa..5d81d1120 100644 --- a/zenstore/blockstore.cpp +++ b/zenstore/blockstore.cpp @@ -168,7 +168,7 @@ BlockStore::Initialize(const std::filesystem::path& BlocksBasePath, { // Log removing unreferenced block // Clear out unused blocks - ZEN_INFO("removing unused block at '{}'", Path); + ZEN_DEBUG("removing unused block at '{}'", Path); std::error_code Ec; std::filesystem::remove(Path, Ec); if (Ec) @@ -334,7 +334,7 @@ BlockStore::ReclaimSpace(const ReclaimSnapshotState& Snapshot, Stopwatch TotalTimer; const auto _ = MakeGuard([&] { - ZEN_INFO( + ZEN_DEBUG( "reclaim space for '{}' DONE after {}, write lock: {} ({}), read lock: {} ({}), collected {} bytes, deleted #{} and moved " "#{} " "of #{} " @@ -424,12 +424,12 @@ BlockStore::ReclaimSpace(const ReclaimSnapshotState& Snapshot, if (DryRun) { - ZEN_INFO("garbage collect for '{}' DISABLED, found #{} {} chunks of total #{} {}", - m_BlocksBasePath, - DeleteCount, - NiceBytes(OldTotalSize - NewTotalSize), - TotalChunkCount, - OldTotalSize); + ZEN_DEBUG("garbage collect for '{}' DISABLED, found #{} {} chunks of total #{} {}", + m_BlocksBasePath, + DeleteCount, + NiceBytes(OldTotalSize - NewTotalSize), + TotalChunkCount, + OldTotalSize); return; } diff --git a/zenstore/compactcas.cpp b/zenstore/compactcas.cpp index d0c2f59ac..e52f5b7cb 100644 --- a/zenstore/compactcas.cpp +++ b/zenstore/compactcas.cpp @@ -386,7 +386,7 @@ CasContainerStrategy::CollectGarbage(GcContext& GcCtx) // do a blocking operation and update the m_LocationMap after each new block is // written and figuring out the path to the next new block. - ZEN_INFO("collecting garbage from '{}'", m_RootDirectory / m_ContainerBaseName); + ZEN_DEBUG("collecting garbage from '{}'", m_RootDirectory / m_ContainerBaseName); uint64_t WriteBlockTimeUs = 0; uint64_t WriteBlockLongestTimeUs = 0; diff --git a/zenstore/filecas.cpp b/zenstore/filecas.cpp index 1b53c405b..1d3542f62 100644 --- a/zenstore/filecas.cpp +++ b/zenstore/filecas.cpp @@ -847,7 +847,7 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx) { ZEN_ASSERT(m_IsInitialized); - ZEN_INFO("collecting garbage from {}", m_RootDirectory); + ZEN_DEBUG("collecting garbage from {}", m_RootDirectory); std::vector ChunksToDelete; std::atomic ChunksToDeleteBytes{0}; @@ -861,13 +861,13 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx) Stopwatch TotalTimer; const auto _ = MakeGuard([&] { - ZEN_INFO("garbage collect for '{}' DONE after {}, deleted {} out of {} files, removed {} out of {}", - m_RootDirectory, - NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()), - DeletedCount, - ChunkCount, - NiceBytes(OldTotalSize - m_TotalSize.load(std::memory_order::relaxed)), - NiceBytes(OldTotalSize)); + ZEN_DEBUG("garbage collect for '{}' DONE after {}, deleted {} out of {} files, removed {} out of {}", + m_RootDirectory, + NiceTimeSpanMs(TotalTimer.GetElapsedTimeMs()), + DeletedCount, + ChunkCount, + NiceBytes(OldTotalSize - m_TotalSize.load(std::memory_order::relaxed)), + NiceBytes(OldTotalSize)); }); IterateChunks([&](const IoHash& Hash, BasicFile& Payload) { @@ -900,15 +900,15 @@ FileCasStrategy::CollectGarbage(GcContext& GcCtx) if (ChunksToDelete.empty()) { - ZEN_INFO("gc for '{}' SKIPPED, nothing to delete", m_RootDirectory); + ZEN_DEBUG("gc for '{}' SKIPPED, nothing to delete", m_RootDirectory); return; } - ZEN_INFO("deleting file CAS garbage for '{}': {} out of {} chunks ({})", - m_RootDirectory, - ChunksToDelete.size(), - ChunkCount.load(), - NiceBytes(ChunksToDeleteBytes)); + ZEN_DEBUG("deleting file CAS garbage for '{}': {} out of {} chunks ({})", + m_RootDirectory, + ChunksToDelete.size(), + ChunkCount.load(), + NiceBytes(ChunksToDeleteBytes)); if (GcCtx.IsDeletionMode() == false) { -- cgit v1.2.3