From 068142c78f25eb5b0d90eaac1125b248401b0ca4 Mon Sep 17 00:00:00 2001 From: Sandro Wenzel Date: Sat, 25 Jul 2026 18:56:03 +0200 Subject: [PATCH 1/2] Account for CPU used by child processes getCpuAndContexts() only sampled RUSAGE_SELF, so CPU burned by forked children was never reported. Sample RUSAGE_CHILDREN as well. The final measurement is reachable via finalizeProcessMonitoring() instead of only ~Monitoring(), and bypasses the 1s rate guard, which would otherwise discard a delta that no later call can pick up. Details: * RUSAGE_CHILDREN only becomes non-zero once a child has been reaped, so this is one half of the fix: the caller has to reap the child, and has to do so without killing an intermediate shell first. See the companion change in AliceO2Group/AliceO2#15636. * Forced (final) measurements are deliberately excluded from the percentage series. A reaped child's CPU becomes visible as one lump, and lump / (time since the last sample) is a meaningless rate - 14315% was observed before this exclusion. Only the absolute and accumulated fields carry meaning for such a sample, so consumers that care about external subprocesses (Hyperloop accounting) should read cpuTimeConsumedByProcess, not the percentage series. * Consequently a process that ends before the first periodic sample has no percentage at all - pushLoop() sleeps 100ms before sampling - and averaging over the empty series produced a NaN averageCpuUsedPercentage. Verified with a Monitoring instance destroyed after 10ms: 'nan' before, '0.14' on the unpatched library. Such a measurement now reports no average instead of a NaN one. * init() clears the aggregates, so monitoring that is stopped and started again reports the new period rather than blending it with the previous one. DPL devices go RUNNING -> READY -> RUNNING across runs and re-arm process monitoring on start. Related to https://its.cern.ch/jira/browse/O2-7096 Assisted by Claude Opus 5 --- include/Monitoring/Monitoring.h | 4 +++ include/Monitoring/ProcessMonitor.h | 7 ++++- src/Monitoring.cxx | 10 +++++- src/ProcessMonitor.cxx | 48 +++++++++++++++++++++++------ 4 files changed, 58 insertions(+), 11 deletions(-) diff --git a/include/Monitoring/Monitoring.h b/include/Monitoring/Monitoring.h index d3c78274..9ff410b1 100644 --- a/include/Monitoring/Monitoring.h +++ b/include/Monitoring/Monitoring.h @@ -73,6 +73,10 @@ class Monitoring /// \param enabledMeasurements vector of monitor measurements, eg. PmMeasurement::Cpu void enableProcessMonitoring(const unsigned int interval = 5, std::vector enabledMeasurements = {PmMeasurement::Cpu, PmMeasurement::Mem, PmMeasurement::Smaps}); + /// Stops process monitoring and transmits the final measurement. Idempotent; + /// call explicitly where destructor timing is not guaranteed to be reached. + void finalizeProcessMonitoring(); + /// Flushes metric buffer (this can also happen when buffer is full) void flushBuffer(); diff --git a/include/Monitoring/ProcessMonitor.h b/include/Monitoring/ProcessMonitor.h index fbc291b2..762efa00 100644 --- a/include/Monitoring/ProcessMonitor.h +++ b/include/Monitoring/ProcessMonitor.h @@ -112,6 +112,9 @@ class ProcessMonitor /// Best-effort open of the retired-instructions counter (no-op off Linux) void openInstructionCounter(); + /// 'getrusage(RUSAGE_CHILDREN)' values from last execution + struct rusage mPreviousGetrUsageChildren; + ///each measurement will be saved to compute average/accumulation usage std::vector mVmSizeMeasurements; std::vector mVmRssMeasurements; @@ -128,7 +131,9 @@ class ProcessMonitor std::vector getSmaps(); /// Retrieves CPU usage (%) and number of context switches during the interval - std::vector getCpuAndContexts(); + /// \param force ignore the 1s minimum interval; for the final measurement, + /// where a skipped delta would be lost rather than deferred + std::vector getCpuAndContexts(bool force = false); std::vector makeLastMeasurementAndGetMetrics(); }; diff --git a/src/Monitoring.cxx b/src/Monitoring.cxx index 10414e81..27b7842f 100644 --- a/src/Monitoring.cxx +++ b/src/Monitoring.cxx @@ -130,13 +130,21 @@ void Monitoring::addBackend(std::unique_ptr backend) mBackends.push_back(std::move(backend)); } -Monitoring::~Monitoring() +void Monitoring::finalizeProcessMonitoring() { + if (!mMonitorRunning) { + return; + } mMonitorRunning = false; if (mMonitorThread.joinable()) { mMonitorThread.join(); transmit(mProcessMonitor->makeLastMeasurementAndGetMetrics()); } +} + +Monitoring::~Monitoring() +{ + finalizeProcessMonitoring(); flushBuffer(); } diff --git a/src/ProcessMonitor.cxx b/src/ProcessMonitor.cxx index 8f01ad60..72117f23 100644 --- a/src/ProcessMonitor.cxx +++ b/src/ProcessMonitor.cxx @@ -60,6 +60,7 @@ ProcessMonitor::ProcessMonitor() mPid = static_cast(::getpid()); mTimeLastRun = std::chrono::high_resolution_clock::now(); getrusage(RUSAGE_SELF, &mPreviousGetrUsage); + getrusage(RUSAGE_CHILDREN, &mPreviousGetrUsageChildren); #ifdef O2_MONITORING_OS_LINUX setTotalMemory(); #endif @@ -99,6 +100,13 @@ void ProcessMonitor::init() { mTimeLastRun = std::chrono::high_resolution_clock::now(); getrusage(RUSAGE_SELF, &mPreviousGetrUsage); + getrusage(RUSAGE_CHILDREN, &mPreviousGetrUsageChildren); + // The aggregates describe one monitoring period: monitoring that is stopped + // and started again reports the new period, not both blended together. + mCpuPerctange.clear(); + mCpuMicroSeconds.clear(); + mVmSizeMeasurements.clear(); + mVmRssMeasurements.clear(); } void ProcessMonitor::enable(PmMeasurement measurement) @@ -167,27 +175,41 @@ std::vector ProcessMonitor::getSmaps() return {{pssTotal, metricsNames[PSS]}, {cleanTotal, metricsNames[PRIVATE_CLEAN]}, {dirtyTotal, metricsNames[PRIVATE_DIRTY]}}; } -std::vector ProcessMonitor::getCpuAndContexts() +std::vector ProcessMonitor::getCpuAndContexts(bool force) { std::vector metrics; struct rusage currentUsage; + struct rusage currentUsageChildren; getrusage(RUSAGE_SELF, ¤tUsage); + // CPU of reaped children (e.g. an external event generator forked by o2-sim) + // is spent outside this process and is invisible to RUSAGE_SELF + getrusage(RUSAGE_CHILDREN, ¤tUsageChildren); auto timeNow = std::chrono::high_resolution_clock::now(); double timePassed = std::chrono::duration_cast(timeNow - mTimeLastRun).count(); - if (timePassed < 950) { + if (timePassed < 950 && !force) { MonLogger::Get(Severity::Warn) << "Do not invoke Process Monitor more frequent then every 1s" << MonLogger::End(); metrics.emplace_back("processPerformance"); return metrics; } - uint64_t cpuUsedInMicroSeconds = currentUsage.ru_utime.tv_sec * 1000000.0 + currentUsage.ru_utime.tv_usec - (mPreviousGetrUsage.ru_utime.tv_sec * 1000000.0 + mPreviousGetrUsage.ru_utime.tv_usec) + currentUsage.ru_stime.tv_sec * 1000000.0 + currentUsage.ru_stime.tv_usec - (mPreviousGetrUsage.ru_stime.tv_sec * 1000000.0 + mPreviousGetrUsage.ru_stime.tv_usec); + auto micros = [](const timeval& t) { return t.tv_sec * 1000000.0 + t.tv_usec; }; + auto cpuDelta = [µs](const struct rusage& now, const struct rusage& before) { + return micros(now.ru_utime) - micros(before.ru_utime) + micros(now.ru_stime) - micros(before.ru_stime); + }; + uint64_t cpuUsedInMicroSeconds = cpuDelta(currentUsage, mPreviousGetrUsage) + + cpuDelta(currentUsageChildren, mPreviousGetrUsageChildren); double fractionCpuUsed = cpuUsedInMicroSeconds / timePassed; double cpuUsedPerctange = std::round(fractionCpuUsed * 100.0 * 100.0) / 100.0; - mCpuPerctange.push_back(cpuUsedPerctange); mCpuMicroSeconds.push_back(cpuUsedInMicroSeconds); - metrics.emplace_back(Metric{cpuUsedPerctange, metricsNames[CPU_USED_PERCENTAGE]}); + // A forced measurement may report CPU accumulated over the whole run but only + // made visible at once (children become visible on reap), for which an + // instantaneous rate is meaningless: report it as absolute time only. + if (!force) { + mCpuPerctange.push_back(cpuUsedPerctange); + metrics.emplace_back(Metric{cpuUsedPerctange, metricsNames[CPU_USED_PERCENTAGE]}); + } metrics.emplace_back(Metric{ static_cast(currentUsage.ru_nivcsw - mPreviousGetrUsage.ru_nivcsw), metricsNames[INVOLUNTARY_CONTEXT_SWITCHES]}); metrics.emplace_back(Metric{ @@ -212,6 +234,7 @@ std::vector ProcessMonitor::getCpuAndContexts() mTimeLastRun = timeNow; mPreviousGetrUsage = currentUsage; + mPreviousGetrUsageChildren = currentUsageChildren; return metrics; } @@ -262,14 +285,21 @@ std::vector ProcessMonitor::makeLastMeasurementAndGetMetrics() } #endif if (mEnabledMeasurements.at(static_cast(PmMeasurement::Cpu))) { - getCpuAndContexts(); + // forced: no later call will pick up a delta discarded here + auto lastCpuMetrics = getCpuAndContexts(true); + std::move(lastCpuMetrics.begin(), lastCpuMetrics.end(), std::back_inserter(metrics)); - auto avgCpuUsage = std::accumulate(mCpuPerctange.begin(), mCpuPerctange.end(), 0.0) / - mCpuPerctange.size(); uint64_t accumulationOfCpuTimeConsumption = std::accumulate(mCpuMicroSeconds.begin(), mCpuMicroSeconds.end(), 0UL); - metrics.emplace_back(avgCpuUsage, metricsNames[AVG_CPU_USED_PERCENTAGE]); + // Only forced measurements contribute no percentage, so a process that + // ends before the first periodic sample has none at all - report no + // average rather than a NaN one. + if (!mCpuPerctange.empty()) { + auto avgCpuUsage = std::accumulate(mCpuPerctange.begin(), mCpuPerctange.end(), 0.0) / + mCpuPerctange.size(); + metrics.emplace_back(avgCpuUsage, metricsNames[AVG_CPU_USED_PERCENTAGE]); + } metrics.emplace_back(accumulationOfCpuTimeConsumption, metricsNames[ACCUMULATED_CPU_TIME]); } return metrics; From 2d32eac35d796941cce9d65425ef724ac2dfed17 Mon Sep 17 00:00:00 2001 From: Sandro Wenzel Date: Mon, 10 Aug 2026 13:31:54 +0200 Subject: [PATCH 2/2] Account for children in the context switches too The previous commit made the CPU numbers the sum over this process and its reaped children, but left the two context-switch counts on RUSAGE_SELF alone, so a single measurement mixed a process-tree quantity with a parent-only one. Both counts now sum the same pair of snapshots. Raised in review. The surrounding measurement code is tidied while we are here: the CPU delta is expressed in the same shape as the context-switch deltas, and the percentage is computed only on the path that actually reports one. Co-Authored-By: Claude Opus 5 --- include/Monitoring/Monitoring.h | 3 +- include/Monitoring/ProcessMonitor.h | 10 +++--- src/ProcessMonitor.cxx | 51 ++++++++++++++--------------- 3 files changed, 32 insertions(+), 32 deletions(-) diff --git a/include/Monitoring/Monitoring.h b/include/Monitoring/Monitoring.h index 9ff410b1..9b0d3352 100644 --- a/include/Monitoring/Monitoring.h +++ b/include/Monitoring/Monitoring.h @@ -74,7 +74,8 @@ class Monitoring void enableProcessMonitoring(const unsigned int interval = 5, std::vector enabledMeasurements = {PmMeasurement::Cpu, PmMeasurement::Mem, PmMeasurement::Smaps}); /// Stops process monitoring and transmits the final measurement. Idempotent; - /// call explicitly where destructor timing is not guaranteed to be reached. + /// call it explicitly where destructor timing is not guaranteed, e.g. on a + /// DPL device's RUNNING->READY transition. void finalizeProcessMonitoring(); /// Flushes metric buffer (this can also happen when buffer is full) diff --git a/include/Monitoring/ProcessMonitor.h b/include/Monitoring/ProcessMonitor.h index 762efa00..6955b564 100644 --- a/include/Monitoring/ProcessMonitor.h +++ b/include/Monitoring/ProcessMonitor.h @@ -104,6 +104,9 @@ class ProcessMonitor /// 'getrusage' values from last execution struct rusage mPreviousGetrUsage; + /// 'getrusage(RUSAGE_CHILDREN)' values from last execution + struct rusage mPreviousGetrUsageChildren; + /// Retired-instructions hardware counter (perf_event_open, Linux only); /// -1 when unavailable (high perf_event_paranoid, container seccomp, or no PMU). int mInstructionsFd = -1; @@ -112,9 +115,6 @@ class ProcessMonitor /// Best-effort open of the retired-instructions counter (no-op off Linux) void openInstructionCounter(); - /// 'getrusage(RUSAGE_CHILDREN)' values from last execution - struct rusage mPreviousGetrUsageChildren; - ///each measurement will be saved to compute average/accumulation usage std::vector mVmSizeMeasurements; std::vector mVmRssMeasurements; @@ -131,8 +131,8 @@ class ProcessMonitor std::vector getSmaps(); /// Retrieves CPU usage (%) and number of context switches during the interval - /// \param force ignore the 1s minimum interval; for the final measurement, - /// where a skipped delta would be lost rather than deferred + /// \param force ignore the 1s minimum interval and report no percentage; + /// for the final measurement, whose delta no later call would pick up std::vector getCpuAndContexts(bool force = false); std::vector makeLastMeasurementAndGetMetrics(); diff --git a/src/ProcessMonitor.cxx b/src/ProcessMonitor.cxx index 72117f23..9de2f0b5 100644 --- a/src/ProcessMonitor.cxx +++ b/src/ProcessMonitor.cxx @@ -101,8 +101,8 @@ void ProcessMonitor::init() mTimeLastRun = std::chrono::high_resolution_clock::now(); getrusage(RUSAGE_SELF, &mPreviousGetrUsage); getrusage(RUSAGE_CHILDREN, &mPreviousGetrUsageChildren); - // The aggregates describe one monitoring period: monitoring that is stopped - // and started again reports the new period, not both blended together. + // The aggregates cover one monitoring period: monitoring stopped and started + // again reports the new period, not both blended together. mCpuPerctange.clear(); mCpuMicroSeconds.clear(); mVmSizeMeasurements.clear(); @@ -178,11 +178,11 @@ std::vector ProcessMonitor::getSmaps() std::vector ProcessMonitor::getCpuAndContexts(bool force) { std::vector metrics; + // RUSAGE_SELF does not see work done by reaped children (e.g. an external + // event generator forked by o2-sim), so every counter below sums the two. struct rusage currentUsage; struct rusage currentUsageChildren; getrusage(RUSAGE_SELF, ¤tUsage); - // CPU of reaped children (e.g. an external event generator forked by o2-sim) - // is spent outside this process and is invisible to RUSAGE_SELF getrusage(RUSAGE_CHILDREN, ¤tUsageChildren); auto timeNow = std::chrono::high_resolution_clock::now(); double timePassed = std::chrono::duration_cast(timeNow - mTimeLastRun).count(); @@ -192,28 +192,28 @@ std::vector ProcessMonitor::getCpuAndContexts(bool force) return metrics; } - auto micros = [](const timeval& t) { return t.tv_sec * 1000000.0 + t.tv_usec; }; - auto cpuDelta = [µs](const struct rusage& now, const struct rusage& before) { - return micros(now.ru_utime) - micros(before.ru_utime) + micros(now.ru_stime) - micros(before.ru_stime); + // CPU time (user + system) of one snapshot, in microseconds + auto cpuMicros = [](const struct rusage& usage) { + return (usage.ru_utime.tv_sec + usage.ru_stime.tv_sec) * 1000000.0 + usage.ru_utime.tv_usec + usage.ru_stime.tv_usec; }; - uint64_t cpuUsedInMicroSeconds = cpuDelta(currentUsage, mPreviousGetrUsage) + - cpuDelta(currentUsageChildren, mPreviousGetrUsageChildren); - double fractionCpuUsed = cpuUsedInMicroSeconds / timePassed; - - double cpuUsedPerctange = std::round(fractionCpuUsed * 100.0 * 100.0) / 100.0; + uint64_t cpuUsedInMicroSeconds = (cpuMicros(currentUsage) - cpuMicros(mPreviousGetrUsage)) + + (cpuMicros(currentUsageChildren) - cpuMicros(mPreviousGetrUsageChildren)); mCpuMicroSeconds.push_back(cpuUsedInMicroSeconds); - // A forced measurement may report CPU accumulated over the whole run but only - // made visible at once (children become visible on reap), for which an - // instantaneous rate is meaningless: report it as absolute time only. + // A child's CPU time appears all at once when it is reaped, so the delta of a + // forced (final) measurement is not a rate over the interval: absolute time only. if (!force) { + double fractionCpuUsed = cpuUsedInMicroSeconds / timePassed; + double cpuUsedPerctange = std::round(fractionCpuUsed * 100.0 * 100.0) / 100.0; mCpuPerctange.push_back(cpuUsedPerctange); metrics.emplace_back(Metric{cpuUsedPerctange, metricsNames[CPU_USED_PERCENTAGE]}); } - metrics.emplace_back(Metric{ - static_cast(currentUsage.ru_nivcsw - mPreviousGetrUsage.ru_nivcsw), metricsNames[INVOLUNTARY_CONTEXT_SWITCHES]}); - metrics.emplace_back(Metric{ - static_cast(currentUsage.ru_nvcsw - mPreviousGetrUsage.ru_nvcsw), metricsNames[VOLUNTARY_CONTEXT_SWITCHES]}); + uint64_t involuntaryContextSwitches = (currentUsage.ru_nivcsw - mPreviousGetrUsage.ru_nivcsw) + + (currentUsageChildren.ru_nivcsw - mPreviousGetrUsageChildren.ru_nivcsw); + uint64_t voluntaryContextSwitches = (currentUsage.ru_nvcsw - mPreviousGetrUsage.ru_nvcsw) + + (currentUsageChildren.ru_nvcsw - mPreviousGetrUsageChildren.ru_nvcsw); + metrics.emplace_back(Metric{involuntaryContextSwitches, metricsNames[INVOLUNTARY_CONTEXT_SWITCHES]}); + metrics.emplace_back(Metric{voluntaryContextSwitches, metricsNames[VOLUNTARY_CONTEXT_SWITCHES]}); metrics.emplace_back(cpuUsedInMicroSeconds, metricsNames[CPU_USED_ABSOLUTE]); #ifdef O2_MONITORING_OS_LINUX @@ -285,21 +285,20 @@ std::vector ProcessMonitor::makeLastMeasurementAndGetMetrics() } #endif if (mEnabledMeasurements.at(static_cast(PmMeasurement::Cpu))) { - // forced: no later call will pick up a delta discarded here + // forced: no later call would pick up a delta the rate guard discards here auto lastCpuMetrics = getCpuAndContexts(true); std::move(lastCpuMetrics.begin(), lastCpuMetrics.end(), std::back_inserter(metrics)); - uint64_t accumulationOfCpuTimeConsumption = std::accumulate(mCpuMicroSeconds.begin(), - mCpuMicroSeconds.end(), 0UL); - - // Only forced measurements contribute no percentage, so a process that - // ends before the first periodic sample has none at all - report no - // average rather than a NaN one. + // A process that ends before the first periodic measurement has no + // percentages at all (the forced one contributes none), and averaging an + // empty vector would give NaN. if (!mCpuPerctange.empty()) { auto avgCpuUsage = std::accumulate(mCpuPerctange.begin(), mCpuPerctange.end(), 0.0) / mCpuPerctange.size(); metrics.emplace_back(avgCpuUsage, metricsNames[AVG_CPU_USED_PERCENTAGE]); } + uint64_t accumulationOfCpuTimeConsumption = std::accumulate(mCpuMicroSeconds.begin(), + mCpuMicroSeconds.end(), 0UL); metrics.emplace_back(accumulationOfCpuTimeConsumption, metricsNames[ACCUMULATED_CPU_TIME]); } return metrics;