From 050b61eee042dd23cfb8ad1744f876ec00932198 Mon Sep 17 00:00:00 2001 From: Dan Engelbrecht Date: Thu, 22 Sep 2022 23:59:56 +0200 Subject: De/more upstream details (#168) * 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 --- zenserver/cache/structuredcache.cpp | 259 +++++++++++++++++++++++------------- 1 file changed, 166 insertions(+), 93 deletions(-) (limited to 'zenserver/cache/structuredcache.cpp') 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 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(reinterpret_cast(&Params.Request) - offsetof(RecordRequestData, Upstream)); + Request.ElapsedTimeUs += static_cast(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 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 Values; - std::string_view Source; - CachePolicy DownstreamPolicy; - bool Exists = false; - bool HasRequest = false; - bool ValuesRead = false; + IoBuffer CacheValue; + std::vector 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 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(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 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(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++; } } -- cgit v1.2.3