add more trace scopes (#362)

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

1 files changed, 160 insertions, 115 deletions

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)