[PATCH 5/6] rteval: Refactor timerlat parsing and fix max line duplication bug

John Kacur <[email protected]> Thu, 23 Jul 2026 15:47:50 -0400
Newsgroups org.kernel.vger.linux-rt-users
Message-ID <[email protected]>
Extract max and overflow parsing into dedicated helper methods
(_parse_max_latencies and _parse_histogram_overflows) for better code
organization and consistency with cyclictest.py structure.

Fix bug where rtla timerlat's ALL: section contains a second max: line
with only 3 aggregate values (IRQ, Thread, User maxima across all cores).
This second max: line was incorrectly being parsed as core 0 data,
overwriting the correct per-core maximum values from the first max: line.

The first max: line contains per-core data (48 values for 16 cores with
3 columns each), while the second is an aggregate summary. Add max_parsed
flag to track parsing state and only parse the first occurrence.

When stoptrace is disabled, break after parsing the first max: line since
all needed histogram data has been collected. When stoptrace is enabled,
continue parsing to capture trace analysis data but skip the duplicate
max: line.

Enable rtla timerlat summary output (remove --no-summary) to get accurate
max values from the summary line rather than calculating from histogram
buckets, which are capped at the bucket range.

Assisted-by: Claude:claude-sonnet-4-5
Signed-off-by: John Kacur <[email protected]>
---
 rteval/modules/measurement/timerlat.py | 90 +++++++++++++++++---------
 1 file changed, 61 insertions(+), 29 deletions(-)

diff --git a/rteval/modules/measurement/timerlat.py b/rteval/modules/measurement/timerlat.py
index 1201302d47b4..f983cedf0daa 100644
--- a/rteval/modules/measurement/timerlat.py
+++ b/rteval/modules/measurement/timerlat.py
@@ -256,6 +256,54 @@ class Timerlat(rtevalModulePrototype):
             os.makedirs(logdir)
         return os.open(os.path.join(logdir, name), os.O_CREAT|os.O_RDWR|os.O_TRUNC)
 
+    def _parse_max_latencies(self, line):
+        """Parse the max: line from rtla timerlat output"""
+        if not line.startswith('max:'):
+            return
+
+        try:
+            vals = line.split()
+            if not vals or vals[0] != 'max:':
+                return
+
+            for i, core in enumerate(self.__cpus):
+                # timerlat has 3 columns per core: IRQ, Thread, User
+                # Take the maximum of the 3 values as the overall max for this core
+                if i*3 + 3 < len(vals):
+                    irq_max = int(vals[i*3+1])
+                    thr_max = int(vals[i*3+2])
+                    usr_max = int(vals[i*3+3])
+                    core_max = max(irq_max, thr_max, usr_max)
+
+                    self.__timerlatdata[core].update_max(core_max)
+                    self.__timerlatdata['system'].update_max(core_max)
+        except (IndexError, ValueError) as e:
+            self._log(Log.DEBUG, f"Error parsing max line: {e}")
+
+    def _parse_histogram_overflows(self, line):
+        """Parse the over: line from rtla timerlat output"""
+        if not line.startswith('over:'):
+            return
+
+        try:
+            vals = line.split()
+            if not vals or vals[0] != 'over:':
+                return
+
+            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)
+        except (IndexError, ValueError) as e:
+            self._log(Log.DEBUG, f"Error parsing overflow line: {e}")
+
     def _WorkloadSetup(self):
         self.__timerlat_process = None
 
@@ -271,7 +319,7 @@ class Timerlat(rtevalModulePrototype):
         self.__cmd.extend(['-P', f'f:{int(self.__priority)}', '-u'])
         self.__cmd.extend(['-c', self.__cpulist])
         self.__cmd.extend(['-E', str(self.__buckets)])
-        self.__cmd.append('--no-summary')
+        # self.__cmd.append('--no-summary')  # Commented out to get max: line for accurate overflow max values
         # Only disable auto-analysis if not using stoptrace (stoptrace needs it for trace analysis output)
         if not self.__cfg.stoptrace:
             self.__cmd.append('--no-aa')
@@ -405,6 +453,7 @@ class Timerlat(rtevalModulePrototype):
             blocking_thread_detected = False
             softirq_interference_detected = False
             irq_interference_detected = False
+            max_parsed = False  # Track if we've already parsed the max: line
 
             for line in output_lines:
                 if isinstance(line, bytes):
@@ -503,29 +552,7 @@ class Timerlat(rtevalModulePrototype):
                     #print(line)
                     continue
                 elif line.startswith('over:'):
-                    # 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}")
+                    self._parse_histogram_overflows(line)
                     continue
                 elif line.startswith('count:'):
                     #print(line)
@@ -537,16 +564,21 @@ class Timerlat(rtevalModulePrototype):
                     #print(line)
                     continue
                 elif line.startswith('max:'):
-                    #print(line)
+                    # Only parse the first max: line (per-core data)
+                    # Skip subsequent max: lines (like the ALL: section)
+                    if not max_parsed:
+                        self._parse_max_latencies(line)
+                        max_parsed = True
+                        # Max line is the last histogram data we need
+                        # If stoptrace is enabled, continue parsing for trace analysis
+                        # Otherwise stop to avoid the ALL: section
+                        if not self.__cfg.stoptrace:
+                            break
                     continue
                 elif line.startswith('timerlat hit stop tracing'):
                     self.__stoptrace = True
                     self.__posttrace += line
                     continue
-                elif line.startswith('ALL:'):
-                    # We should only see 'ALL:' without timerlat --no-summary
-                    # print(line)
-                    continue
                 else:
                     #print(line)
                     pass
-- 
2.55.0