[PATCH 0/3] rteval: Fix issues with cyclictest.py module

[PATCH 0/3] rteval: Fix issues with cyclictest.py module

[Punit Agrawal]

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

[PATCH 1/3] rteval: cyclictest.py Enable logging cyclictest output

[Punit Agrawal]

From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>

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.

Signed-off-by: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
---
 rteval/modules/measurement/cyclictest.py | 5 ++++-
 1 file changed, 4 insertions(+), 1 deletion(-)

diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
index b1755d4f4421..0037c3ad07bd 100644
--- a/rteval/modules/measurement/cyclictest.py
+++ b/rteval/modules/measurement/cyclictest.py
@@ -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

Re: [PATCH 1/3] rteval: cyclictest.py Enable logging cyclictest output

[John Kacur]

On Thu, 2 Sep 2021, Punit Agrawal wrote:

> From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> 
> 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.
> 
> Signed-off-by: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> ---
>  rteval/modules/measurement/cyclictest.py | 5 ++++-
>  1 file changed, 4 insertions(+), 1 deletion(-)
> 
> diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
> index b1755d4f4421..0037c3ad07bd 100644
> --- a/rteval/modules/measurement/cyclictest.py
> +++ b/rteval/modules/measurement/cyclictest.py
> @@ -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

[PATCH 2/3] rteval: cyclictest.py Parse max latencies from cyclictest ouput

[Punit Agrawal]

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.

Signed-off-by: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
---
 rteval/modules/measurement/cyclictest.py | 31 +++++++++++++++++++-----
 1 file changed, 25 insertions(+), 6 deletions(-)

diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
index 0037c3ad07bd..67a2eab21d7c 100644
--- a/rteval/modules/measurement/cyclictest.py
+++ b/rteval/modules/measurement/cyclictest.py
@@ -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

[PATCH 3/3] rteval: misc.py: Sort the list of cpus returned by online_cpus()

[Punit Agrawal]

From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>

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.

Signed-off-by: Punit Agrawal <punitagrawal@gmail.com>
---
 rteval/misc.py | 1 +
 1 file changed, 1 insertion(+)

diff --git a/rteval/misc.py b/rteval/misc.py
index 0dd361ff19fd..ec3641e4a013 100644
--- a/rteval/misc.py
+++ b/rteval/misc.py
@@ -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

Re: [PATCH 3/3] rteval: misc.py: Sort the list of cpus returned by online_cpus()

[John Kacur]

On Thu, 2 Sep 2021, Punit Agrawal wrote:

> From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> 
> 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.
> 
> Signed-off-by: Punit Agrawal <punitagrawal@gmail.com>
> ---
>  rteval/misc.py | 1 +
>  1 file changed, 1 insertion(+)
> 
> diff --git a/rteval/misc.py b/rteval/misc.py
> index 0dd361ff19fd..ec3641e4a013 100644
> --- a/rteval/misc.py
> +++ b/rteval/misc.py
> @@ -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

Re: [PATCH 0/3] rteval: Fix issues with cyclictest.py module

[Punit Agrawal]

Punit Agrawal <punitagrawal@gmail.com> writes:

[...]

> 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.

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

[...]