5867fda300
Add timerlat tracing Add Fix-aNone being pass to cyclictest Resolves: RHEL-35462 Signed-off-by: John Kacur <jkacur@redhat.com>
218 lines
12 KiB
Diff
218 lines
12 KiB
Diff
From 4fd5b77dc47f039551050925e442db9a17be5e75 Mon Sep 17 00:00:00 2001
|
|
From: John Kacur <jkacur@redhat.com>
|
|
Date: Mon, 24 Jun 2024 08:45:54 -0400
|
|
Subject: [PATCH 4/4] rteval: timerlat tracing clean-up
|
|
|
|
The patch cleans-up the code that stores the timerlat summary into xml,
|
|
after a trace is stopped. It does so by grouping similar kinds of output
|
|
together for parsing. It also reduces the amount of debug output.
|
|
|
|
Signed-off-by: John Kacur <jkacur@redhat.com>
|
|
---
|
|
rteval/modules/measurement/timerlat.py | 142 ++++++++++---------------
|
|
rteval/rteval_text.xsl | 10 +-
|
|
2 files changed, 62 insertions(+), 90 deletions(-)
|
|
|
|
diff --git a/rteval/modules/measurement/timerlat.py b/rteval/modules/measurement/timerlat.py
|
|
index 45adec1b33e1..dc6226ccc991 100644
|
|
--- a/rteval/modules/measurement/timerlat.py
|
|
+++ b/rteval/modules/measurement/timerlat.py
|
|
@@ -273,12 +273,14 @@ class Timerlat(rtevalModulePrototype):
|
|
os.kill(self.__timerlat_process.pid, signal.SIGINT)
|
|
time.sleep(2)
|
|
|
|
+
|
|
+ # Parse histogram output
|
|
+ self.__timerlat_out.seek(0)
|
|
+
|
|
blocking_thread_detected = False
|
|
softirq_interference_detected = False
|
|
irq_interference_detected = False
|
|
|
|
- # Parse histogram output
|
|
- self.__timerlat_out.seek(0)
|
|
for line in self.__timerlat_out:
|
|
line = bytes.decode(line)
|
|
|
|
@@ -291,6 +293,8 @@ class Timerlat(rtevalModulePrototype):
|
|
self.__posttrace += line
|
|
line = line.strip()
|
|
fields = line.split()
|
|
+ if not line:
|
|
+ continue
|
|
if line.startswith("##") and fields[1] == "CPU":
|
|
self.stcpu = int(fields[2])
|
|
self._log(Log.DEBUG, f"self.stcpu = {self.stcpu}")
|
|
@@ -304,91 +308,59 @@ class Timerlat(rtevalModulePrototype):
|
|
softirq_interference_detected = False
|
|
irq_interference_detected = False
|
|
continue
|
|
- if line.startswith("Thread latency:"):
|
|
- thread_latency_percent = fields[-1].strip('()%')
|
|
- self._log(Log.DEBUG, f"thread_latency_percent = {thread_latency_percent}")
|
|
- thread_latency = fields[-3]
|
|
- self._log(Log.DEBUG, f"thread_latency = {thread_latency}")
|
|
- self.__stdata[self.stcpu]["Thread_latency"] = (thread_latency, thread_latency_percent)
|
|
- elif line.startswith("Previous IRQ interference"):
|
|
- self._log(Log.DEBUG, f'Previous_IRQ_interference = {fields[-2]}')
|
|
- self.__stdata[self.stcpu]["Previous_IRQ_interference"] = fields[-2]
|
|
- elif line.startswith("IRQ handler delay:"):
|
|
- irq_handler_delay_percent = fields[-2].strip('(')
|
|
- irq_handler_delay = fields[-4]
|
|
- # Do we have (exit from idle)?
|
|
- if fields[3] == '(exit':
|
|
- field_name = "IRQ_handler_delay_exit_from_idle"
|
|
- else:
|
|
- field_name = "IRQ_handler_delay"
|
|
- self._log(Log.DEBUG, f"{field_name} = {irq_handler_delay}")
|
|
- self._log(Log.DEBUG, f"{field_name}_percent = {irq_handler_delay_percent}")
|
|
- self.__stdata[self.stcpu][field_name] = (irq_handler_delay, irq_handler_delay_percent)
|
|
- elif line.startswith("IRQ latency:"):
|
|
- self._log(Log.DEBUG, f"irq_latency = {fields[-2]}")
|
|
- self.__stdata[self.stcpu]["IRQ_latency"] = fields[-2]
|
|
- elif line.startswith("Timerlat IRQ duration"):
|
|
- timerlat_irq_duration_percent = fields[-2].strip('(')
|
|
- self._log(Log.DEBUG, f"timerlat_irq_duration_percent = {timerlat_irq_duration_percent}")
|
|
- timerlat_irq_duration = fields[-4]
|
|
- self._log(Log.DEBUG, f"timerlat_irq_duration = {timerlat_irq_duration}")
|
|
- self.__stdata[self.stcpu]["Timerlat_IRQ_duration"] = (timerlat_irq_duration, timerlat_irq_duration_percent)
|
|
- elif line.startswith("Blocking thread:"):
|
|
- blocking_thread_percent = fields[-2].strip('(')
|
|
- self._log(Log.DEBUG, f"blocking_thread_percent = {blocking_thread_percent}")
|
|
- blocking_thread = fields[-4]
|
|
- self._log(Log.DEBUG, f"blocking_thread = {blocking_thread}")
|
|
- self.__stdata[self.stcpu]["Blocking_Thread"] = (blocking_thread, blocking_thread_percent)
|
|
- blocking_thread_detected = True
|
|
- irq_interference_detected = False
|
|
- softirq_interference_detected = False
|
|
- elif line.startswith("IRQ interference"):
|
|
- irq_interference_percent = fields[-2].strip('(')
|
|
- self._log(Log.DEBUG, f"irq_interference_percent = {irq_interference_percent}")
|
|
- irq_interference = fields[-4]
|
|
- self._log(Log.DEBUG, f"irq_interference = {irq_interference}")
|
|
- self.__stdata[self.stcpu]["IRQ_interference"] = (irq_interference, irq_interference_percent)
|
|
- blocking_thread_detected = False
|
|
- irq_interference_detected = True
|
|
- softirq_interference_detected = False
|
|
- elif line.startswith("Softirq interference"):
|
|
- softirq_interference_percent = fields[-2].strip('(')
|
|
- self._log(Log.DEBUG, f"softirq_interference_percent = {softirq_interference_percent}")
|
|
- softirq_interference = fields[-4]
|
|
- self._log(Log.DEBUG, f"softirq_interference = {softirq_interference}")
|
|
- self.__stdata[self.stcpu]["Softirq_interference"] = (softirq_interference, softirq_interference_percent)
|
|
- blocking_thread_detected = False
|
|
- irq_interference_detected = False
|
|
- softirq_interference_detected = True
|
|
- elif blocking_thread_detected:
|
|
- self._log(Log.DEBUG, f'line={line}')
|
|
- blocking_thread = " ".join(fields[0:-2])
|
|
- self._log(Log.DEBUG, f"blocking_thread = {blocking_thread}")
|
|
- blocking_threadus = fields[-2]
|
|
- self._log(Log.DEBUG, f"blocking_threadus = {blocking_threadus}")
|
|
- self.__stdata[self.stcpu].setdefault("blocking_thread", [])
|
|
- self.__stdata[self.stcpu]["blocking_thread"] += [(blocking_thread, blocking_threadus)]
|
|
- elif softirq_interference_detected:
|
|
- softirq = " ".join(fields[0:-2])
|
|
- softirq_latency = fields[-2]
|
|
- self._log(Log.DEBUG, f'softirq = {softirq}')
|
|
- self._log(Log.DEBUG, f'softirq_latency = {softirq_latency}')
|
|
- self.__stdata[self.stcpu].setdefault("softirq_interference", [])
|
|
- self.__stdata[self.stcpu]["softirq_interference"] += [(softirq, softirq_latency)]
|
|
- elif irq_interference_detected:
|
|
- irq_interference_name = " ".join(fields[0:-2])
|
|
- irq_interference_latency = fields[-2]
|
|
- self._log(Log.DEBUG, f'irq_interference = {irq_interference_name}, latency = {irq_interference_latency}')
|
|
- self.__stdata[self.stcpu].setdefault("irq_interference", [])
|
|
- self.__stdata[self.stcpu]["irq_interference"] += [(irq_interference_name, irq_interference_latency)]
|
|
- elif line.startswith("Max timerlat IRQ latency"):
|
|
- self._log(Log.DEBUG, f"line={line}")
|
|
- max_timerlat_irq_latency = fields[-5]
|
|
- self._log(Log.DEBUG, f"max_timerlat_irq_latency = {max_timerlat_irq_latency}")
|
|
+
|
|
+ # work around rtla not printing ':' after all names
|
|
+ if line.startswith('Softirq interference'):
|
|
+ name = 'Softirq_interference'
|
|
+ elif line.startswith('IRQ interference'):
|
|
+ name = 'IRQ_interference'
|
|
+ else:
|
|
+ name = ''.join(line.split(':')[0]).replace(' ', '_')
|
|
+ self._log(Log.DEBUG, f"name={name}")
|
|
+
|
|
+ if name in ['Thread_latency']:
|
|
+ latency = fields[-3]
|
|
+ percent = fields[-1].strip('()%')
|
|
+ self._log(Log.DEBUG, f'{name} = ({latency}, {percent})')
|
|
+ self.__stdata[self.stcpu][name] = (latency, percent)
|
|
+ continue
|
|
+ if name in ['Timerlat_IRQ_duration', 'IRQ_handler_delay', 'Blocking_thread', 'IRQ_interference', 'Softirq_interference']:
|
|
+ latency = fields[-4]
|
|
+ percent = fields[-2].strip('(')
|
|
+ if name == 'IRQ_handler_delay' and fields[3] == '(exit':
|
|
+ name = 'IRQ_handler_delay_exit_from_idle'
|
|
+ self._log(Log.DEBUG, f'{name} = ({latency}, {percent})')
|
|
+ self.__stdata[self.stcpu][name] = (latency, percent)
|
|
+ detected = {'Blocking_thread' : (True, False, False),
|
|
+ 'IRQ_interference' : (False, True, False),
|
|
+ 'Softirq_interference' : (False, False, True) }
|
|
+ if name in ('Blocking_thread', 'IRQ_interference', 'Softirq_interference'):
|
|
+ blocking_thread_detected, irq_interference_detected, softirq_interference_detected = detected.get(name)
|
|
+ continue
|
|
+ if name in ["IRQ_latency", "Previous_IRQ_interference"]:
|
|
+ latency = fields[-2]
|
|
+ self._log(Log.DEBUG, f'{name} = {fields[-2]}')
|
|
+ self.__stdata[self.stcpu][name] = fields[-2]
|
|
+ continue
|
|
+ if blocking_thread_detected or softirq_interference_detected or irq_interference_detected:
|
|
+ if blocking_thread_detected:
|
|
+ field_name = "blocking_thread"
|
|
+ elif softirq_interference_detected:
|
|
+ field_name = "softirq_interference"
|
|
+ elif irq_interference_detected:
|
|
+ field_name = "irq_interference"
|
|
+ thread = " ".join(fields[0:-2])
|
|
+ latency = fields[-2]
|
|
+ self._log(Log.DEBUG, f"{field_name} += [({thread}, {latency})]")
|
|
+ self.__stdata[self.stcpu].setdefault(field_name, [])
|
|
+ self.__stdata[self.stcpu][field_name] += [(thread, latency)]
|
|
+ continue
|
|
+ if name == "Max_timerlat_IRQ_latency_from_idle":
|
|
+ latency = fields[-5]
|
|
max_timerlat_cpu = int(fields[-1])
|
|
- self._log(Log.DEBUG, f"max_timerlat_cpu = {max_timerlat_cpu}")
|
|
+ self._log(Log.DEBUG, f'self.__stdata[{max_timerlat_cpu}][{name}] = {latency}')
|
|
self.__stdata.setdefault(max_timerlat_cpu, {})
|
|
- self.__stdata[max_timerlat_cpu]["Max_timerlat_IRQ_latency_from_idle"] = max_timerlat_irq_latency
|
|
+ self.__stdata[max_timerlat_cpu][name] = latency
|
|
else:
|
|
self._log(Log.DEBUG, f'line = {line}')
|
|
continue
|
|
diff --git a/rteval/rteval_text.xsl b/rteval/rteval_text.xsl
|
|
index 70777354efa5..7ca0ae3a4c66 100644
|
|
--- a/rteval/rteval_text.xsl
|
|
+++ b/rteval/rteval_text.xsl
|
|
@@ -546,16 +546,16 @@
|
|
<xsl:text>)
|
|
</xsl:text>
|
|
|
|
- <xsl:if test="Blocking_Thread">
|
|
+ <xsl:if test="Blocking_thread">
|
|
<xsl:text>Blocking thread:</xsl:text>
|
|
<xsl:text> </xsl:text>
|
|
- <xsl:value-of select="Blocking_Thread/latency"/>
|
|
+ <xsl:value-of select="Blocking_thread/latency"/>
|
|
<xsl:text> </xsl:text>
|
|
- <xsl:value-of select="Blocking_Thread/latency/@unit"/>
|
|
+ <xsl:value-of select="Blocking_thread/latency/@unit"/>
|
|
<xsl:text> (</xsl:text>
|
|
- <xsl:value-of select="Blocking_Thread/latency_percent"/>
|
|
+ <xsl:value-of select="Blocking_thread/latency_percent"/>
|
|
<xsl:text> </xsl:text>
|
|
- <xsl:value-of select="Blocking_Thread/latency_percent/@unit"/>
|
|
+ <xsl:value-of select="Blocking_thread/latency_percent/@unit"/>
|
|
<xsl:text>)
|
|
</xsl:text>
|
|
</xsl:if>
|
|
--
|
|
2.45.2
|
|
|