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.
This commit is contained in:
Pratik Mankawde
2026-08-14 21:44:19 +01:00
parent 546cdf9a83
commit ddda820591

View File

@@ -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());
}