De/more upstream details (#168)v0.1.6-pre9v0.1.6-pre10

* Pass along endpoint info for each upstream request
* Add more timing details in log
* more log details for single item upstream fetch
* DISABLEDQUERY over SKIP

1 files changed, 166 insertions, 93 deletions

diff --git a/zenserver/cache/structuredcache.cpp b/zenserver/cache/structuredcache.cpp
index 50ecd41c2..cd679d186 100644
--- a/zenserver/cache/structuredcache.cpp
+++ b/zenserver/cache/structuredcache.cpp
@@ -502,6 +502,8 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 		return Request.WriteResponse(HttpResponseCode::OK);
 	}
 
+	Stopwatch Timer;
+
 	if (EnumHasAllFlags(PolicyFromUrl, CachePolicy::QueryLocal) &&
 		m_CacheStore.Get(Ref.Namespace, Ref.BucketSegment, Ref.HashKey, ClientResultValue))
 	{
@@ -564,12 +566,13 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 
 	if (Success)
 	{
-		ZEN_DEBUG("HIT - '{}/{}/{}' {} '{}' (LOCAL)",
+		ZEN_DEBUG("GETCACHERECORD HIT - '{}/{}/{}' {} '{}' (LOCAL) in {}",
 				  Ref.Namespace,
 				  Ref.BucketSegment,
 				  Ref.HashKey,
 				  NiceBytes(ClientResultValue.Value.Size()),
-				  ToString(ClientResultValue.Value.GetContentType()));
+				  ToString(ClientResultValue.Value.GetContentType()),
+				  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 
 		m_CacheStats.HitCount++;
 		if (SkipData && AcceptType != ZenContentType::kCbPackage && AcceptType != ZenContentType::kCbObject)
@@ -584,7 +587,12 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 	}
 	else if (!EnumHasAllFlags(PolicyFromUrl, CachePolicy::QueryRemote))
 	{
-		ZEN_DEBUG("MISS - '{}/{}/{}' '{}'", Ref.Namespace, Ref.BucketSegment, Ref.HashKey, ToString(AcceptType));
+		ZEN_DEBUG("GETCACHERECORD MISS - '{}/{}/{}' '{}' in {}",
+				  Ref.Namespace,
+				  Ref.BucketSegment,
+				  Ref.HashKey,
+				  ToString(AcceptType),
+				  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 		m_CacheStats.MissCount++;
 		return Request.WriteResponse(HttpResponseCode::NotFound);
 	}
@@ -592,7 +600,10 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 	// Issue upstream query asynchronously in order to keep requests flowing without
 	// hogging I/O servicing threads with blocking work
 
-	Request.WriteResponseAsync([this, AcceptType, PolicyFromUrl, Ref](HttpServerRequest& AsyncRequest) {
+	uint64_t LocalElapsedTimeUs = Timer.GetElapsedTimeUs();
+
+	Request.WriteResponseAsync([this, AcceptType, PolicyFromUrl, Ref, LocalElapsedTimeUs](HttpServerRequest& AsyncRequest) {
+		Stopwatch	  Timer;
 		bool		  Success		= false;
 		const bool	  PartialRecord = EnumHasAllFlags(PolicyFromUrl, CachePolicy::PartialRecord);
 		const bool	  QueryLocal	= EnumHasAllFlags(PolicyFromUrl, CachePolicy::QueryLocal);
@@ -602,9 +613,9 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 
 		metrics::OperationTiming::Scope $(m_UpstreamGetRequestTiming);
 
-		if (GetUpstreamCacheResult UpstreamResult =
+		if (GetUpstreamCacheSingleResult UpstreamResult =
 				m_UpstreamCache.GetCacheRecord(Ref.Namespace, {Ref.BucketSegment, Ref.HashKey}, AcceptType);
-			UpstreamResult.Success)
+			UpstreamResult.Status.Success)
 		{
 			Success = true;
 
@@ -725,12 +736,13 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 
 		if (Success)
 		{
-			ZEN_DEBUG("HIT - '{}/{}/{}' {} '{}' (UPSTREAM)",
+			ZEN_DEBUG("GETCACHERECORD HIT - '{}/{}/{}' {} '{}' (UPSTREAM) in {}",
 					  Ref.Namespace,
 					  Ref.BucketSegment,
 					  Ref.HashKey,
 					  NiceBytes(ClientResultValue.Value.Size()),
-					  ToString(ClientResultValue.Value.GetContentType()));
+					  ToString(ClientResultValue.Value.GetContentType()),
+					  NiceLatencyNs((LocalElapsedTimeUs + Timer.GetElapsedTimeUs()) * 1000));
 
 			m_CacheStats.HitCount++;
 			m_CacheStats.UpstreamHitCount++;
@@ -748,7 +760,12 @@ HttpStructuredCacheService::HandleGetCacheRecord(zen::HttpServerRequest& Request
 		}
 		else
 		{
-			ZEN_DEBUG("MISS - '{}/{}/{}' '{}'", Ref.Namespace, Ref.BucketSegment, Ref.HashKey, ToString(AcceptType));
+			ZEN_DEBUG("GETCACHERECORD MISS - '{}/{}/{}' '{}' in {}",
+					  Ref.Namespace,
+					  Ref.BucketSegment,
+					  Ref.HashKey,
+					  ToString(AcceptType),
+					  NiceLatencyNs((LocalElapsedTimeUs + Timer.GetElapsedTimeUs()) * 1000));
 			m_CacheStats.MissCount++;
 			AsyncRequest.WriteResponse(HttpResponseCode::NotFound);
 		}
@@ -769,9 +786,10 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 
 	Body.SetContentType(ContentType);
 
+	Stopwatch Timer;
+
 	if (ContentType == HttpContentType::kBinary || ContentType == HttpContentType::kCompressedBinary)
 	{
-		ZEN_DEBUG("PUT - '{}/{}/{}' {} '{}'", Ref.Namespace, Ref.BucketSegment, Ref.HashKey, NiceBytes(Body.Size()), ToString(ContentType));
 		m_CacheStore.Put(Ref.Namespace, Ref.BucketSegment, Ref.HashKey, {.Value = Body});
 
 		if (EnumHasAllFlags(PolicyFromUrl, CachePolicy::StoreRemote))
@@ -779,6 +797,13 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 			m_UpstreamCache.EnqueueUpstream({.Type = ContentType, .Namespace = Ref.Namespace, .Key = {Ref.BucketSegment, Ref.HashKey}});
 		}
 
+		ZEN_DEBUG("PUTCACHERECORD - '{}/{}/{}' {} '{}' in {}",
+				  Ref.Namespace,
+				  Ref.BucketSegment,
+				  Ref.HashKey,
+				  NiceBytes(Body.Size()),
+				  ToString(ContentType),
+				  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 		Request.WriteResponse(HttpResponseCode::Created);
 	}
 	else if (ContentType == HttpContentType::kCbObject)
@@ -787,7 +812,7 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 
 		if (ValidationResult != CbValidateError::None)
 		{
-			ZEN_WARN("PUT - '{}/{}/{}' '{}' FAILED, invalid compact binary",
+			ZEN_WARN("PUTCACHERECORD - '{}/{}/{}' '{}' FAILED, invalid compact binary",
 					 Ref.Namespace,
 					 Ref.BucketSegment,
 					 Ref.HashKey,
@@ -809,14 +834,15 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 			TotalCount++;
 		});
 
-		ZEN_DEBUG("PUT - '{}/{}/{}' {} '{}' attachments '{}/{}' (valid/total)",
+		ZEN_DEBUG("PUTCACHERECORD - '{}/{}/{}' {} '{}' attachments '{}/{}' (valid/total) in {}",
 				  Ref.Namespace,
 				  Ref.BucketSegment,
 				  Ref.HashKey,
 				  NiceBytes(Body.Size()),
 				  ToString(ContentType),
 				  TotalCount,
-				  ValidAttachments.size());
+				  ValidAttachments.size(),
+				  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 
 		Body.SetContentType(ZenContentType::kCbObject);
 		m_CacheStore.Put(Ref.Namespace, Ref.BucketSegment, Ref.HashKey, {.Value = Body});
@@ -839,7 +865,11 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 
 		if (!Package.TryLoad(Body))
 		{
-			ZEN_WARN("PUT - '{}/{}/{}' '{}' FAILED, invalid package", Ref.Namespace, Ref.BucketSegment, Ref.HashKey, ToString(ContentType));
+			ZEN_WARN("PUTCACHERECORD - '{}/{}/{}' '{}' FAILED, invalid package",
+					 Ref.Namespace,
+					 Ref.BucketSegment,
+					 Ref.HashKey,
+					 ToString(ContentType));
 			return Request.WriteResponse(HttpResponseCode::BadRequest, HttpContentType::kText, "Invalid package"sv);
 		}
 		CachePolicy Policy = PolicyFromUrl;
@@ -869,7 +899,7 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 				}
 				else
 				{
-					ZEN_WARN("PUT - '{}/{}/{}' '{}' FAILED, attachment '{}' is not compressed",
+					ZEN_WARN("PUTCACHERECORD - '{}/{}/{}' '{}' FAILED, attachment '{}' is not compressed",
 							 Ref.Namespace,
 							 Ref.BucketSegment,
 							 Ref.HashKey,
@@ -891,7 +921,7 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 			return Request.WriteResponse(HttpResponseCode::BadRequest, HttpContentType::kText, "Invalid attachment(s)"sv);
 		}
 
-		ZEN_DEBUG("PUT - '{}/{}/{}' {} '{}', attachments '{}/{}/{}' (new/valid/total)",
+		ZEN_DEBUG("PUTCACHERECORD - '{}/{}/{}' {} '{}', attachments '{}/{}/{}' (new/valid/total) in {}",
 				  Ref.Namespace,
 				  Ref.BucketSegment,
 				  Ref.HashKey,
@@ -899,7 +929,8 @@ HttpStructuredCacheService::HandlePutCacheRecord(zen::HttpServerRequest& Request
 				  ToString(ContentType),
 				  Count.New,
 				  Count.Valid,
-				  Count.Total);
+				  Count.Total,
+				  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 
 		ZenCacheValue CacheValue;
 		CacheValue.Value = CacheRecord.GetBuffer().AsIoBuffer();
@@ -947,21 +978,22 @@ HttpStructuredCacheService::HandleGetCacheChunk(zen::HttpServerRequest& Request,
 {
 	Stopwatch Timer;
 
-	IoBuffer	Value			= m_CidStore.FindChunkByCid(Ref.ValueContentId);
-	bool		InUpstreamCache = false;
-	CachePolicy Policy			= PolicyFromUrl;
+	IoBuffer					Value  = m_CidStore.FindChunkByCid(Ref.ValueContentId);
+	const UpstreamEndpointInfo* Source = nullptr;
+	CachePolicy					Policy = PolicyFromUrl;
 	{
 		const bool QueryUpstream = !Value && EnumHasAllFlags(Policy, CachePolicy::QueryRemote);
 
 		if (QueryUpstream)
 		{
-			if (auto UpstreamResult = m_UpstreamCache.GetCacheChunk(Ref.Namespace, {Ref.BucketSegment, Ref.HashKey}, Ref.ValueContentId);
-				UpstreamResult.Success)
+			if (GetUpstreamCacheSingleResult UpstreamResult =
+					m_UpstreamCache.GetCacheChunk(Ref.Namespace, {Ref.BucketSegment, Ref.HashKey}, Ref.ValueContentId);
+				UpstreamResult.Status.Success)
 			{
 				if (CompressedBuffer Compressed = CompressedBuffer::FromCompressed(SharedBuffer(UpstreamResult.Value)))
 				{
 					m_CidStore.AddChunk(Compressed);
-					InUpstreamCache = true;
+					Source = UpstreamResult.Source;
 				}
 				else
 				{
@@ -973,7 +1005,7 @@ HttpStructuredCacheService::HandleGetCacheChunk(zen::HttpServerRequest& Request,
 
 	if (!Value)
 	{
-		ZEN_DEBUG("MISS - '{}/{}/{}/{}' '{}' in {}",
+		ZEN_DEBUG("GETCACHECHUNK MISS - '{}/{}/{}/{}' '{}' in {}",
 				  Ref.Namespace,
 				  Ref.BucketSegment,
 				  Ref.HashKey,
@@ -984,18 +1016,18 @@ HttpStructuredCacheService::HandleGetCacheChunk(zen::HttpServerRequest& Request,
 		return Request.WriteResponse(HttpResponseCode::NotFound);
 	}
 
-	ZEN_DEBUG("HIT - '{}/{}/{}/{}' {} '{}' ({}) in {}",
+	ZEN_DEBUG("GETCACHECHUNK HIT - '{}/{}/{}/{}' {} '{}' ({}) in {}",
 			  Ref.Namespace,
 			  Ref.BucketSegment,
 			  Ref.HashKey,
 			  Ref.ValueContentId,
 			  NiceBytes(Value.Size()),
 			  ToString(Value.GetContentType()),
-			  InUpstreamCache ? "UPSTREAM" : "LOCAL",
+			  Source ? Source->Url : "LOCAL"sv,
 			  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 
 	m_CacheStats.HitCount++;
-	if (InUpstreamCache)
+	if (Source)
 	{
 		m_CacheStats.UpstreamHitCount++;
 	}
@@ -1043,7 +1075,7 @@ HttpStructuredCacheService::HandlePutCacheChunk(zen::HttpServerRequest& Request,
 
 	CidStore::InsertResult Result = m_CidStore.AddChunk(Compressed);
 
-	ZEN_DEBUG("PUT - '{}/{}/{}/{}' {} '{}' ({}) in {}",
+	ZEN_DEBUG("PUTCACHECHUNK - '{}/{}/{}/{}' {} '{}' ({}) in {}",
 			  Ref.Namespace,
 			  Ref.BucketSegment,
 			  Ref.HashKey,
@@ -1196,6 +1228,8 @@ HttpStructuredCacheService::PutCacheRecord(PutRequestData& Request, const CbPack
 	uint64_t			RecordObjectSize = Record.GetSize();
 	uint64_t			TransferredSize	 = RecordObjectSize;
 
+	Stopwatch Timer;
+
 	Request.RecordObject.IterateAttachments([this, &Request, Package, &ValidAttachments, &Count, &TransferredSize](CbFieldView HashView) {
 		const IoHash ValueHash = HashView.AsHash();
 		if (const CbAttachment* Attachment = Package ? Package->FindAttachment(ValueHash) : nullptr)
@@ -1216,7 +1250,7 @@ HttpStructuredCacheService::PutCacheRecord(PutRequestData& Request, const CbPack
 			}
 			else
 			{
-				ZEN_WARN("PUT - '{}/{}/{}' '{}' FAILED, attachment '{}' is not compressed",
+				ZEN_WARN("PUTCACEHRECORD - '{}/{}/{}' '{}' FAILED, attachment '{}' is not compressed",
 						 Request.Namespace,
 						 Request.Key.Bucket,
 						 Request.Key.Hash,
@@ -1238,14 +1272,15 @@ HttpStructuredCacheService::PutCacheRecord(PutRequestData& Request, const CbPack
 		return PutResult::Invalid;
 	}
 
-	ZEN_DEBUG("PUT - '{}/{}/{}' {}, attachments '{}/{}/{}' (new/valid/total)",
+	ZEN_DEBUG("PUTCACEHRECORD - '{}/{}/{}' {}, attachments '{}/{}/{}' (new/valid/total) in {}",
 			  Request.Namespace,
 			  Request.Key.Bucket,
 			  Request.Key.Hash,
 			  NiceBytes(TransferredSize),
 			  Count.New,
 			  Count.Valid,
-			  Count.Total);
+			  Count.Total,
+			  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 
 	ZenCacheValue CacheValue;
 	CacheValue.Value = IoBuffer(Record.GetSize());
@@ -1289,8 +1324,9 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 		IoBuffer					  RecordCacheValue;
 		CacheRecordPolicy			  DownstreamPolicy;
 		std::vector<ValueRequestData> Values;
-		bool						  Complete	   = false;
-		bool						  UsedUpstream = false;
+		bool						  Complete = false;
+		const UpstreamEndpointInfo*	  Source   = nullptr;
+		uint64_t					  ElapsedTimeUs;
 	};
 
 	std::string_view		   PolicyText	 = Params["DefaultPolicy"sv].AsString();
@@ -1324,6 +1360,7 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 
 	for (CbFieldView RequestField : RequestsArray)
 	{
+		Stopwatch		   Timer;
 		RecordRequestData& Request		 = Requests.emplace_back();
 		CbObjectView	   RequestObject = RequestField.AsObjectView();
 		CbObjectView	   KeyObject	 = RequestObject["Key"sv].AsObjectView();
@@ -1420,6 +1457,7 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 				UpstreamIndexes.push_back(Requests.size() - 1);
 			}
 		}
+		Request.ElapsedTimeUs = Timer.GetElapsedTimeUs();
 	}
 	if (Requests.empty())
 	{
@@ -1465,7 +1503,10 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 
 			RecordRequestData& Request =
 				*reinterpret_cast<RecordRequestData*>(reinterpret_cast<char*>(&Params.Request) - offsetof(RecordRequestData, Upstream));
+			Request.ElapsedTimeUs += static_cast<uint64_t>(Params.ElapsedSeconds * 1000000.0);
 			const CacheKey& Key = Request.Upstream.Key;
+			Stopwatch		Timer;
+			auto			TimeGuard = MakeGuard([&Timer, &Request]() { Request.ElapsedTimeUs += Timer.GetElapsedTimeUs(); });
 			if (!Request.RecordObject)
 			{
 				CbObject ObjectBuffer	 = CbObject::Clone(Params.Record);
@@ -1477,7 +1518,7 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 					m_CacheStore.Put(*Namespace, Key.Bucket, Key.Hash, {.Value = {Request.RecordCacheValue}});
 				}
 				ParseValues(Request);
-				Request.UsedUpstream = true;
+				Request.Source = Params.Source;
 			}
 
 			Request.Complete = true;
@@ -1499,8 +1540,8 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 					{
 						if (CompressedBuffer Compressed = Attachment->AsCompressedBinary())
 						{
-							Request.UsedUpstream = true;
-							Value.Exists		 = true;
+							Request.Source = Params.Source;
+							Value.Exists   = true;
 							if (EnumHasAllFlags(ValuePolicy, CachePolicy::StoreLocal))
 							{
 								m_CidStore.AddChunk(Compressed);
@@ -1528,6 +1569,7 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 					// didn't exist and we will not get here. In the PartialRecord==true case, we do not need to inform the client of
 					// any missing SkipData attachments.
 				}
+				Request.ElapsedTimeUs += Timer.GetElapsedTimeUs();
 			}
 		};
 
@@ -1553,15 +1595,16 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 				}
 			}
 
-			ZEN_DEBUG("HIT - '{}/{}/{}' {}{}{}",
+			ZEN_DEBUG("GETCACHERECORD HIT - '{}/{}/{}' {}{} ({}) in {}",
 					  *Namespace,
 					  Key.Bucket,
 					  Key.Hash,
 					  NiceBytes(Request.RecordCacheValue.Size()),
 					  Request.Complete ? ""sv : " (PARTIAL)"sv,
-					  Request.UsedUpstream ? " (UPSTREAM)"sv : ""sv);
+					  Request.Source ? Request.Source->Url : "LOCAL"sv,
+					  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
 			m_CacheStats.HitCount++;
-			m_CacheStats.UpstreamHitCount += Request.UsedUpstream ? 1 : 0;
+			m_CacheStats.UpstreamHitCount += Request.Source ? 1 : 0;
 		}
 		else
 		{
@@ -1570,11 +1613,21 @@ HttpStructuredCacheService::HandleRpcGetCacheRecords(zen::HttpServerRequest& Htt
 			if (!EnumHasAnyFlags(Request.DownstreamPolicy.GetRecordPolicy(), CachePolicy::Query))
 			{
 				// If they requested no query, do not record this as a miss
-				ZEN_DEBUG("DISABLEDQUERY - '{}/{}/{}'", *Namespace, Key.Bucket, Key.Hash);
+				ZEN_DEBUG("GETCACHERECORD DISABLEDQUERY - '{}/{}/{}' in {}",
+						  *Namespace,
+						  Key.Bucket,
+						  Key.Hash,
+						  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
 			}
 			else
 			{
-				ZEN_DEBUG("MISS - '{}/{}/{}' {}", *Namespace, Key.Bucket, Key.Hash, Request.RecordObject ? ""sv : "(PARTIAL)"sv);
+				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++;
 			}
 		}
@@ -1610,6 +1663,8 @@ HttpStructuredCacheService::HandleRpcPutCacheValues(zen::HttpServerRequest& Requ
 	std::vector<bool> Results;
 	for (CbFieldView RequestField : Params["Requests"sv])
 	{
+		Stopwatch Timer;
+
 		CbObjectView RequestObject = RequestField.AsObjectView();
 		CbObjectView KeyView	   = RequestObject["Key"sv].AsObjectView();
 
@@ -1669,12 +1724,13 @@ HttpStructuredCacheService::HandleRpcPutCacheValues(zen::HttpServerRequest& Requ
 			m_UpstreamCache.EnqueueUpstream({.Type = ZenContentType::kCompressedBinary, .Namespace = *Namespace, .Key = Key});
 		}
 		Results.push_back(Succeeded);
-		ZEN_DEBUG("PUTCACHEVALUES - '{}/{}/{}' {}, '{}'",
+		ZEN_DEBUG("PUTCACHEVALUES - '{}/{}/{}' {}, '{}' in {}",
 				  *Namespace,
 				  Key.Bucket,
 				  Key.Hash,
 				  NiceBytes(TransferredSize),
-				  Succeeded ? "Added"sv : "Invalid");
+				  Succeeded ? "Added"sv : "Invalid",
+				  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 	}
 	if (Results.empty())
 	{
@@ -1834,7 +1890,7 @@ HttpStructuredCacheService::HandleRpcGetCacheValues(zen::HttpServerRequest& Http
 								  ChunkRequest.Key.Bucket,
 								  ChunkRequest.Key.Hash,
 								  NiceBytes(Request.Result.GetCompressed().GetSize()),
-								  "UPSTREAM"sv,
+								  Params.Source ? Params.Source->Url : "UPSTREAM",
 								  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 						m_CacheStats.HitCount++;
 						m_CacheStats.UpstreamHitCount++;
@@ -1845,7 +1901,7 @@ HttpStructuredCacheService::HandleRpcGetCacheValues(zen::HttpServerRequest& Http
 						  *Namespace,
 						  ChunkRequest.Key.Bucket,
 						  ChunkRequest.Key.Hash,
-						  "UPSTREAM"sv,
+						  Params.Source ? Params.Source->Url : "UPSTREAM",
 						  NiceLatencyNs(Timer.GetElapsedTimeUs() * 1000));
 				m_CacheStats.MissCount++;
 			});
@@ -1906,27 +1962,28 @@ namespace cache::detail {
 	};
 	struct RecordBody
 	{
-		IoBuffer				 CacheValue;
-		std::vector<RecordValue> Values;
-		std::string_view		 Source;
-		CachePolicy				 DownstreamPolicy;
-		bool					 Exists		= false;
-		bool					 HasRequest = false;
-		bool					 ValuesRead = false;
+		IoBuffer					CacheValue;
+		std::vector<RecordValue>	Values;
+		const UpstreamEndpointInfo* Source = nullptr;
+		CachePolicy					DownstreamPolicy;
+		bool						Exists	   = false;
+		bool						HasRequest = false;
+		bool						ValuesRead = false;
 	};
 	struct ChunkRequest
 	{
-		CacheChunkRequest* Key	  = nullptr;
-		RecordBody*		   Record = nullptr;
-		CompressedBuffer   Value;
-		std::string_view   Source;
-		uint64_t		   TotalSize	   = 0;
-		uint64_t		   RequestedSize   = 0;
-		uint64_t		   RequestedOffset = 0;
-		CachePolicy		   DownstreamPolicy;
-		bool			   Exists		   = false;
-		bool			   TotalSizeKnown  = false;
-		bool			   IsRecordRequest = false;
+		CacheChunkRequest*			Key	   = nullptr;
+		RecordBody*					Record = nullptr;
+		CompressedBuffer			Value;
+		const UpstreamEndpointInfo* Source			= nullptr;
+		uint64_t					TotalSize		= 0;
+		uint64_t					RequestedSize	= 0;
+		uint64_t					RequestedOffset = 0;
+		CachePolicy					DownstreamPolicy;
+		bool						Exists			= false;
+		bool						TotalSizeKnown	= false;
+		bool						IsRecordRequest = false;
+		uint64_t					ElapsedTimeUs	= 0;
 	};
 
 }  // namespace cache::detail
@@ -2092,6 +2149,7 @@ HttpStructuredCacheService::GetLocalCacheRecords(std::string_view							Namespac
 	std::vector<CacheKeyRequest*> UpstreamRecordRequests;
 	for (size_t RecordIndex = 0; RecordIndex < Records.size(); ++RecordIndex)
 	{
+		Stopwatch		 Timer;
 		CacheKeyRequest& RecordKey = RecordKeys[RecordIndex];
 		RecordBody&		 Record	   = Records[RecordIndex];
 		if (Record.HasRequest)
@@ -2105,7 +2163,6 @@ HttpStructuredCacheService::GetLocalCacheRecords(std::string_view							Namespac
 				{
 					Record.Exists	  = true;
 					Record.CacheValue = std::move(CacheValue.Value);
-					Record.Source	  = "LOCAL"sv;
 				}
 			}
 			if (!Record.Exists && EnumHasAllFlags(Record.DownstreamPolicy, CachePolicy::QueryRemote))
@@ -2113,38 +2170,42 @@ HttpStructuredCacheService::GetLocalCacheRecords(std::string_view							Namespac
 				RecordKey.Policy = CacheRecordPolicy(ConvertToUpstream(Record.DownstreamPolicy));
 				UpstreamRecordRequests.push_back(&RecordKey);
 			}
+			RecordRequests[RecordIndex]->ElapsedTimeUs += Timer.GetElapsedTimeUs();
 		}
 	}
 
 	if (!UpstreamRecordRequests.empty())
 	{
-		const auto OnCacheRecordGetComplete = [this, Namespace, &RecordKeys, &Records](CacheRecordGetCompleteParams&& Params) {
-			if (!Params.Record)
-			{
-				return;
-			}
-			CacheKeyRequest& RecordKey	 = Params.Request;
-			size_t			 RecordIndex = std::distance(RecordKeys.data(), &RecordKey);
-			RecordBody&		 Record		 = Records[RecordIndex];
-
-			const CacheKey& Key	  = RecordKey.Key;
-			Record.Exists		  = true;
-			CbObject ObjectBuffer = CbObject::Clone(Params.Record);
-			Record.CacheValue	  = ObjectBuffer.GetBuffer().AsIoBuffer();
-			Record.CacheValue.SetContentType(ZenContentType::kCbObject);
-			Record.Source = "UPSTREAM"sv;
-
-			if (EnumHasAllFlags(Record.DownstreamPolicy, CachePolicy::StoreLocal))
-			{
-				m_CacheStore.Put(Namespace, Key.Bucket, Key.Hash, {.Value = Record.CacheValue});
-			}
-		};
+		const auto OnCacheRecordGetComplete =
+			[this, Namespace, &RecordKeys, &Records, &RecordRequests](CacheRecordGetCompleteParams&& Params) {
+				if (!Params.Record)
+				{
+					return;
+				}
+				CacheKeyRequest& RecordKey	 = Params.Request;
+				size_t			 RecordIndex = std::distance(RecordKeys.data(), &RecordKey);
+				RecordRequests[RecordIndex]->ElapsedTimeUs += static_cast<uint64_t>(Params.ElapsedSeconds * 1000000.0);
+				RecordBody& Record = Records[RecordIndex];
+
+				const CacheKey& Key	  = RecordKey.Key;
+				Record.Exists		  = true;
+				CbObject ObjectBuffer = CbObject::Clone(Params.Record);
+				Record.CacheValue	  = ObjectBuffer.GetBuffer().AsIoBuffer();
+				Record.CacheValue.SetContentType(ZenContentType::kCbObject);
+				Record.Source = Params.Source;
+
+				if (EnumHasAllFlags(Record.DownstreamPolicy, CachePolicy::StoreLocal))
+				{
+					m_CacheStore.Put(Namespace, Key.Bucket, Key.Hash, {.Value = Record.CacheValue});
+				}
+			};
 		m_UpstreamCache.GetCacheRecords(Namespace, UpstreamRecordRequests, std::move(OnCacheRecordGetComplete));
 	}
 
 	std::vector<CacheChunkRequest*> UpstreamPayloadRequests;
 	for (ChunkRequest* Request : RecordRequests)
 	{
+		Stopwatch Timer;
 		if (Request->Key->ChunkId == IoHash::Zero)
 		{
 			// Unreal uses a 12 byte ID to address cache record values. When the uncompressed hash (ChunkId)
@@ -2194,7 +2255,6 @@ HttpStructuredCacheService::GetLocalCacheRecords(std::string_view							Namespac
 					if (m_CidStore.ContainsChunk(Request->Key->ChunkId))
 					{
 						Request->Exists = true;
-						Request->Source = "LOCAL"sv;
 					}
 				}
 				else if (IoBuffer Payload = m_CidStore.FindChunkByCid(Request->Key->ChunkId))
@@ -2209,7 +2269,6 @@ HttpStructuredCacheService::GetLocalCacheRecords(std::string_view							Namespac
 						Request->Exists			= true;
 						Request->TotalSize		= Compressed.GetRawSize();
 						Request->TotalSizeKnown = true;
-						Request->Source			= "LOCAL"sv;
 					}
 				}
 			}
@@ -2219,6 +2278,7 @@ HttpStructuredCacheService::GetLocalCacheRecords(std::string_view							Namespac
 				OutUpstreamChunks.push_back(Request->Key);
 			}
 		}
+		Request->ElapsedTimeUs += Timer.GetElapsedTimeUs();
 	}
 }
 
@@ -2231,6 +2291,7 @@ HttpStructuredCacheService::GetLocalCacheValues(std::string_view						   Namespa
 
 	for (ChunkRequest* Request : ValueRequests)
 	{
+		Stopwatch Timer;
 		if (!Request->Exists && EnumHasAllFlags(Request->DownstreamPolicy, CachePolicy::QueryLocal))
 		{
 			ZenCacheValue CacheValue;
@@ -2249,7 +2310,6 @@ HttpStructuredCacheService::GetLocalCacheValues(std::string_view						   Namespa
 						Request->Exists			= true;
 						Request->TotalSize		= Result.GetRawSize();
 						Request->TotalSizeKnown = true;
-						Request->Source			= "LOCAL"sv;
 					}
 				}
 			}
@@ -2264,6 +2324,7 @@ HttpStructuredCacheService::GetLocalCacheValues(std::string_view						   Namespa
 			}
 			OutUpstreamChunks.push_back(Request->Key);
 		}
+		Request->ElapsedTimeUs += Timer.GetElapsedTimeUs();
 	}
 }
 
@@ -2286,6 +2347,7 @@ HttpStructuredCacheService::GetUpstreamCacheChunks(std::string_view							 Names
 			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))
 			{
@@ -2316,7 +2378,7 @@ HttpStructuredCacheService::GetUpstreamCacheChunks(std::string_view							 Names
 			Request.Exists		   = true;
 			Request.TotalSize	   = Params.RawSize;
 			Request.TotalSizeKnown = true;
-			Request.Source		   = "UPSTREAM"sv;
+			Request.Source		   = Params.Source;
 
 			m_CacheStats.UpstreamHitCount++;
 		};
@@ -2352,23 +2414,34 @@ HttpStructuredCacheService::WriteGetCacheChunksResponse(std::string_view
 					Writer.AddInteger("RawSize"sv, Request.TotalSize);
 				}
 
-				ZEN_DEBUG("HIT - '{}/{}/{}/{}' {} '{}' ({})",
+				ZEN_DEBUG("GETCACHECHUNKS HIT - '{}/{}/{}/{}' {} '{}' ({}) in {}",
 						  Namespace,
 						  Request.Key->Key.Bucket,
 						  Request.Key->Key.Hash,
 						  Request.Key->ValueId,
 						  NiceBytes(Request.TotalSize),
 						  Request.IsRecordRequest ? "Record"sv : "Value"sv,
-						  Request.Source);
+						  Request.Source ? Request.Source->Url : "LOCAL"sv,
+						  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
 				m_CacheStats.HitCount++;
 			}
 			else if (!EnumHasAnyFlags(Request.DownstreamPolicy, CachePolicy::Query))
 			{
-				ZEN_DEBUG("SKIP - '{}/{}/{}/{}'", Namespace, Request.Key->Key.Bucket, Request.Key->Key.Hash, Request.Key->ValueId);
+				ZEN_DEBUG("GETCACHECHUNKS DISABLEDQUERY - '{}/{}/{}/{}' in {}",
+						  Namespace,
+						  Request.Key->Key.Bucket,
+						  Request.Key->Key.Hash,
+						  Request.Key->ValueId,
+						  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
 			}
 			else
 			{
-				ZEN_DEBUG("MISS - '{}/{}/{}/{}'", Namespace, Request.Key->Key.Bucket, Request.Key->Key.Hash, Request.Key->ValueId);
+				ZEN_DEBUG("GETCACHECHUNKS MISS - '{}/{}/{}/{}' in {}",
+						  Namespace,
+						  Request.Key->Key.Bucket,
+						  Request.Key->Key.Hash,
+						  Request.Key->ValueId,
+						  NiceLatencyNs(Request.ElapsedTimeUs * 1000));
 				m_CacheStats.MissCount++;
 			}
 		}