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

1 files changed, 53 insertions, 34 deletions

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<AccessTime>&									  AccessTimes,
 										  std::vector<ZenCacheDiskLayer::CacheBucket::BucketPayload>& 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<ZenCacheDiskLayer::CacheBucket::BucketPayload>&  Payloads,
 										   const std::vector<ZenCacheDiskLayer::CacheBucket::BucketMetaData>& 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<uint64_t()>& 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<uin
 uint64_t
 ZenCacheDiskLayer::CacheBucket::ReadIndexFile(RwLock::ExclusiveLockScope&, const std::filesystem::path& IndexPath, uint32_t& OutVersion)
 {
-	ZEN_TRACE_CPU("Z$::Disk::Bucket::ReadIndexFile");
+	ZEN_TRACE_CPU("Z$::Bucket::ReadIndexFile");
 
 	if (!std::filesystem::is_regular_file(IndexPath))
 	{
@@ -964,7 +968,7 @@ ZenCacheDiskLayer::CacheBucket::ReadIndexFile(RwLock::ExclusiveLockScope&, const
 uint64_t
 ZenCacheDiskLayer::CacheBucket::ReadLog(RwLock::ExclusiveLockScope&, const std::filesystem::path& LogPath, uint64_t SkipEntryCount)
 {
-	ZEN_TRACE_CPU("Z$::Disk::Bucket::ReadLog");
+	ZEN_TRACE_CPU("Z$::Bucket::ReadLog");
 
 	if (!std::filesystem::is_regular_file(LogPath))
 	{
@@ -1034,7 +1038,7 @@ ZenCacheDiskLayer::CacheBucket::ReadLog(RwLock::ExclusiveLockScope&, const std::
 void
 ZenCacheDiskLayer::CacheBucket::InitializeIndexFromDisk(RwLock::ExclusiveLockScope& IndexLock, const bool IsNew)
 {
-	ZEN_TRACE_CPU("Z$::Disk::Bucket::OpenLog");
+	ZEN_TRACE_CPU("Z$::Bucket::Initialize");
 
 	m_StandaloneSize = 0;
 
@@ -1136,7 +1140,7 @@ ZenCacheDiskLayer::CacheBucket::BuildPath(PathBuilderBase& Path, const IoHash& H
 IoBuffer
 ZenCacheDiskLayer::CacheBucket::GetInlineCacheValue(const DiskLocation& Loc) const
 {
-	ZEN_TRACE_CPU("Z$::Disk::Bucket::GetInlineCacheValue");
+	ZEN_TRACE_CPU("Z$::Bucket::GetInlineCacheValue");
 
 	BlockStoreLocation Location = Loc.GetBlockLocation(m_Configuration.PayloadAlignment);
 
@@ -1152,7 +1156,7 @@ ZenCacheDiskLayer::CacheBucket::GetInlineCacheValue(const DiskLocation& Loc) con
 IoBuffer
 ZenCacheDiskLayer::CacheBucket::GetStandaloneCacheValue(ZenContentType ContentType, const IoHash& HashKey) const
 {
-	ZEN_TRACE_CPU("Z$::Disk::Bucket::GetStandaloneCacheValue");
+	ZEN_TRACE_CPU("Z$::Bucket::GetStandaloneCacheValue");
 
 	ExtendablePathBuilder<256> 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<IoHash> 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<uint64_t>& 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<uint64_t()>& 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<CacheBucket*> Buckets;
 	{
@@ -2494,7 +2503,7 @@ ZenCacheDiskLayer::CollectGarbage(GcContext& GcCtx)
 void
 ZenCacheDiskLayer::CacheBucket::PutStandaloneCacheValue(const IoHash& HashKey, const ZenCacheValue& Value, std::span<IoHash> 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<IoHash> 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<uint64_t()>& 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<GcReferenceChecker*>
 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<ReferenceIndex> FirstReferenceIndex;
 	std::vector<IoHash>			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<IoHash> 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<std::unique_ptr<CacheBucket>> Buckets;
@@ -4051,6 +4066,8 @@ ZenCacheDiskLayer::Drop()
 void
 ZenCacheDiskLayer::Flush()
 {
+	ZEN_TRACE_CPU("Z$::Flush");
+
 	std::vector<CacheBucket*> 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<std::future<void>> 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<CacheBucket*> 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);