add more trace scopes (#362)

* more trace scopes
* Make sure ReplayLogEntries uses the correct size for oplog buffer
* changelog

4 files changed, 212 insertions, 130 deletions

diff --git a/src/zenserver/cache/cachedisklayer.cpp b/src/zenserver/cache/cachedisklayer.cpp
index 9d3935131..7adf07350 100644
--- a/src/zenserver/cache/cachedisklayer.cpp
+++ b/src/zenserver/cache/cachedisklayer.cpp
@@ -183,7 +183,7 @@ ZenCacheDiskLayer::CacheBucket::OpenOrCreate(std::filesystem::path BucketDir, bo
 {
 	using namespace std::literals;
 
-	ZEN_TRACE_CPU("Z$::Bucket::OpenOrCreate");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::OpenOrCreate");
 
 	ZEN_LOG_SCOPE("opening cache bucket '{}'", BucketDir);
 
@@ -232,6 +232,8 @@ ZenCacheDiskLayer::CacheBucket::OpenOrCreate(std::filesystem::path BucketDir, bo
 
 	if (!IsNew)
 	{
+		ZEN_TRACE_CPU("Z$::Disk::Bucket::OpenOrCreate::Manifest");
+
 		Stopwatch  Timer;
 		const auto _ =
 			MakeGuard([&] { ZEN_INFO("read store manifest '{}' in {}", ManifestPath, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
@@ -277,7 +279,7 @@ ZenCacheDiskLayer::CacheBucket::OpenOrCreate(std::filesystem::path BucketDir, bo
 void
 ZenCacheDiskLayer::CacheBucket::MakeIndexSnapshot()
 {
-	ZEN_TRACE_CPU("Z$::Bucket::MakeIndexSnapshot");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::MakeIndexSnapshot");
 
 	uint64_t LogCount = m_SlogFile.GetLogCount();
 	if (m_LogFlushPosition == LogCount)
@@ -362,7 +364,7 @@ ZenCacheDiskLayer::CacheBucket::MakeIndexSnapshot()
 uint64_t
 ZenCacheDiskLayer::CacheBucket::ReadIndexFile(const std::filesystem::path& IndexPath, uint32_t& OutVersion)
 {
-	ZEN_TRACE_CPU("Z$::Bucket::ReadIndexFile");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::ReadIndexFile");
 
 	if (std::filesystem::is_regular_file(IndexPath))
 	{
@@ -437,7 +439,7 @@ ZenCacheDiskLayer::CacheBucket::ReadIndexFile(const std::filesystem::path& Index
 uint64_t
 ZenCacheDiskLayer::CacheBucket::ReadLog(const std::filesystem::path& LogPath, uint64_t SkipEntryCount)
 {
-	ZEN_TRACE_CPU("Z$::Bucket::ReadLog");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::ReadLog");
 
 	if (std::filesystem::is_regular_file(LogPath))
 	{
@@ -492,7 +494,7 @@ ZenCacheDiskLayer::CacheBucket::ReadLog(const std::filesystem::path& LogPath, ui
 void
 ZenCacheDiskLayer::CacheBucket::OpenLog(const bool IsNew)
 {
-	ZEN_TRACE_CPU("Z$::Bucket::OpenLog");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::OpenLog");
 
 	m_TotalStandaloneSize = 0;
 
@@ -624,6 +626,8 @@ ZenCacheDiskLayer::CacheBucket::BuildPath(PathBuilderBase& Path, const IoHash& H
 IoBuffer
 ZenCacheDiskLayer::CacheBucket::GetInlineCacheValue(const DiskLocation& Loc) const
 {
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::GetInlineCacheValue");
+
 	BlockStoreLocation Location = Loc.GetBlockLocation(m_PayloadAlignment);
 
 	IoBuffer Value = m_BlockStore.TryGetChunk(Location);
@@ -638,7 +642,7 @@ ZenCacheDiskLayer::CacheBucket::GetInlineCacheValue(const DiskLocation& Loc) con
 IoBuffer
 ZenCacheDiskLayer::CacheBucket::GetStandaloneCacheValue(const DiskLocation& Loc, const IoHash& HashKey) const
 {
-	ZEN_TRACE_CPU("Z$::Bucket::GetStandaloneCacheValue");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::GetStandaloneCacheValue");
 
 	ExtendablePathBuilder<256> DataFilePath;
 	BuildPath(DataFilePath, HashKey);
@@ -723,7 +727,7 @@ ZenCacheDiskLayer::CacheBucket::Put(const IoHash& HashKey, const ZenCacheValue&
 bool
 ZenCacheDiskLayer::CacheBucket::Drop()
 {
-	ZEN_TRACE_CPU("Z$::Bucket::Drop");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::Drop");
 
 	RwLock::ExclusiveLockScope _(m_IndexLock);
 
@@ -747,7 +751,7 @@ ZenCacheDiskLayer::CacheBucket::Drop()
 void
 ZenCacheDiskLayer::CacheBucket::Flush()
 {
-	ZEN_TRACE_CPU("Z$::Bucket::Flush");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::Flush");
 
 	m_BlockStore.Flush();
 
@@ -762,7 +766,7 @@ ZenCacheDiskLayer::CacheBucket::SaveManifest()
 {
 	using namespace std::literals;
 
-	ZEN_TRACE_CPU("Z$::Bucket::SaveManifest");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::SaveManifest");
 
 	CbObjectWriter Writer;
 	Writer << "BucketId"sv << m_BucketId;
@@ -884,7 +888,7 @@ ValidateCacheBucketEntryValue(ZenContentType ContentType, IoBuffer Buffer)
 void
 ZenCacheDiskLayer::CacheBucket::ScrubStorage(ScrubContext& Ctx)
 {
-	ZEN_TRACE_CPU("Z$::Bucket::Scrub");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::Scrub");
 
 	ZEN_INFO("scrubbing '{}'", m_BucketDir);
 
@@ -1123,7 +1127,7 @@ ZenCacheDiskLayer::CacheBucket::ScrubStorage(ScrubContext& Ctx)
 void
 ZenCacheDiskLayer::CacheBucket::GatherReferences(GcContext& GcCtx)
 {
-	ZEN_TRACE_CPU("Z$::DiskLayer::CacheBucket::GatherReferences");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::GatherReferences");
 
 	uint64_t WriteBlockTimeUs		 = 0;
 	uint64_t WriteBlockLongestTimeUs = 0;
@@ -1225,7 +1229,7 @@ ZenCacheDiskLayer::CacheBucket::GatherReferences(GcContext& GcCtx)
 void
 ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx)
 {
-	ZEN_TRACE_CPU("Z$::DiskLayer::CacheBucket::CollectGarbage");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::CollectGarbage");
 
 	ZEN_DEBUG("collecting garbage from '{}'", m_BucketDir);
 
@@ -1320,6 +1324,8 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx)
 	IndexMap						 Index;
 	BlockStore::ReclaimSnapshotState BlockStoreState;
 	{
+		ZEN_TRACE_CPU("Z$::Disk::Bucket::CollectGarbage::State");
+
 		RwLock::SharedLockScope __(m_IndexLock);
 		Stopwatch				Timer;
 		const auto				____ = MakeGuard([&] {
@@ -1364,6 +1370,8 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx)
 
 	if (GcCtx.IsDeletionMode())
 	{
+		ZEN_TRACE_CPU("Z$::Disk::Bucket::CollectGarbage::Delete");
+
 		std::error_code			   Ec;
 		ExtendablePathBuilder<256> Path;
 
@@ -1545,6 +1553,8 @@ ZenCacheDiskLayer::CacheBucket::CollectGarbage(GcContext& GcCtx)
 void
 ZenCacheDiskLayer::CacheBucket::UpdateAccessTimes(const std::vector<zen::access_tracking::KeyAccessTime>& AccessTimes)
 {
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::UpdateAccessTimes");
+
 	using namespace access_tracking;
 
 	for (const KeyAccessTime& KeyTime : AccessTimes)
@@ -1612,6 +1622,8 @@ ZenCacheDiskLayer::CacheBucket::GetValueDetails(const std::string_view ValueFilt
 void
 ZenCacheDiskLayer::CollectGarbage(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("Z$::Disk::CollectGarbage");
+
 	RwLock::SharedLockScope _(m_Lock);
 
 	for (auto& Kv : m_Buckets)
@@ -1639,7 +1651,7 @@ ZenCacheDiskLayer::UpdateAccessTimes(const zen::access_tracking::AccessTimes& Ac
 void
 ZenCacheDiskLayer::CacheBucket::PutStandaloneCacheValue(const IoHash& HashKey, const ZenCacheValue& Value)
 {
-	ZEN_TRACE_CPU("Z$::Bucket::PutStandaloneCacheValue");
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::PutStandaloneCacheValue");
 
 	uint64_t NewFileSize = Value.Value.Size();
 
@@ -1777,6 +1789,8 @@ ZenCacheDiskLayer::CacheBucket::PutStandaloneCacheValue(const IoHash& HashKey, c
 void
 ZenCacheDiskLayer::CacheBucket::PutInlineCacheValue(const IoHash& HashKey, const ZenCacheValue& Value)
 {
+	ZEN_TRACE_CPU("Z$::Disk::Bucket::PutInlineCacheValue");
+
 	uint8_t EntryFlags = 0;
 
 	if (Value.Value.GetContentType() == ZenContentType::kCbObject)
@@ -1824,6 +1838,8 @@ ZenCacheDiskLayer::~ZenCacheDiskLayer() = default;
 bool
 ZenCacheDiskLayer::Get(std::string_view InBucket, const IoHash& HashKey, ZenCacheValue& OutValue)
 {
+	ZEN_TRACE_CPU("Z$::Disk::Get");
+
 	const auto	 BucketName = std::string(InBucket);
 	CacheBucket* Bucket		= nullptr;
 
@@ -1871,6 +1887,8 @@ ZenCacheDiskLayer::Get(std::string_view InBucket, const IoHash& HashKey, ZenCach
 void
 ZenCacheDiskLayer::Put(std::string_view InBucket, const IoHash& HashKey, const ZenCacheValue& Value)
 {
+	ZEN_TRACE_CPU("Z$::Disk::Put");
+
 	const auto	 BucketName = std::string(InBucket);
 	CacheBucket* Bucket		= nullptr;
 
@@ -2060,6 +2078,8 @@ ZenCacheDiskLayer::ScrubStorage(ScrubContext& Ctx)
 void
 ZenCacheDiskLayer::GatherReferences(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("Z$::Disk::GatherReferences");
+
 	RwLock::SharedLockScope _(m_Lock);
 
 	for (auto& Kv : m_Buckets)
diff --git a/src/zenserver/cache/cachememorylayer.cpp b/src/zenserver/cache/cachememorylayer.cpp
index 1ef581ba5..c18db7706 100644
--- a/src/zenserver/cache/cachememorylayer.cpp
+++ b/src/zenserver/cache/cachememorylayer.cpp
@@ -4,6 +4,7 @@
 
 #include <zencore/compactbinaryvalidation.h>
 #include <zencore/compress.h>
+#include <zencore/trace.h>
 
 //////////////////////////////////////////////////////////////////////////
 
@@ -20,6 +21,8 @@ ZenCacheMemoryLayer::~ZenCacheMemoryLayer()
 bool
 ZenCacheMemoryLayer::Get(std::string_view InBucket, const IoHash& HashKey, ZenCacheValue& OutValue)
 {
+	ZEN_TRACE_CPU("Z$::Mem::Get");
+
 	RwLock::SharedLockScope _(m_Lock);
 
 	auto It = m_Buckets.find(std::string(InBucket));
@@ -43,6 +46,8 @@ ZenCacheMemoryLayer::Get(std::string_view InBucket, const IoHash& HashKey, ZenCa
 void
 ZenCacheMemoryLayer::Put(std::string_view InBucket, const IoHash& HashKey, const ZenCacheValue& Value)
 {
+	ZEN_TRACE_CPU("Z$::Mem::Put");
+
 	const auto	 BucketName = std::string(InBucket);
 	CacheBucket* Bucket		= nullptr;
 
@@ -240,6 +245,8 @@ ZenCacheMemoryLayer::CacheBucket::GatherAccessTimes(std::vector<zen::access_trac
 bool
 ZenCacheMemoryLayer::CacheBucket::Get(const IoHash& HashKey, ZenCacheValue& OutValue)
 {
+	ZEN_TRACE_CPU("Z$::Mem::Bucket::Get");
+
 	RwLock::SharedLockScope _(m_BucketLock);
 
 	if (auto It = m_CacheMap.find(HashKey); It != m_CacheMap.end())
@@ -261,6 +268,8 @@ ZenCacheMemoryLayer::CacheBucket::Get(const IoHash& HashKey, ZenCacheValue& OutV
 void
 ZenCacheMemoryLayer::CacheBucket::Put(const IoHash& HashKey, const ZenCacheValue& Value)
 {
+	ZEN_TRACE_CPU("Z$::Mem::Bucket::Put");
+
 	size_t PayloadSize = Value.Value.GetSize();
 	{
 		GcClock::Tick			   AccessTime = GcClock::TickCount();
diff --git a/src/zenserver/cache/httpstructuredcache.cpp b/src/zenserver/cache/httpstructuredcache.cpp
index 7f1ce18f9..32e8c1f98 100644
--- a/src/zenserver/cache/httpstructuredcache.cpp
+++ b/src/zenserver/cache/httpstructuredcache.cpp
@@ -603,7 +603,10 @@ HttpStructuredCacheService::HandleDetailsRequest(HttpServerRequest& Request)
 void
 HttpStructuredCacheService::HandleRequest(HttpServerRequest& Request)
 {
+	ZEN_TRACE_CPU("z$::Http::HandleRequest");
+
 	m_CacheStats.RequestCount++;
+
 	metrics::OperationTiming::Scope $(m_HttpRequests);
 
 	std::string_view Key = Request.RelativeUri();
@@ -1599,6 +1602,8 @@ HttpStructuredCacheService::HandleRpcRequest(const CacheRequestContext& Context,
 											 int&						OutTargetProcessId,
 											 CbPackage&					OutResultPackage)
 {
+	ZEN_TRACE_CPU("Z$::HandleRpcRequest");
+
 	CbPackage	 Package;
 	CbObjectView Object;
 	CbObject	 ObjectBuffer;
@@ -1719,6 +1724,7 @@ HttpStructuredCacheService::ReplayRequestRecorder(const CacheRequestContext&  Co
 void
 HttpStructuredCacheService::HandleRpcRequest(HttpServerRequest& Request)
 {
+	ZEN_TRACE_CPU("z$::Http::HandleRpcRequest");
 	switch (Request.RequestVerb())
 	{
 		case HttpVerb::kPost:
@@ -2020,6 +2026,8 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(const CacheRequestContext&
 
 	for (CbFieldView RequestField : RequestsArray)
 	{
+		ZEN_TRACE_CPU("Z$::RpcGetCacheRecords::Request");
+
 		Stopwatch		   Timer;
 		RecordRequestData& Request		 = Requests.emplace_back();
 		CbObjectView	   RequestObject = RequestField.AsObjectView();
@@ -2245,70 +2253,74 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(const CacheRequestContext&
 		m_UpstreamCache.GetCacheRecords(*Namespace, UpstreamRequests, std::move(OnCacheRecordGetComplete));
 	}
 
-	CbPackage	   ResponsePackage;
-	CbObjectWriter ResponseObject;
-
-	ResponseObject.BeginArray("Result"sv);
-	for (RecordRequestData& Request : Requests)
 	{
-		const CacheKey& Key = Request.Upstream.Key;
-		if (Request.Complete ||
-			(Request.RecordObject && EnumHasAllFlags(Request.DownstreamPolicy.GetRecordPolicy(), CachePolicy::PartialRecord)))
+		ZEN_TRACE_CPU("Z$::RpcGetCacheRecords::Response");
+		CbPackage	   ResponsePackage;
+		CbObjectWriter ResponseObject;
+
+		ResponseObject.BeginArray("Result"sv);
+		for (RecordRequestData& Request : Requests)
 		{
-			ResponseObject << Request.RecordObject;
-			for (ValueRequestData& Value : Request.Values)
+			const CacheKey& Key = Request.Upstream.Key;
+			if (Request.Complete ||
+				(Request.RecordObject && EnumHasAllFlags(Request.DownstreamPolicy.GetRecordPolicy(), CachePolicy::PartialRecord)))
 			{
-				if (!EnumHasAllFlags(Value.DownstreamPolicy, CachePolicy::SkipData) && Value.Payload)
+				ResponseObject << Request.RecordObject;
+				for (ValueRequestData& Value : Request.Values)
 				{
-					ResponsePackage.AddAttachment(CbAttachment(Value.Payload, Value.ContentId));
+					if (!EnumHasAllFlags(Value.DownstreamPolicy, CachePolicy::SkipData) && Value.Payload)
+					{
+						ResponsePackage.AddAttachment(CbAttachment(Value.Payload, Value.ContentId));
+					}
 				}
-			}
 
-			ZEN_DEBUG("GETCACHERECORD HIT - '{}/{}/{}' {}{} ({}) in {}",
-					  *Namespace,
-					  Key.Bucket,
-					  Key.Hash,
-					  NiceBytes(Request.RecordCacheValue.Size()),
-					  Request.Complete ? ""sv : " (PARTIAL)"sv,
-					  Request.Source ? Request.Source->Url : "LOCAL"sv,
-					  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
-			m_CacheStats.HitCount++;
-			m_CacheStats.UpstreamHitCount += Request.Source ? 1 : 0;
-		}
-		else
-		{
-			ResponseObject.AddNull();
-
-			if (!EnumHasAnyFlags(Request.DownstreamPolicy.GetRecordPolicy(), CachePolicy::Query))
-			{
-				// If they requested no query, do not record this as a miss
-				ZEN_DEBUG("GETCACHERECORD DISABLEDQUERY - '{}/{}/{}' in {}",
+				ZEN_DEBUG("GETCACHERECORD HIT - '{}/{}/{}' {}{} ({}) in {}",
 						  *Namespace,
 						  Key.Bucket,
 						  Key.Hash,
+						  NiceBytes(Request.RecordCacheValue.Size()),
+						  Request.Complete ? ""sv : " (PARTIAL)"sv,
+						  Request.Source ? Request.Source->Url : "LOCAL"sv,
 						  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
+				m_CacheStats.HitCount++;
+				m_CacheStats.UpstreamHitCount += Request.Source ? 1 : 0;
 			}
 			else
 			{
-				ZEN_DEBUG("GETCACHERECORD MISS - '{}/{}/{}'{} ({}) in {}",
-						  *Namespace,
-						  Key.Bucket,
-						  Key.Hash,
-						  Request.RecordObject ? ""sv : " (PARTIAL)"sv,
-						  Request.Source ? Request.Source->Url : "LOCAL"sv,
-						  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
-				m_CacheStats.MissCount++;
+				ResponseObject.AddNull();
+
+				if (!EnumHasAnyFlags(Request.DownstreamPolicy.GetRecordPolicy(), CachePolicy::Query))
+				{
+					// If they requested no query, do not record this as a miss
+					ZEN_DEBUG("GETCACHERECORD DISABLEDQUERY - '{}/{}/{}' in {}",
+							  *Namespace,
+							  Key.Bucket,
+							  Key.Hash,
+							  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
+				}
+				else
+				{
+					ZEN_DEBUG("GETCACHERECORD MISS - '{}/{}/{}'{} ({}) in {}",
+							  *Namespace,
+							  Key.Bucket,
+							  Key.Hash,
+							  Request.RecordObject ? ""sv : " (PARTIAL)"sv,
+							  Request.Source ? Request.Source->Url : "LOCAL"sv,
+							  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
+					m_CacheStats.MissCount++;
+				}
 			}
 		}
+		ResponseObject.EndArray();
+		ResponsePackage.SetObject(ResponseObject.Save());
+		return ResponsePackage;
 	}
-	ResponseObject.EndArray();
-	ResponsePackage.SetObject(ResponseObject.Save());
-	return ResponsePackage;
 }
 
 CbPackage
 HttpStructuredCacheService::HandleRpcPutCacheValues(const CacheRequestContext& Context, const CbPackage& BatchRequest)
 {
+	ZEN_TRACE_CPU("Z$::RpcPutCacheValues");
 	CbObjectView BatchObject = BatchRequest.GetObject();
 	CbObjectView Params		 = BatchObject["Params"sv].AsObjectView();
 
@@ -2324,6 +2336,8 @@ HttpStructuredCacheService::HandleRpcPutCacheValues(const CacheRequestContext& C
 	std::vector<bool> Results;
 	for (CbFieldView RequestField : Params["Requests"sv])
 	{
+		ZEN_TRACE_CPU("Z$::RpcPutCacheValues::Request");
+
 		Stopwatch Timer;
 
 		CbObjectView RequestObject = RequestField.AsObjectView();
@@ -2404,23 +2418,27 @@ HttpStructuredCacheService::HandleRpcPutCacheValues(const CacheRequestContext& C
 		return CbPackage{};
 	}
 
-	CbObjectWriter ResponseObject;
-	ResponseObject.BeginArray("Result"sv);
-	for (bool Value : Results)
 	{
-		ResponseObject.AddBool(Value);
-	}
-	ResponseObject.EndArray();
+		ZEN_TRACE_CPU("Z$::RpcPutCacheValues::Response");
+		CbObjectWriter ResponseObject;
+		ResponseObject.BeginArray("Result"sv);
+		for (bool Value : Results)
+		{
+			ResponseObject.AddBool(Value);
+		}
+		ResponseObject.EndArray();
 
-	CbPackage RpcResponse;
-	RpcResponse.SetObject(ResponseObject.Save());
+		CbPackage RpcResponse;
+		RpcResponse.SetObject(ResponseObject.Save());
 
-	return RpcResponse;
+		return RpcResponse;
+	}
 }
 
 CbPackage
 HttpStructuredCacheService::HandleRpcGetCacheValues(const CacheRequestContext& Context, CbObjectView RpcRequest)
 {
+	ZEN_TRACE_CPU("Z$::RpcGetCacheValues");
 	ZEN_ASSERT(RpcRequest["Method"sv].AsString() == "GetCacheValues"sv);
 
 	CbObjectView			   Params		 = RpcRequest["Params"sv].AsObjectView();
@@ -2450,6 +2468,8 @@ HttpStructuredCacheService::HandleRpcGetCacheValues(const CacheRequestContext& C
 
 	for (CbFieldView RequestField : RequestView)
 	{
+		ZEN_TRACE_CPU("Z$::RpcGetCacheValues::Request");
+
 		Stopwatch Timer;
 
 		RequestData& Request	   = Requests.emplace_back();
@@ -2584,38 +2604,41 @@ HttpStructuredCacheService::HandleRpcGetCacheValues(const CacheRequestContext& C
 		return CbPackage{};
 	}
 
-	CbPackage	   RpcResponse;
-	CbObjectWriter ResponseObject;
-	ResponseObject.BeginArray("Result"sv);
-	for (const RequestData& Request : Requests)
 	{
-		ResponseObject.BeginObject();
+		ZEN_TRACE_CPU("Z$::RpcGetCacheValues::Response");
+		CbPackage	   RpcResponse;
+		CbObjectWriter ResponseObject;
+		ResponseObject.BeginArray("Result"sv);
+		for (const RequestData& Request : Requests)
 		{
-			const CompressedBuffer& Result = Request.Result;
-			if (Result)
+			ResponseObject.BeginObject();
 			{
-				ResponseObject.AddHash("RawHash"sv, Request.RawHash);
-				if (!EnumHasAllFlags(Request.Policy, CachePolicy::SkipData))
+				const CompressedBuffer& Result = Request.Result;
+				if (Result)
 				{
-					RpcResponse.AddAttachment(CbAttachment(Result, Request.RawHash));
+					ResponseObject.AddHash("RawHash"sv, Request.RawHash);
+					if (!EnumHasAllFlags(Request.Policy, CachePolicy::SkipData))
+					{
+						RpcResponse.AddAttachment(CbAttachment(Result, Request.RawHash));
+					}
+					else
+					{
+						ResponseObject.AddInteger("RawSize"sv, Request.RawSize);
+					}
 				}
-				else
+				else if (Request.RawHash != IoHash::Zero)
 				{
+					ResponseObject.AddHash("RawHash"sv, Request.RawHash);
 					ResponseObject.AddInteger("RawSize"sv, Request.RawSize);
 				}
 			}
-			else if (Request.RawHash != IoHash::Zero)
-			{
-				ResponseObject.AddHash("RawHash"sv, Request.RawHash);
-				ResponseObject.AddInteger("RawSize"sv, Request.RawSize);
-			}
+			ResponseObject.EndObject();
 		}
-		ResponseObject.EndObject();
-	}
-	ResponseObject.EndArray();
+		ResponseObject.EndArray();
 
-	RpcResponse.SetObject(ResponseObject.Save());
-	return RpcResponse;
+		RpcResponse.SetObject(ResponseObject.Save());
+		return RpcResponse;
+	}
 }
 
 namespace cache::detail {
@@ -2657,6 +2680,7 @@ namespace cache::detail {
 CbPackage
 HttpStructuredCacheService::HandleRpcGetCacheChunks(const CacheRequestContext& Context, CbObjectView RpcRequest)
 {
+	ZEN_TRACE_CPU("Z$::RpcGetCacheChunks");
 	using namespace cache::detail;
 
 	std::string						Namespace;
@@ -2698,6 +2722,8 @@ HttpStructuredCacheService::ParseGetCacheChunksRequest(std::string&								  Nam
 													   std::vector<cache::detail::ChunkRequest*>& ValueRequests,
 													   CbObjectView								  RpcRequest)
 {
+	ZEN_TRACE_CPU("Z$::ParseGetCacheChunksRequest");
+
 	using namespace cache::detail;
 
 	ZEN_ASSERT(RpcRequest["Method"sv].AsString() == "GetCacheChunks"sv);
@@ -2731,6 +2757,8 @@ HttpStructuredCacheService::ParseGetCacheChunksRequest(std::string&								  Nam
 
 	for (CbFieldView RequestView : ChunkRequestsArray)
 	{
+		ZEN_TRACE_CPU("Z$::ParseGetCacheChunksRequest::Request");
+
 		CbObjectView	   RequestObject = RequestView.AsObjectView();
 		CacheChunkRequest& RequestKey	 = RequestKeys.emplace_back();
 		ChunkRequest&	   Request		 = Requests.emplace_back();
@@ -2809,12 +2837,16 @@ HttpStructuredCacheService::GetLocalCacheRecords(const CacheRequestContext&
 												 std::vector<cache::detail::ChunkRequest*>& RecordRequests,
 												 std::vector<CacheChunkRequest*>&			OutUpstreamChunks)
 {
+	ZEN_TRACE_CPU("Z$::GetLocalCacheRecords");
+
 	using namespace cache::detail;
 	const bool HasUpstream = m_UpstreamCache.IsActive();
 
 	std::vector<CacheKeyRequest*> UpstreamRecordRequests;
 	for (size_t RecordIndex = 0; RecordIndex < Records.size(); ++RecordIndex)
 	{
+		ZEN_TRACE_CPU("Z$::GetLocalCacheRecords::Record");
+
 		Stopwatch		 Timer;
 		CacheKeyRequest& RecordKey = RecordKeys[RecordIndex];
 		RecordBody&		 Record	   = Records[RecordIndex];
@@ -2872,6 +2904,8 @@ HttpStructuredCacheService::GetLocalCacheRecords(const CacheRequestContext&
 
 	for (ChunkRequest* Request : RecordRequests)
 	{
+		ZEN_TRACE_CPU("Z$::GetLocalCacheRecords::Chunk");
+
 		Stopwatch Timer;
 		if (Request->Key->ChunkId == IoHash::Zero)
 		{
@@ -2962,11 +2996,15 @@ HttpStructuredCacheService::GetLocalCacheValues(const CacheRequestContext&
 												std::vector<cache::detail::ChunkRequest*>& ValueRequests,
 												std::vector<CacheChunkRequest*>&		   OutUpstreamChunks)
 {
+	ZEN_TRACE_CPU("Z$::GetLocalCacheValues");
+
 	using namespace cache::detail;
 	const bool HasUpstream = m_UpstreamCache.IsActive();
 
 	for (ChunkRequest* Request : ValueRequests)
 	{
+		ZEN_TRACE_CPU("Z$::GetLocalCacheValues::Value");
+
 		Stopwatch Timer;
 		if (!Request->Exists && EnumHasAllFlags(Request->DownstreamPolicy, CachePolicy::QueryLocal))
 		{
@@ -3007,62 +3045,65 @@ HttpStructuredCacheService::GetUpstreamCacheChunks(const CacheRequestContext&
 												   std::vector<CacheChunkRequest>&			 RequestKeys,
 												   std::vector<cache::detail::ChunkRequest>& Requests)
 {
+	if (UpstreamChunks.empty())
+	{
+		return;
+	}
+	ZEN_TRACE_CPU("Z$::GetUpstreamCacheChunks");
+
 	using namespace cache::detail;
 
-	if (!UpstreamChunks.empty())
-	{
-		const auto OnCacheChunksGetComplete = [this, Namespace, &RequestKeys, &Requests, Context](CacheChunkGetCompleteParams&& Params) {
-			if (Params.RawHash == Params.RawHash.Zero)
+	const auto OnCacheChunksGetComplete = [this, Namespace, &RequestKeys, &Requests, Context](CacheChunkGetCompleteParams&& Params) {
+		if (Params.RawHash == Params.RawHash.Zero)
+		{
+			return;
+		}
+
+		CacheChunkRequest& Key			= Params.Request;
+		size_t			   RequestIndex = std::distance(RequestKeys.data(), &Key);
+		ChunkRequest&	   Request		= Requests[RequestIndex];
+		Request.ElapsedTimeUs += static_cast<uint64_t>(Params.ElapsedSeconds * 1000000.0);
+		if (EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::StoreLocal) ||
+			!EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::SkipData))
+		{
+			CompressedBuffer Compressed = CompressedBuffer::FromCompressedNoValidate(IoBuffer(Params.Value));
+			if (!Compressed)
 			{
 				return;
 			}
 
-			CacheChunkRequest& Key			= Params.Request;
-			size_t			   RequestIndex = std::distance(RequestKeys.data(), &Key);
-			ChunkRequest&	   Request		= Requests[RequestIndex];
-			Request.ElapsedTimeUs += static_cast<uint64_t>(Params.ElapsedSeconds * 1000000.0);
-			if (EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::StoreLocal) ||
-				!EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::SkipData))
+			bool StoreLocal = EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::StoreLocal) && AreDiskWritesAllowed();
+			if (StoreLocal)
 			{
-				CompressedBuffer Compressed = CompressedBuffer::FromCompressedNoValidate(IoBuffer(Params.Value));
-				if (!Compressed)
+				if (Request.IsRecordRequest)
 				{
-					return;
-				}
-
-				bool StoreLocal = EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::StoreLocal) && AreDiskWritesAllowed();
-				if (StoreLocal)
-				{
-					if (Request.IsRecordRequest)
-					{
-						m_CidStore.AddChunk(Params.Value, Params.RawHash);
-					}
-					else
-					{
-						m_CacheStore.Put(Context,
-										 Namespace,
-										 Key.Key.Bucket,
-										 Key.Key.Hash,
-										 {.Value = Params.Value, .RawSize = Params.RawSize, .RawHash = Params.RawHash});
-						m_CacheStats.WriteCount++;
-					}
+					m_CidStore.AddChunk(Params.Value, Params.RawHash);
 				}
-				if (!EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::SkipData))
+				else
 				{
-					Request.Value = std::move(Compressed);
+					m_CacheStore.Put(Context,
+									 Namespace,
+									 Key.Key.Bucket,
+									 Key.Key.Hash,
+									 {.Value = Params.Value, .RawSize = Params.RawSize, .RawHash = Params.RawHash});
+					m_CacheStats.WriteCount++;
 				}
 			}
-			Key.ChunkId			 = Params.RawHash;
-			Request.Exists		 = true;
-			Request.RawSize		 = Params.RawSize;
-			Request.RawSizeKnown = true;
-			Request.Source		 = Params.Source;
+			if (!EnumHasAllFlags(Request.DownstreamPolicy, CachePolicy::SkipData))
+			{
+				Request.Value = std::move(Compressed);
+			}
+		}
+		Key.ChunkId			 = Params.RawHash;
+		Request.Exists		 = true;
+		Request.RawSize		 = Params.RawSize;
+		Request.RawSizeKnown = true;
+		Request.Source		 = Params.Source;
 
-			m_CacheStats.UpstreamHitCount++;
-		};
+		m_CacheStats.UpstreamHitCount++;
+	};
 
-		m_UpstreamCache.GetCacheChunks(Namespace, UpstreamChunks, std::move(OnCacheChunksGetComplete));
-	}
+	m_UpstreamCache.GetCacheChunks(Namespace, UpstreamChunks, std::move(OnCacheChunksGetComplete));
 }
 
 CbPackage
@@ -3070,6 +3111,8 @@ HttpStructuredCacheService::WriteGetCacheChunksResponse([[maybe_unused]] const C
 														std::string_view							Namespace,
 														std::vector<cache::detail::ChunkRequest>&	Requests)
 {
+	ZEN_TRACE_CPU("Z$::WriteGetCacheChunksResponse");
+
 	using namespace cache::detail;
 
 	CbPackage	   RpcResponse;
@@ -3078,6 +3121,8 @@ HttpStructuredCacheService::WriteGetCacheChunksResponse([[maybe_unused]] const C
 	Writer.BeginArray("Result"sv);
 	for (ChunkRequest& Request : Requests)
 	{
+		ZEN_TRACE_CPU("Z$::WriteGetCacheChunksResponse::Request");
+
 		Writer.BeginObject();
 		{
 			if (Request.Exists)
diff --git a/src/zenserver/cache/structuredcachestore.cpp b/src/zenserver/cache/structuredcachestore.cpp
index 56e83eef2..2ba1f61bd 100644
--- a/src/zenserver/cache/structuredcachestore.cpp
+++ b/src/zenserver/cache/structuredcachestore.cpp
@@ -61,7 +61,7 @@ ZenCacheNamespace::~ZenCacheNamespace()
 bool
 ZenCacheNamespace::Get(std::string_view InBucket, const IoHash& HashKey, ZenCacheValue& OutValue)
 {
-	ZEN_TRACE_CPU("Z$::Get");
+	ZEN_TRACE_CPU("Z$::Namespace::Get");
 
 	bool Ok = m_MemLayer.Get(InBucket, HashKey, OutValue);
 
@@ -90,7 +90,7 @@ ZenCacheNamespace::Get(std::string_view InBucket, const IoHash& HashKey, ZenCach
 void
 ZenCacheNamespace::Put(std::string_view InBucket, const IoHash& HashKey, const ZenCacheValue& Value)
 {
-	ZEN_TRACE_CPU("Z$::Put");
+	ZEN_TRACE_CPU("Z$::Namespace::Put");
 
 	// Store value and index
 
@@ -152,6 +152,8 @@ ZenCacheNamespace::ScrubStorage(ScrubContext& Ctx)
 void
 ZenCacheNamespace::GatherReferences(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("Z$::ZenCacheNamespace::GatherReferences");
+
 	Stopwatch  Timer;
 	const auto Guard =
 		MakeGuard([&] { ZEN_DEBUG("cache gathered all references from '{}' in {}", m_RootDir, NiceTimeSpanMs(Timer.GetElapsedTimeMs())); });
@@ -166,6 +168,8 @@ ZenCacheNamespace::GatherReferences(GcContext& GcCtx)
 void
 ZenCacheNamespace::CollectGarbage(GcContext& GcCtx)
 {
+	ZEN_TRACE_CPU("Z$::Namespace::CollectGarbage");
+
 	m_MemLayer.Reset();
 	m_DiskLayer.CollectGarbage(GcCtx);
 }
@@ -354,6 +358,8 @@ ZenCacheStore::Get(const CacheRequestContext& Context,
 				   const IoHash&			  HashKey,
 				   ZenCacheValue&			  OutValue)
 {
+	ZEN_TRACE_CPU("Z$::Get");
+
 	if (ZenCacheNamespace* Store = GetNamespace(Namespace); Store)
 	{
 		bool Result = Store->Get(Bucket, HashKey, OutValue);
@@ -396,6 +402,8 @@ ZenCacheStore::Put(const CacheRequestContext& Context,
 				   const IoHash&			  HashKey,
 				   const ZenCacheValue&		  Value)
 {
+	ZEN_TRACE_CPU("Z$::Put");
+
 	if (m_Configuration.EnableWriteLog)
 	{
 		ZEN_TRACE_CPU("Z$::Get::WriteLog");