From 16fd9ea89c7560216b654843400ab3d852b04e16 Mon Sep 17 00:00:00 2001 From: Dan Engelbrecht Date: Wed, 13 Dec 2023 09:25:05 -0500 Subject: improve trace (#606) * Adding some more trace scopes for better visiblity * Removed spammy trace scope when replaying oplogs * Remove "::Disk" from trace scopes - redundant now that we have merge disk and memory layers --- src/zenserver/cache/cachedisklayer.cpp | 87 +++++++++++++++++++++------------- 1 file changed, 53 insertions(+), 34 deletions(-) (limited to 'src/zenserver/cache/cachedisklayer.cpp') diff --git a/src/zenserver/cache/cachedisklayer.cpp b/src/zenserver/cache/cachedisklayer.cpp index 0987cd0f1..f1aab6093 100644 --- a/src/zenserver/cache/cachedisklayer.cpp +++ b/src/zenserver/cache/cachedisklayer.cpp @@ -504,6 +504,8 @@ BucketManifestSerializer::ReadSidecarFile(RwLock::ExclusiveLockScope& B std::vector& AccessTimes, std::vector& Payloads) { + ZEN_TRACE_CPU("Z$::ReadSidecarFile"); + ZEN_ASSERT(AccessTimes.size() == Payloads.size()); std::error_code Ec; @@ -590,6 +592,8 @@ BucketManifestSerializer::WriteSidecarFile(RwLock::SharedLockScope&, const std::vector& Payloads, const std::vector& MetaDatas) { + ZEN_TRACE_CPU("Z$::WriteSidecarFile"); + BucketMetaHeader Header; Header.EntryCount = m_ManifestEntryCount; Header.LogPosition = SnapshotLogPosition; @@ -698,7 +702,7 @@ ZenCacheDiskLayer::CacheBucket::OpenOrCreate(std::filesystem::path BucketDir, bo { using namespace std::literals; - ZEN_TRACE_CPU("Z$::Disk::Bucket::OpenOrCreate"); + ZEN_TRACE_CPU("Z$::Bucket::OpenOrCreate"); ZEN_ASSERT(m_IsFlushing.load()); // We want to take the lock here since we register as a GC referencer a construction @@ -765,7 +769,7 @@ ZenCacheDiskLayer::CacheBucket::OpenOrCreate(std::filesystem::path BucketDir, bo void ZenCacheDiskLayer::CacheBucket::WriteIndexSnapshotLocked(const std::function& ClaimDiskReserveFunc) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::WriteIndexSnapshot"); + ZEN_TRACE_CPU("Z$::Bucket::WriteIndexSnapshot"); const uint64_t LogCount = m_SlogFile.GetLogCount(); if (m_LogFlushPosition == LogCount) @@ -875,7 +879,7 @@ ZenCacheDiskLayer::CacheBucket::WriteIndexSnapshotLocked(const std::function DataFilePath; BuildPath(DataFilePath, HashKey); @@ -1172,6 +1176,8 @@ ZenCacheDiskLayer::CacheBucket::GetStandaloneCacheValue(ZenContentType ContentTy bool ZenCacheDiskLayer::CacheBucket::Get(const IoHash& HashKey, ZenCacheValue& OutValue) { + ZEN_TRACE_CPU("Z$::Bucket::Get"); + metrics::RequestStats::Scope StatsScope(m_GetOps, 0); RwLock::SharedLockScope IndexLock(m_IndexLock); @@ -1228,7 +1234,7 @@ ZenCacheDiskLayer::CacheBucket::Get(const IoHash& HashKey, ZenCacheValue& OutVal size_t ValueSize = OutValue.Value.GetSize(); if (OutValue.Value && ValueSize <= m_Configuration.MemCacheSizeThreshold) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::Get::MemCache"); + ZEN_TRACE_CPU("Z$::Bucket::Get::MemCache"); OutValue.Value = IoBufferBuilder::ReadFromFileMaybe(OutValue.Value); RwLock::ExclusiveLockScope UpdateIndexLock(m_IndexLock); if (auto UpdateIt = m_Index.find(HashKey); UpdateIt != m_Index.end()) @@ -1247,7 +1253,7 @@ ZenCacheDiskLayer::CacheBucket::Get(const IoHash& HashKey, ZenCacheValue& OutVal if (FillRawHashAndRawSize) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::Get::MetaData"); + ZEN_TRACE_CPU("Z$::Bucket::Get::MetaData"); if (Location.IsFlagSet(DiskLocation::kCompressed)) { if (!CompressedBuffer::ValidateCompressedHeader(OutValue.Value, OutValue.RawHash, OutValue.RawSize)) @@ -1290,6 +1296,8 @@ ZenCacheDiskLayer::CacheBucket::Get(const IoHash& HashKey, ZenCacheValue& OutVal void ZenCacheDiskLayer::CacheBucket::Put(const IoHash& HashKey, const ZenCacheValue& Value, std::span References) { + ZEN_TRACE_CPU("Z$::Bucket::Put"); + metrics::RequestStats::Scope $(m_PutOps, Value.Value.Size()); if (Value.Value.Size() >= m_Configuration.LargeObjectThreshold) @@ -1307,7 +1315,7 @@ ZenCacheDiskLayer::CacheBucket::Put(const IoHash& HashKey, const ZenCacheValue& uint64_t ZenCacheDiskLayer::CacheBucket::MemCacheTrim(GcClock::TimePoint ExpireTime) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::MemCacheTrim"); + ZEN_TRACE_CPU("Z$::Bucket::MemCacheTrim"); uint64_t Trimmed = 0; GcClock::Tick ExpireTicks = ExpireTime.time_since_epoch().count(); @@ -1355,7 +1363,7 @@ ZenCacheDiskLayer::CacheBucket::MemCacheTrim(GcClock::TimePoint ExpireTime) void ZenCacheDiskLayer::CacheBucket::GetUsageByAccess(GcClock::TimePoint Now, GcClock::Duration MaxAge, std::vector& InOutUsageSlots) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::GetUsageByAccess"); + ZEN_TRACE_CPU("Z$::Bucket::GetUsageByAccess"); size_t SlotCount = InOutUsageSlots.capacity(); RwLock::SharedLockScope _(m_IndexLock); @@ -1388,7 +1396,7 @@ ZenCacheDiskLayer::CacheBucket::GetUsageByAccess(GcClock::TimePoint Now, GcClock bool ZenCacheDiskLayer::CacheBucket::Drop() { - ZEN_TRACE_CPU("Z$::Disk::Bucket::Drop"); + ZEN_TRACE_CPU("Z$::Bucket::Drop"); RwLock::ExclusiveLockScope _(m_IndexLock); @@ -1424,7 +1432,7 @@ ZenCacheDiskLayer::CacheBucket::Drop() void ZenCacheDiskLayer::CacheBucket::Flush() { - ZEN_TRACE_CPU("Z$::Disk::Bucket::Flush"); + ZEN_TRACE_CPU("Z$::Bucket::Flush"); bool Expected = false; if (m_IsFlushing || !m_IsFlushing.compare_exchange_strong(Expected, true)) { @@ -1450,6 +1458,7 @@ ZenCacheDiskLayer::CacheBucket::Flush() void ZenCacheDiskLayer::CacheBucket::SaveSnapshot(const std::function& ClaimDiskReserveFunc) { + ZEN_TRACE_CPU("Z$::Bucket::SaveSnapshot"); try { bool UseLegacyScheme = false; @@ -1624,7 +1633,7 @@ ValidateCacheBucketEntryValue(ZenContentType ContentType, IoBuffer Buffer) void ZenCacheDiskLayer::CacheBucket::ScrubStorage(ScrubContext& Ctx) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::Scrub"); + ZEN_TRACE_CPU("Z$::Bucket::Scrub"); ZEN_INFO("scrubbing '{}'", m_BucketDir); @@ -1864,7 +1873,7 @@ ZenCacheDiskLayer::CacheBucket::ScrubStorage(ScrubContext& Ctx) void ZenCacheDiskLayer::CacheBucket::GatherReferences(GcContext& GcCtx) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::GatherReferences"); + ZEN_TRACE_CPU("Z$::Bucket::GatherReferences"); #define CALCULATE_BLOCKING_TIME 0 @@ -2082,7 +2091,7 @@ ZenCacheDiskLayer::CacheBucket::GatherReferences(GcContext& GcCtx) void ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CollectGarbage"); + ZEN_TRACE_CPU("Z$::Bucket::CollectGarbage"); ZEN_DEBUG("collecting garbage from '{}'", m_BucketDir); @@ -2182,7 +2191,7 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) auto FlushingGuard = MakeGuard([&] { m_IsFlushing.store(false); }); { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CollectGarbage::State"); + ZEN_TRACE_CPU("Z$::Bucket::CollectGarbage::State"); RwLock::SharedLockScope IndexLock(m_IndexLock); Stopwatch Timer; @@ -2230,7 +2239,7 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx) if (GcCtx.IsDeletionMode()) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CollectGarbage::Delete"); + ZEN_TRACE_CPU("Z$::Bucket::CollectGarbage::Delete"); ExtendablePathBuilder<256> Path; @@ -2470,7 +2479,7 @@ ZenCacheDiskLayer::CacheBucket::EnumerateBucketContents( void ZenCacheDiskLayer::CollectGarbage(GcContext& GcCtx) { - ZEN_TRACE_CPU("Z$::Disk::CollectGarbage"); + ZEN_TRACE_CPU("Z$::CollectGarbage"); std::vector Buckets; { @@ -2494,7 +2503,7 @@ ZenCacheDiskLayer::CollectGarbage(GcContext& GcCtx) void ZenCacheDiskLayer::CacheBucket::PutStandaloneCacheValue(const IoHash& HashKey, const ZenCacheValue& Value, std::span References) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::PutStandaloneCacheValue"); + ZEN_TRACE_CPU("Z$::Bucket::PutStandaloneCacheValue"); uint64_t NewFileSize = Value.Value.Size(); @@ -2744,7 +2753,7 @@ ZenCacheDiskLayer::CacheBucket::GetMetaData(RwLock::SharedLockScope&, const Buck void ZenCacheDiskLayer::CacheBucket::PutInlineCacheValue(const IoHash& HashKey, const ZenCacheValue& Value, std::span References) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::PutInlineCacheValue"); + ZEN_TRACE_CPU("Z$::Bucket::PutInlineCacheValue"); uint8_t EntryFlags = 0; @@ -2821,7 +2830,7 @@ public: virtual void CompactStore(GcCtx& Ctx, GcCompactStoreStats& Stats, const std::function& ClaimDiskReserveCallback) override { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CompactStore"); + ZEN_TRACE_CPU("Z$::Bucket::CompactStore"); Stopwatch Timer; const auto _ = MakeGuard([&] { @@ -3044,7 +3053,7 @@ private: GcStoreCompactor* ZenCacheDiskLayer::CacheBucket::RemoveExpiredData(GcCtx& Ctx, GcStats& Stats) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::RemoveExpiredData"); + ZEN_TRACE_CPU("Z$::Bucket::RemoveExpiredData"); size_t TotalEntries = 0; @@ -3185,7 +3194,7 @@ public: virtual void PreCache(GcCtx& Ctx) override { - ZEN_TRACE_CPU("Z$::Disk::Bucket::PreCache"); + ZEN_TRACE_CPU("Z$::Bucket::PreCache"); Stopwatch Timer; const auto _ = MakeGuard([&] { @@ -3406,7 +3415,7 @@ public: virtual void LockState(GcCtx& Ctx) override { - ZEN_TRACE_CPU("Z$::Disk::Bucket::LockState"); + ZEN_TRACE_CPU("Z$::Bucket::LockState"); Stopwatch Timer; const auto _ = MakeGuard([&] { @@ -3479,7 +3488,7 @@ public: virtual void RemoveUsedReferencesFromSet(GcCtx& Ctx, HashSet& IoCids) override { - ZEN_TRACE_CPU("Z$::Disk::Bucket::RemoveUsedReferencesFromSet"); + ZEN_TRACE_CPU("Z$::Bucket::RemoveUsedReferencesFromSet"); ZEN_ASSERT(m_IndexLock); size_t InitialCount = IoCids.size(); @@ -3526,7 +3535,7 @@ public: std::vector ZenCacheDiskLayer::CacheBucket::CreateReferenceCheckers(GcCtx& Ctx) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CreateReferenceCheckers"); + ZEN_TRACE_CPU("Z$::Bucket::CreateReferenceCheckers"); Stopwatch Timer; const auto _ = MakeGuard([&] { @@ -3551,7 +3560,7 @@ ZenCacheDiskLayer::CacheBucket::CreateReferenceCheckers(GcCtx& Ctx) void ZenCacheDiskLayer::CacheBucket::CompactReferences(RwLock::ExclusiveLockScope&) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CompactReferences"); + ZEN_TRACE_CPU("Z$::Bucket::CompactReferences"); std::vector FirstReferenceIndex; std::vector NewReferenceHashes; @@ -3734,7 +3743,7 @@ ZenCacheDiskLayer::CacheBucket::CompactState(RwLock::ExclusiveLockScope&, IndexMap& Index, RwLock::ExclusiveLockScope& IndexLock) { - ZEN_TRACE_CPU("Z$::Disk::Bucket::CompactState"); + ZEN_TRACE_CPU("Z$::Bucket::CompactState"); size_t EntryCount = m_Index.size(); Payloads.reserve(EntryCount); @@ -3833,7 +3842,7 @@ ZenCacheDiskLayer::~ZenCacheDiskLayer() ZenCacheDiskLayer::CacheBucket* ZenCacheDiskLayer::GetOrCreateBucket(std::string_view InBucket) { - ZEN_TRACE_CPU("Z$::Disk::GetOrCreateBucket"); + ZEN_TRACE_CPU("Z$::GetOrCreateBucket"); const auto BucketName = std::string(InBucket); { @@ -3880,7 +3889,7 @@ ZenCacheDiskLayer::GetOrCreateBucket(std::string_view InBucket) bool ZenCacheDiskLayer::Get(std::string_view InBucket, const IoHash& HashKey, ZenCacheValue& OutValue) { - ZEN_TRACE_CPU("Z$::Disk::Get"); + ZEN_TRACE_CPU("Z$::Get"); if (CacheBucket* Bucket = GetOrCreateBucket(InBucket); Bucket != nullptr) { @@ -3896,7 +3905,7 @@ ZenCacheDiskLayer::Get(std::string_view InBucket, const IoHash& HashKey, ZenCach void ZenCacheDiskLayer::Put(std::string_view InBucket, const IoHash& HashKey, const ZenCacheValue& Value, std::span References) { - ZEN_TRACE_CPU("Z$::Disk::Put"); + ZEN_TRACE_CPU("Z$::Put"); if (CacheBucket* Bucket = GetOrCreateBucket(InBucket); Bucket != nullptr) { @@ -3908,6 +3917,8 @@ ZenCacheDiskLayer::Put(std::string_view InBucket, const IoHash& HashKey, const Z void ZenCacheDiskLayer::DiscoverBuckets() { + ZEN_TRACE_CPU("Z$::DiscoverBuckets"); + DirectoryContent DirContent; GetDirectoryContent(m_RootDir, DirectoryContent::IncludeDirsFlag, DirContent); @@ -4008,6 +4019,8 @@ ZenCacheDiskLayer::DiscoverBuckets() bool ZenCacheDiskLayer::DropBucket(std::string_view InBucket) { + ZEN_TRACE_CPU("Z$::DropBucket"); + RwLock::ExclusiveLockScope _(m_Lock); auto It = m_Buckets.find(std::string(InBucket)); @@ -4030,6 +4043,8 @@ ZenCacheDiskLayer::DropBucket(std::string_view InBucket) bool ZenCacheDiskLayer::Drop() { + ZEN_TRACE_CPU("Z$::Drop"); + RwLock::ExclusiveLockScope _(m_Lock); std::vector> Buckets; @@ -4051,6 +4066,8 @@ ZenCacheDiskLayer::Drop() void ZenCacheDiskLayer::Flush() { + ZEN_TRACE_CPU("Z$::Flush"); + std::vector Buckets; Stopwatch Timer; const auto _ = MakeGuard([&] { @@ -4092,6 +4109,8 @@ ZenCacheDiskLayer::Flush() void ZenCacheDiskLayer::ScrubStorage(ScrubContext& Ctx) { + ZEN_TRACE_CPU("Z$::ScrubStorage"); + RwLock::SharedLockScope _(m_Lock); { std::vector> Results; @@ -4118,7 +4137,7 @@ ZenCacheDiskLayer::ScrubStorage(ScrubContext& Ctx) void ZenCacheDiskLayer::GatherReferences(GcContext& GcCtx) { - ZEN_TRACE_CPU("Z$::Disk::GatherReferences"); + ZEN_TRACE_CPU("Z$::GatherReferences"); std::vector Buckets; { @@ -4235,7 +4254,7 @@ ZenCacheDiskLayer::GetValueDetails(const std::string_view BucketFilter, const st void ZenCacheDiskLayer::MemCacheTrim() { - ZEN_TRACE_CPU("Z$::Disk::MemCacheTrim"); + ZEN_TRACE_CPU("Z$::MemCacheTrim"); ZEN_ASSERT(m_Configuration.MemCacheTargetFootprintBytes != 0); ZEN_ASSERT(m_Configuration.MemCacheMaxAgeSeconds != 0); -- cgit v1.2.3