[PATCH 4/6] rteval: Improve overflow bucket handling and add timerlat support
John Kacur <[email protected]> Thu, 23 Jul 2026 15:47:49 -0400
| Newsgroups | org.kernel.vger.linux-rt-users |
|---|---|
| Message-ID | <[email protected]> |
This improves the overflow bucket implementation by using cyclictest's native overflow tracking instead of manual bucket clamping, and extends overflow support to the timerlat measurement module. Changes to cyclictest module: - Parse "# Histogram Overflows:" line from cyclictest output - Remove manual bucket clamping logic (cyclictest handles this) - Improve SIGINT timeout handling with progressive waits (10s->5s->2s) - Create dedicated overflow bucket with index="overflow" attribute - Remove overflow_bucket attribute (no longer needed) Changes to timerlat module: - Parse "over:" line from rtla timerlat hist output - Track overflow per-core and accumulate for system-wide totals - Add overflow_samples to statistics output - Improve SIGINT timeout handling matching cyclictest - Create dedicated overflow bucket with index="overflow" attribute - Log warnings when overflow occurs Changes to XSL stylesheet: - Display total overflow count in summary section - Display per-core overflow samples in statistics output This provides consistent overflow handling across both measurement modules, giving users meaningful statistics even when latency spikes exceed the histogram range. Assisted-by: Claude:claude-sonnet-4-5 Signed-off-by: John Kacur <[email protected]> --- rteval/modules/measurement/cyclictest.py | 75 +++++++++++++++------- rteval/modules/measurement/timerlat.py | 79 +++++++++++++++++++++++- rteval/rteval_text.xsl | 30 ++++++++- 3 files changed, 159 insertions(+), 25 deletions(-) diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py index 8371aa2e2aa5..b193330e27e0 100644 --- a/rteval/modules/measurement/cyclictest.py +++ b/rteval/modules/measurement/cyclictest.py @@ -39,7 +39,6 @@ class RunData: self.__mad = 0.0 self._log = logfnc self.__overflow_samples = 0 # Track samples that exceeded bucket range - self.__bucket_limit = None # Maximum bucket index def __str__(self): retval = f"id: {self.__id}\n" @@ -63,28 +62,24 @@ class RunData: if value < self.__min: self.__min = value - def set_bucket_limit(self, limit): - """Set the maximum bucket index for overflow handling""" - self.__bucket_limit = limit + def set_overflow_count(self, count): + """Set overflow count from cyclictest output""" + self.__overflow_samples = count + + def add_overflow_samples(self, count): + """Add to overflow count (for system-wide accumulation)""" + self.__overflow_samples += count def get_overflow_count(self): """Get the number of samples that exceeded the bucket limit""" return self.__overflow_samples def bucket(self, index, value): - """Add samples to histogram bucket, clamping overflow to the last bucket""" - # Track the actual max before clamping + """Add samples to histogram bucket""" + self.__samples[index] = self.__samples.setdefault(index, 0) + value if value: self.update_max(index) self.update_min(index) - - # Clamp to bucket limit if set (overflow bucket) - if self.__bucket_limit is not None and index >= self.__bucket_limit: - if value: - self.__overflow_samples += value - index = self.__bucket_limit - 1 # Use last bucket as overflow bucket - - self.__samples[index] = self.__samples.setdefault(index, 0) + value self.__numsamples += value def reduce(self): @@ -193,7 +188,6 @@ class RunData: hist_n = rep_n.newChild(None, 'histogram', None) hist_n.newProp('nbuckets', str(len(self.__samples))) if self.__overflow_samples > 0: - hist_n.newProp('overflow_bucket', str(self.__bucket_limit - 1)) hist_n.newProp('overflow_count', str(self.__overflow_samples)) keys = list(self.__samples.keys()) keys.sort() @@ -205,6 +199,13 @@ class RunData: b_n.newProp('index', str(k)) b_n.newProp('value', str(self.__samples[k])) + # Add dedicated overflow bucket if overflow occurred + if self.__overflow_samples > 0: + b_n = hist_n.newChild(None, 'bucket', None) + b_n.newProp('index', 'overflow') + b_n.newProp('value', str(self.__overflow_samples)) + b_n.newProp('type', 'overflow') + return rep_n @@ -232,14 +233,12 @@ class Cyclictest(rtevalModulePrototype): self.__cyclicdata[core] = RunData(core, 'core', self.__priority, logfnc=self._log) self.__cyclicdata[core].description = info[core]['model name'] - self.__cyclicdata[core].set_bucket_limit(self.__buckets) # Create a RunData object for the overall system self.__cyclicdata['system'] = RunData('system', 'system', self.__priority, logfnc=self._log) self.__cyclicdata['system'].description = (f"({self.__numcores} cores) ") + info['0']['model name'] - self.__cyclicdata['system'].set_bucket_limit(self.__buckets) # Logging configuration self._logging = self.__cfg.setdefault('logging', False) @@ -377,19 +376,51 @@ class Cyclictest(rtevalModulePrototype): except (IndexError, ValueError) as e: self._log(Log.WARN, f"Error parsing max latencies: {e}") + def _parse_histogram_overflows(self, line): + if not line.startswith('# Histogram Overflows:'): + return + + try: + line = line.split(':')[1] + vals = [int(x) for x in line.split()] + + # First N values are per-core overflow counts + for i, core in enumerate(self.__cpus): + if i < len(vals): + overflow_count = vals[i] + self.__cyclicdata[core].set_overflow_count(overflow_count) + self.__cyclicdata['system'].add_overflow_samples(overflow_count) + except (IndexError, ValueError) as e: + self._log(Log.WARN, f"Error parsing histogram overflows: {e}") def _WorkloadCleanup(self): if not self.__started: return # Send SIGINT and wait for graceful exit - # Limit attempts to avoid infinite loop (RHEL-140898) + # Use wait(timeout) to return immediately when process exits max_attempts = 5 attempt = 0 while self.__cyclicprocess.poll() is None and attempt < max_attempts: self._log(Log.DEBUG, f"Sending SIGINT (attempt {attempt + 1}/{max_attempts})") os.kill(self.__cyclicprocess.pid, signal.SIGINT) - time.sleep(2) + + # Use longer timeout on first attempt to allow histogram output to complete + # Subsequent attempts use shorter timeouts + if attempt == 0: + timeout = 10 # First attempt: 10 seconds for histogram output + elif attempt == 1: + timeout = 5 # Second attempt: 5 seconds + else: + timeout = 2 # Remaining attempts: 2 seconds + + try: + self.__cyclicprocess.wait(timeout=timeout) + break # Process exited gracefully + except subprocess.TimeoutExpired: + # Process still running after timeout, will try again + pass + attempt += 1 # Check if process exited @@ -431,6 +462,8 @@ class Cyclictest(rtevalModulePrototype): self._log(Log.WARN, f"Error parsing break value: {e}") elif line.startswith('# Max Latencies: '): self._parse_max_latencies(line) + elif line.startswith('# Histogram Overflows:'): + self._parse_histogram_overflows(line) continue # Skipping blank lines @@ -508,10 +541,10 @@ class Cyclictest(rtevalModulePrototype): rep_n.addChild(abrt_n) # Let the user know if max latency overshot the number of buckets - if self.__cyclicdata["system"].get_max() > self.__buckets: + if self.__cyclicdata["system"].get_max() >= self.__buckets: overflow_count = self.__cyclicdata["system"].get_overflow_count() self._log(Log.WARN, f'Max latency({self.__cyclicdata["system"].get_max()}us) exceeded histogram range({self.__buckets}us)') - self._log(Log.WARN, f'{overflow_count} samples clamped to overflow bucket at index {self.__buckets - 1}') + self._log(Log.WARN, f'{overflow_count} samples stored in overflow bucket') self._log(Log.WARN, "Consider increasing buckets parameter for better resolution") rep_n.addChild(self.__cyclicdata["system"].MakeReport()) diff --git a/rteval/modules/measurement/timerlat.py b/rteval/modules/measurement/timerlat.py index b0e20a72ef38..1201302d47b4 100644 --- a/rteval/modules/measurement/timerlat.py +++ b/rteval/modules/measurement/timerlat.py @@ -39,6 +39,7 @@ class TLRunData: self.__mode = 0.0 self.__median = 0.0 self.__range = 0.0 + self.__overflow_samples = 0 # Track samples that exceeded bucket range def update_max(self, value): """ highest bucket with a value """ @@ -50,6 +51,18 @@ class TLRunData: if value < self.min: self.min = value + def set_overflow_count(self, count): + """Set overflow count from rtla timerlat output""" + self.__overflow_samples = count + + def add_overflow_samples(self, count): + """Add to overflow count (for system-wide accumulation)""" + self.__overflow_samples += count + + def get_overflow_count(self): + """Get the number of samples that exceeded the bucket limit""" + return self.__overflow_samples + def bucket(self, index, val1, val2, val3): """ Store results index=bucket number, val1=IRQ, val2=thr, val3=usr """ values = val1 + val2 + val3 @@ -158,8 +171,15 @@ class TLRunData: n = stat_n.newTextChild(None, 'standard_deviation', str(self.__stddev)) n.newProp('unit', 'us') + # Report overflow samples if any + if self.__overflow_samples > 0: + n = stat_n.newTextChild(None, 'overflow_samples', str(self.__overflow_samples)) + n.newProp('info', f'{self.__overflow_samples} samples exceeded histogram range') + hist_n = rep_n.newChild(None, 'histogram', None) hist_n.newProp('nbuckets', str(len(self.__samples))) + if self.__overflow_samples > 0: + hist_n.newProp('overflow_count', str(self.__overflow_samples)) keys = list(self.__samples.keys()) keys.sort() @@ -171,6 +191,13 @@ class TLRunData: b_n.newProp('index', str(k)) b_n.newProp('value', str(self.__samples[k])) + # Add dedicated overflow bucket if overflow occurred + if self.__overflow_samples > 0: + b_n = hist_n.newChild(None, 'bucket', None) + b_n.newProp('index', 'overflow') + b_n.newProp('value', str(self.__overflow_samples)) + b_n.newProp('type', 'overflow') + return rep_n class Timerlat(rtevalModulePrototype): @@ -323,13 +350,30 @@ class Timerlat(rtevalModulePrototype): return # Send SIGINT and wait for graceful exit - # Limit attempts to avoid infinite loop and double-SIGINT issues (RHEL-140898) + # Give timerlat time to write complete histogram (including 'over:' line) + # Use wait(timeout) to return immediately when process exits max_attempts = 5 attempt = 0 while self.__timerlat_process.poll() is None and attempt < max_attempts: self._log(Log.DEBUG, f"Sending SIGINT (attempt {attempt + 1}/{max_attempts})") os.kill(self.__timerlat_process.pid, signal.SIGINT) - time.sleep(2) + + # Use longer timeout on first attempt to allow histogram output to complete + # Subsequent attempts use shorter timeouts + if attempt == 0: + timeout = 10 # First attempt: 10 seconds for histogram output + elif attempt == 1: + timeout = 5 # Second attempt: 5 seconds + else: + timeout = 2 # Remaining attempts: 2 seconds + + try: + self.__timerlat_process.wait(timeout=timeout) + break # Process exited gracefully + except subprocess.TimeoutExpired: + # Process still running after timeout, will try again + pass + attempt += 1 # Check if process exited @@ -459,7 +503,29 @@ class Timerlat(rtevalModulePrototype): #print(line) continue elif line.startswith('over:'): - #print(line) + # Parse overflow counts: 3 values per CPU (IRQ, Thread, User) + vals = line.split() + if not vals or vals[0] != 'over:': + continue + try: + for i, core in enumerate(self.__cpus): + # timerlat has 3 columns per core: IRQ, Thread, User + # Calculate total overflow for this core + if i*3 + 3 < len(vals): + irq_overflow = int(vals[i*3+1]) + thr_overflow = int(vals[i*3+2]) + usr_overflow = int(vals[i*3+3]) + total_overflow = irq_overflow + thr_overflow + usr_overflow + + self.__timerlatdata[core].set_overflow_count(total_overflow) + self.__timerlatdata['system'].add_overflow_samples(total_overflow) + + # If overflow occurred, max latency is at least the bucket limit + if total_overflow > 0: + self.__timerlatdata[core].update_max(self.__buckets) + self.__timerlatdata['system'].update_max(self.__buckets) + except (IndexError, ValueError) as e: + self._log(Log.DEBUG, f"Error parsing overflow line: {e}") continue elif line.startswith('count:'): #print(line) @@ -603,6 +669,13 @@ class Timerlat(rtevalModulePrototype): rep_n.addChild(max_timerlat_n) return rep_n + # Let the user know if max latency overshot the number of buckets + if self.__timerlatdata["system"].max >= self.__buckets: + overflow_count = self.__timerlatdata["system"].get_overflow_count() + self._log(Log.WARN, f'Max latency({self.__timerlatdata["system"].max}us) exceeded histogram range({self.__buckets}us)') + self._log(Log.WARN, f'{overflow_count} samples stored in overflow bucket') + self._log(Log.WARN, "Consider increasing buckets parameter for better resolution") + rep_n.addChild(self.__timerlatdata['system'].MakeReport()) for thr in self.__cpus: if str(thr) not in self.__timerlatdata: diff --git a/rteval/rteval_text.xsl b/rteval/rteval_text.xsl index da7084289f87..a6829119170b 100644 --- a/rteval/rteval_text.xsl +++ b/rteval/rteval_text.xsl @@ -163,7 +163,23 @@ <xsl:text>not present</xsl:text> </xsl:otherwise> </xsl:choose> - <xsl:text> </xsl:text> + <xsl:text> </xsl:text> + + <!-- Display total overflow samples if present --> + <xsl:if test="Measurements/cyclictest/system/statistics/overflow_samples or Measurements/timerlat/system/statistics/overflow_samples"> + <xsl:text> Total Overflows: </xsl:text> + <xsl:choose> + <xsl:when test="Measurements/cyclictest/system/statistics/overflow_samples"> + <xsl:value-of select="Measurements/cyclictest/system/statistics/overflow_samples"/> + </xsl:when> + <xsl:when test="Measurements/timerlat/system/statistics/overflow_samples"> + <xsl:value-of select="Measurements/timerlat/system/statistics/overflow_samples"/> + </xsl:when> + </xsl:choose> + <xsl:text> samples exceeded histogram range</xsl:text> + <xsl:text> </xsl:text> + </xsl:if> + <xsl:text> </xsl:text> <!-- Display core sharing warnings if present --> <xsl:if test="SystemInfo/CPUtopology/CoreSharingWarnings/warning"> @@ -321,6 +337,12 @@ <xsl:value-of select="standard_deviation"/> <xsl:value-of select="standard_deviation/@unit"/> <xsl:text> </xsl:text> + + <xsl:if test="overflow_samples"> + <xsl:text> Overflow samples: </xsl:text> + <xsl:value-of select="overflow_samples"/> + <xsl:text> </xsl:text> + </xsl:if> </xsl:if> <xsl:text> </xsl:text> </xsl:template> @@ -428,6 +450,12 @@ <xsl:value-of select="standard_deviation"/> <xsl:value-of select="standard_deviation/@unit"/> <xsl:text> </xsl:text> + + <xsl:if test="overflow_samples"> + <xsl:text> Overflow samples: </xsl:text> + <xsl:value-of select="overflow_samples"/> + <xsl:text> </xsl:text> + </xsl:if> </xsl:if> <xsl:text> </xsl:text> </xsl:template> -- 2.55.0