From ddda820591e69acda3c393f6098e43e7591673c4 Mon Sep 17 00:00:00 2001 From: Pratik Mankawde <3397372+pratikmankawde@users.noreply.github.com> Date: Fri, 14 Aug 2026 21:44:19 +0100 Subject: [PATCH] fix(perflog): record OTel metrics outside the counter locks rpcStart, jobQueue, jobStart and jobFinish each acquired a lock without braces, so it stayed held to the end of the function and covered the OTel recording calls this branch added. counters_.jobsMutex and counters_.methodsMutex are process-wide, so every worker thread starting or finishing a job serialised on the SDK's work. That work is not a bare atomic add: each record builds a map-backed attribute set and takes a spin lock inside the SDK, whose backoff reaches a millisecond-scale sleep under contention. Brace the lock plus the state it guards, then record after it releases. None of the metric calls read lock-protected state, so this is semantics-preserving, and rpcEnd() in the same file already had this shape. --- src/xrpld/perflog/detail/PerfLogImp.cpp | 44 +++++++++++++++++-------- 1 file changed, 30 insertions(+), 14 deletions(-) diff --git a/src/xrpld/perflog/detail/PerfLogImp.cpp b/src/xrpld/perflog/detail/PerfLogImp.cpp index f43464dd1d..106c36f157 100644 --- a/src/xrpld/perflog/detail/PerfLogImp.cpp +++ b/src/xrpld/perflog/detail/PerfLogImp.cpp @@ -331,10 +331,15 @@ PerfLogImp::rpcStart(std::string const& method, std::uint64_t const requestId) std::scoped_lock const lock(counter->second.mutex); ++counter->second.value.started; } - std::scoped_lock const lock(counters_.methodsMutex); - counters_.methods[requestId] = {counter->first.c_str(), steady_clock::now()}; + { + std::scoped_lock const lock(counters_.methodsMutex); + counters_.methods[requestId] = {counter->first.c_str(), steady_clock::now()}; + } - // Task 9.4: Record RPC start in OTel metrics pipeline. + // Task 9.4: Record RPC start in OTel metrics pipeline. Recorded after the + // locks above are released: the OTel call path allocates and takes locks + // inside the SDK, so holding methodsMutex across it would widen a + // process-wide critical section for no reason. Mirrors rpcEnd(). if (auto* mr = app_.getMetricsRegistry()) mr->recordRpcStarted(method); @@ -424,10 +429,13 @@ PerfLogImp::jobQueue(JobType const type, std::string const& name) return; // LCOV_EXCL_STOP } - std::scoped_lock const lock(counter->second.mutex); - ++counter->second.value.queued; + { + std::scoped_lock const lock(counter->second.mutex); + ++counter->second.value.queued; + } - // Task 9.5: Record job enqueue in OTel metrics pipeline. + // Task 9.5: Record job enqueue in OTel metrics pipeline, after the lock + // above is released so the SDK's work stays outside the critical section. if (auto* mr = app_.getMetricsRegistry()) mr->recordJobQueued(JobTypes::name(type), name); } @@ -454,11 +462,16 @@ PerfLogImp::jobStart( ++counter->second.value.started; counter->second.value.queuedDuration += dur; } - std::scoped_lock const lock(counters_.jobsMutex); - if (instance >= 0 && instance < counters_.jobs.size()) - counters_.jobs[instance] = {type, startTime}; + { + std::scoped_lock const lock(counters_.jobsMutex); + if (instance >= 0 && instance < counters_.jobs.size()) + counters_.jobs[instance] = {type, startTime}; + } - // Task 9.5: Record job start in OTel metrics pipeline. + // Task 9.5: Record job start in OTel metrics pipeline, after the locks + // above are released. jobsMutex is process-wide and taken by every worker + // thread on every job, so the SDK's allocation and internal locking must + // not run inside it. if (auto* mr = app_.getMetricsRegistry()) mr->recordJobStarted(JobTypes::name(type), name, dur.count()); } @@ -480,11 +493,14 @@ PerfLogImp::jobFinish(JobType const type, std::string const& name, microseconds ++counter->second.value.finished; counter->second.value.runningDuration += dur; } - std::scoped_lock const lock(counters_.jobsMutex); - if (instance >= 0 && instance < counters_.jobs.size()) - counters_.jobs[instance] = {JtInvalid, steady_time_point()}; + { + std::scoped_lock const lock(counters_.jobsMutex); + if (instance >= 0 && instance < counters_.jobs.size()) + counters_.jobs[instance] = {JtInvalid, steady_time_point()}; + } - // Task 9.5: Record job finish in OTel metrics pipeline. + // Task 9.5: Record job finish in OTel metrics pipeline, after the locks + // above are released, for the same reason as jobStart(). if (auto* mr = app_.getMetricsRegistry()) mr->recordJobFinished(JobTypes::name(type), name, dur.count()); }