rteval: Fix issues with cyclictest.py module

Hi,

A few areas of improvements to the cyclictest module were noted while using rteval to evaluate latencies. The following small set of patches address these.

The first patch persists the output of "cyclictest" - which is helpful in getting more information than what is reported by rteval. It can also help sanity check rteval output when needed.

The second patch uses the max latencies reported by cyclictest vs only relying on the histogram latencies.

The third patch fixes the ordering of reported latencies.

All feedback welcome.

Thanks,
Punit

Punit Agrawal (3):
rteval: cyclictest.py Enable logging cyclictest output
rteval: cyclictest.py Parse max latencies from cyclictest ouput
rteval: misc.py: Sort the list of cpus returned by online_cpus()

 rteval/misc.py                           |  1 +
 rteval/modules/measurement/cyclictest.py | 36 +++++++++++++++++++-----
 2 files changed, 30 insertions(+), 7 deletions(-)

2.32.0

From: Punit Agrawal <[email protected]>

The cyclictest.py module uses a temporary file to store the output from "cyclictest" which is deleted at the end of the run. As the collected log contains more information than what is being reported by rteval it would make sense to persist the logs. It can also be useful to sanity check the results reported by rteval.

With this goal, create a persistent file named "cyclictest.stdout" (instead of a tempfile) to capture the cyclictest logs. The file is stored in the same location as the logs from the other modules.

---
 rteval/modules/measurement/cyclictest.py | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

index b1755d4f4421..0037c3ad07bd 100644
@@ -197,6 +197,7 @@ class Cyclictest(rtevalModulePrototype):
         self.__numanodes = int(self.__cfg.setdefault('numanodes', 0))
         self.__priority = int(self.__cfg.setdefault('priority', 95))
         self.__buckets = int(self.__cfg.setdefault('buckets', 2000))
+        self.__reportdir = self.__cfg.setdefault('reportdir', os.getcwd())
         self.__numcores = 0
         self.__cpus = []
         self.__cyclicdata = {}

@@ -255,6 +256,8 @@ class Cyclictest(rtevalModulePrototype):
         mounts.close()
         return ret
 
+    def _open_logfile(self, name):
+        return open(os.path.join(self.__reportdir, "logs", name), 'w+b')
 
     def _WorkloadSetup(self):
         self.__cyclicprocess = None

@@ -288,7 +291,7 @@ class Cyclictest(rtevalModulePrototype):
             self.__cmd.append("--tracemark")
 
         # Buffer for cyclictest data written to stdout
-        self.__cyclicoutput = tempfile.SpooledTemporaryFile(mode='w+b')
+        self.__cyclicoutput = self._open_logfile('cyclictest.stdout')
 
 
     def _WorkloadTask(self):

2.32.0

This is the kind of information that is interesting to developers of rteval, but is less interesting to general users who are simply testing whether their machines are capable of being used for realtime performance. For these people, this would just create large files to be deleted.

I would consider this perhaps with a command line flag explaining this is an option for rteval developers.

John

When collecting a histogram of latencies, "cyclictest" reports the maximum latency encountered on each core even if they fall outside the configured no. of buckets. This can be useful to understand the worst case latencies for the run as well as right sizing the number of buckets for the histogram.

While processing the output of cyclictest, rteval skips the reported max latencies and calculates them by capping to the no. of buckets.

Fix rteval by parsing the maximum latencies reported by cyclictest.

---
 rteval/modules/measurement/cyclictest.py | 31 +++++++++++++++++++-----
 1 file changed, 25 insertions(+), 6 deletions(-)

index 0037c3ad07bd..67a2eab21d7c 100644
@@ -67,20 +67,25 @@ class RunData:
         retval += "mean:       %f\n" % self.__mean
         return retval
 
-    def sample(self, value):
-        self.__samples[value] += self.__samples.setdefault(value, 0) + 1
+    def update_max(self, value):
         if value > self.__max:
             self.__max = value
+
+    def update_min(self, value):
         if value < self.__min:
             self.__min = value
+
+    def sample(self, value):
+        self.__samples[value] += self.__samples.setdefault(value, 0) + 1
+        self.update_max(value)
+        self.update_min(value)
         self.__numsamples += 1
 
     def bucket(self, index, value):
         self.__samples[index] = self.__samples.setdefault(index, 0) + value
-        if value and index > self.__max:
-            self.__max = index
-        if value and index < self.__min:
-            self.__min = index
+        if value:
+            self.update_max(index)
+            self.update_min(index)
         self.__numsamples += value
 
     def reduce(self):

@@ -328,6 +333,18 @@ class Cyclictest(rtevalModulePrototype):
         return False
 
 
+    def _parse_max_latencies(self, line):
+        if not line.startswith('# Max Latencies: '):
+            return
+
+        line = line.split(':')[1]
+        vals = [int(x) for x in line.split()]
+
+        for i, core in enumerate(self.__cpus):
+            self.__cyclicdata[core].update_max(vals[i])
+            self.__cyclicdata['system'].update_max(vals[i])
+
+
     def _WorkloadCleanup(self):
         if not self.__started:
             return

@@ -344,6 +361,8 @@ class Cyclictest(rtevalModulePrototype):
                 # Catch if cyclictest stopped due to a breaktrace
                 if line.startswith('# Break value: '):
                     self.__breaktraceval = int(line.split(':')[1])
+                elif line.startswith('# Max Latencies: '):
+                    self._parse_max_latencies(line)
                 continue
 
             # Skipping blank lines

2.32.0

From: Punit Agrawal <[email protected]>

online_cpus() returns a list of online cpus in arbitrary order. e.g., on a hexacore system it returns -

    ['5', '3', '1', '4', '2', '0']

Generally this wouldn't be a problem but the cyclictest.py module matches the unsorted list with the latencies output by "cyclictest" which are ordered by core number. This leads to incorrect reporting of per-core latencies in the final report generated by rteval. The issue was noticed when comparing the rteval report with cyclictest logs (enabled by a recent change).

Fix the inconsistency in core numbering by sorting the list of cpus returned by online_cpus(). As the cpus are represented as a string, sort with the integer key to avoid issues on systems with large number of cores.

---
 rteval/misc.py | 1 +
 1 file changed, 1 insertion(+)

index 0dd361ff19fd..ec3641e4a013 100644
@@ -53,6 +53,7 @@ def online_cpus():
         for c in glob.glob('/sys/devices/system/cpu/cpu[0-9]*'):
             num = str(c.replace('/sys/devices/system/cpu/cpu', ''))
             online_cpus.append(num)
+    online_cpus.sort(key=int)
     return online_cpus
 
 def invert_cpulist(cpulist):

2.32.0

Thanks for finding that. I'm wondering if it makes more sense to sort it in cyclictest.py?

John

Punit Agrawal <[email protected]> writes:

[...]

Just realised that the "From" and "Signed-off-by" in patches 2 and 3 are messed up. I've fixed it up locally - will wait to see if there is any other feedback before resending.

Thanks,
Punit

[...]