From 92c0ed1a2be46841c910558819e6e290965eff8c Mon Sep 17 00:00:00 2001 From: Vlad Kuznecov Date: Wed, 11 Sep 2024 09:26:54 +0000 Subject: [PATCH 1/2] Add mode LWTRACK probes to improve introspection of PDisk --- .../lwtrace_probes/blobstorage_probes.h | 8 +++++++- .../pdisk/blobstorage_pdisk_impl.cpp | 19 ++++++++++--------- .../pdisk/blobstorage_pdisk_impl.h | 2 ++ .../pdisk/blobstorage_pdisk_impl_log.cpp | 5 ++++- 4 files changed, 23 insertions(+), 11 deletions(-) diff --git a/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h b/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h index a702d91489d5..881e1d4a6375 100644 --- a/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h +++ b/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h @@ -261,11 +261,17 @@ struct TEventTypeField { TYPES(ui32, ui64, ui64), \ NAMES("chunkIdx", "size", "offset")) \ PROBE(PDiskUpdateCycleDetails, GROUPS("PDisk"), \ - TYPES(ui32, float, float, float, float, float), \ + TYPES(ui64, float, float, float, float, float), \ NAMES("pdisk", "entireUpdateMs", "inputQueueMs", "schedulingMs", "processingMs", "waitingMs")) \ PROBE(PDiskEnqueueAllDetails, GROUPS("PDisk"), \ TYPES(ui64, size_t, size_t, size_t, double), \ NAMES("pdisk", "initialQueueSize", "processedReqs", "pushedToForsetiReqs", "spentTimeMs")) \ + PROBE(PDiskUpdateStarted, GROUPS("PDisk"), TYPES(ui64), NAMES("pdisk")) \ + PROBE(PDiskProcessLogWriteQueue, GROUPS("PDisk"), TYPES(ui64, size_t, size_t), NAMES("pdisk", "logQueueSize", "commitQueueSize")) \ + PROBE(PDiskProcessChunkReadQueue, GROUPS("PDisk"), TYPES(ui64, size_t), NAMES("pdisk", "queueSize")) \ + PROBE(PDiskProcessChunkWriteQueue, GROUPS("PDisk"), TYPES(ui64, size_t), NAMES("pdisk", "queueSize")) \ + PROBE(PDiskStartWaiting, GROUPS("PDisk"), TYPES(ui64), NAMES("pdisk")) \ + PROBE(PDiskUpdateEnded, GROUPS("PDisk"), TYPES(ui64), NAMES("pdisk")) \ PROBE(DSProxyGetEnqueue, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \ PROBE(DSProxyGetBootstrap, GROUPS("DSProxy"), TYPES(), NAMES()) \ PROBE(DSProxyGetHandle, GROUPS("DSProxy", "LWTrackStart"), TYPES(), NAMES()) \ diff --git a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp index 11fb7b0ba41d..73d72ee29f55 100644 --- a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp +++ b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp @@ -2240,14 +2240,11 @@ void TPDisk::ProcessChunkWriteQueue() { Y_FAIL_S("Unexpected request type# " << ui64(req->GetType()) << " in JointChunkWrites"); } } + LWTRACK(PDiskProcessChunkWriteQueue, UpdateCycleOrbit, PCtx->PDiskId, JointChunkWrites.size()); JointChunkWrites.clear(); } void TPDisk::ProcessChunkReadQueue() { - if (JointChunkReads.empty()) { - return; - } - NHPTimer::STime now = HPNow(); // Size (bytes) of elementary sectors block, it is useless to read/write less than that blockSize ui64 bufferSize = BufferPool->GetBufferSize() / Format.SectorSize * Format.SectorSize; @@ -2298,6 +2295,7 @@ void TPDisk::ProcessChunkReadQueue() { Y_FAIL_S("Unexpected request type# " << ui64(req->GetType()) << " in JointChunkReads"); } } + LWTRACK(PDiskProcessChunkReadQueue, UpdateCycleOrbit, PCtx->PDiskId, JointChunkReads.size()); JointChunkReads.clear(); } @@ -3394,14 +3392,13 @@ void TPDisk::ProcessYardInitSet() { } void TPDisk::EnqueueAll() { - TInstant start = TInstant::Now(); + auto start = TMonitonic::Now(); TGuard guard(StateMutex); size_t initialQueueSize = InputQueue.GetWaitingSize(); size_t processedReqs = 0; size_t pushedToForsetiReqs = 0; - while (InputQueue.GetWaitingSize() > 0) { TRequestBase* request = InputQueue.Pop(); AtomicSub(InputQueueCost, request->Cost); @@ -3454,11 +3451,12 @@ void TPDisk::EnqueueAll() { } double spentTimeMs = (TInstant::Now() - start).MillisecondsFloat(); - LWPROBE(PDiskEnqueueAllDetails, PCtx->PDiskId, initialQueueSize, processedReqs, pushedToForsetiReqs, spentTimeMs); + LWPROBE(PDiskEnqueueAllDetails, UpdateCycleOrbit, PCtx->PDiskId, initialQueueSize, processedReqs, pushedToForsetiReqs, spentTimeMs); } void TPDisk::Update() { Mon.UpdateDurationTracker.UpdateStarted(); + LWTRACK(PDiskUpdateStarted, UpdateCycleOrbit, PCtx->PDiskId); // ui32 userSectorSize = 0; @@ -3554,9 +3552,9 @@ void TPDisk::Update() { } } ui64 totalCost = totalLogCost + totalNonLogCost; - LWPROBE(PDiskForsetiCycle, PCtx->PDiskId, nowCycles, prevForsetiTimeNs, ForsetiPrevTimeNs, timeCorrection, + LWTRACK(PDiskForsetiCycle, UpdateCycleOrbit, PCtx->PDiskId, nowCycles, prevForsetiTimeNs, ForsetiPrevTimeNs, timeCorrection, realDuration, virtualDuration, ForsetiTimeNs, totalCost, virtualDeadline); - LWPROBE(PDiskMilliBatchSize, PCtx->PDiskId, totalLogCost, totalNonLogCost, totalLogReqs, totalNonLogReqs); + LWTRACK(PDiskMilliBatchSize, UpdateCycleOrbit, PCtx->PDiskId, totalLogCost, totalNonLogCost, totalLogReqs, totalNonLogReqs); ForsetiRealTimeCycles = nowCycles; @@ -3636,6 +3634,7 @@ void TPDisk::Update() { Mon.UpdateDurationTracker.WaitingStart(isNothingToDo); + LWTRACK(PDiskStartWaiting, UpdateCycleOrbit, PCtx->PDiskId); if (Cfg->SectorMap) { auto diskModeParams = Cfg->SectorMap->GetDiskModeParams(); @@ -3668,6 +3667,8 @@ void TPDisk::Update() { InputQueue.ProducedWait(TDuration::MilliSeconds(10)); } + LWTRACK(PDiskUpdateEnded, UpdateCycleOrbit, PCtx->PDiskId); + UpdateCycleOrbit.Reset(); Mon.UpdateDurationTracker.UpdateEnded(); *Mon.PDiskThreadCPU = ThreadCPUTime(); } diff --git a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.h b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.h index 9359e8521e52..3f789bae5475 100644 --- a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.h +++ b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.h @@ -201,6 +201,8 @@ class TPDisk : public IPDisk { // Metadata storage NMeta::TInfo Meta; + NLWTrace::TOrbit UpdateCycleOrbit; + //////////////////////////////////////////////////////////////////////////////////////////////////////////////////// // Initialization TPDisk(std::shared_ptr pCtx, const TIntrusivePtr cfg, const TIntrusivePtr<::NMonitoring::TDynamicCounters>& counters); diff --git a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl_log.cpp b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl_log.cpp index bb0df0e95b6d..de5e5f087e5f 100644 --- a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl_log.cpp +++ b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl_log.cpp @@ -707,8 +707,10 @@ void TPDisk::WriteSysLogRestorePoint(TCompletionAction *action, TReqId reqId, NW // Common log writing //////////////////////////////////////////////////////////////////////////////////////////////////////////////////// void TPDisk::ProcessLogWriteQueueAndCommits() { - if (JointLogWrites.empty()) + if (JointLogWrites.empty()) { + LWTRACK(PDiskProcessLogWriteQueue, UpdateCycleOrbit, PCtx->PDiskId, JointLogWrites.size(), JointCommits.size()); return; + } NHPTimer::STime now = HPNow(); for (TLogWrite *logCommit : JointCommits) { @@ -748,6 +750,7 @@ void TPDisk::ProcessLogWriteQueueAndCommits() { double(logWrite->Cost) / 1000000.0, HPSecondsFloat(logWrite->Deadline), logWrite->Owner, logWrite->IsFast, logWrite->PriorityClass); } + LWTRACK(PDiskProcessLogWriteQueue, UpdateCycleOrbit, PCtx->PDiskId, JointLogWrites.size(), JointCommits.size()); TReqId reqId = JointLogWrites.back()->ReqId; auto write = MakeHolder( this, std::move(JointLogWrites), std::move(JointCommits), std::move(logChunksToCommit)); From 2432b32ce3f4008212d29acc918d888d6ff305d4 Mon Sep 17 00:00:00 2001 From: Vlad Kuznecov Date: Wed, 11 Sep 2024 09:26:54 +0000 Subject: [PATCH 2/2] Add mode LWTRACK probes to improve introspection of PDisk --- ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h | 2 +- ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp | 6 +++--- 2 files changed, 4 insertions(+), 4 deletions(-) diff --git a/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h b/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h index 881e1d4a6375..db27e07eab42 100644 --- a/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h +++ b/ydb/core/blobstorage/lwtrace_probes/blobstorage_probes.h @@ -261,7 +261,7 @@ struct TEventTypeField { TYPES(ui32, ui64, ui64), \ NAMES("chunkIdx", "size", "offset")) \ PROBE(PDiskUpdateCycleDetails, GROUPS("PDisk"), \ - TYPES(ui64, float, float, float, float, float), \ + TYPES(ui32, float, float, float, float, float), \ NAMES("pdisk", "entireUpdateMs", "inputQueueMs", "schedulingMs", "processingMs", "waitingMs")) \ PROBE(PDiskEnqueueAllDetails, GROUPS("PDisk"), \ TYPES(ui64, size_t, size_t, size_t, double), \ diff --git a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp index 73d72ee29f55..f7863c7d202d 100644 --- a/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp +++ b/ydb/core/blobstorage/pdisk/blobstorage_pdisk_impl.cpp @@ -3392,7 +3392,7 @@ void TPDisk::ProcessYardInitSet() { } void TPDisk::EnqueueAll() { - auto start = TMonitonic::Now(); + auto start = TMonotonic::Now(); TGuard guard(StateMutex); size_t initialQueueSize = InputQueue.GetWaitingSize(); @@ -3450,8 +3450,8 @@ void TPDisk::EnqueueAll() { } } - double spentTimeMs = (TInstant::Now() - start).MillisecondsFloat(); - LWPROBE(PDiskEnqueueAllDetails, UpdateCycleOrbit, PCtx->PDiskId, initialQueueSize, processedReqs, pushedToForsetiReqs, spentTimeMs); + double spentTimeMs = (TMonotonic::Now() - start).MillisecondsFloat(); + LWTRACK(PDiskEnqueueAllDetails, UpdateCycleOrbit, PCtx->PDiskId, initialQueueSize, processedReqs, pushedToForsetiReqs, spentTimeMs); } void TPDisk::Update() {