[PATCH v3 0/4] rteval: Fix issues with cyclictest module

[PATCH v3 0/4] rteval: Fix issues with cyclictest module

[Punit Agrawal]

Hi,

Here's an updated version of the cyclictest fixes previously posted at
[0]. In addition, I've included a follow-up patch[1] that depends on
the previous patches in the series as well.

The combined changelog - 

v2 -> v3:
* Patch 1-3 - no change
* Patch 4 - updated author / Signed-off-by

The patches have been on the list for a few weeks now. It would be
great to see them merged if there are no issues.

Thanks,
Punit

[0] https://lore.kernel.org/all/20210917085343.2775300-1-punitagrawal@gmail.com/

Punit Agrawal (4):
  rteval: cyclictest.py Enable logging cyclictest output
  rteval: cyclictest.py Parse max latencies from cyclictest output
  rteval: cyclictest.py: Sort the list of cpus
  rteval: cyclictest.py: Skip statistics reporting in case of an
    overflow

 rteval/modules/measurement/cyclictest.py | 54 +++++++++++++++++++++---
 1 file changed, 47 insertions(+), 7 deletions(-)

-- 
2.33.0

[PATCH v3 1/4] 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 information that can be useful for development
or debugging, having the ability to persist the logs is useful.

With this goal, introduce a configuration option for the cyclictest.py
module, "savelogs", that can be used to enable persisting the
cyclictest output to a logfile. As the logs an be quite large, the
default is to not save them.

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

diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
index b1755d4f4421..ee1de883d844 100644
--- a/rteval/modules/measurement/cyclictest.py
+++ b/rteval/modules/measurement/cyclictest.py
@@ -197,6 +197,8 @@ 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.__save_logs = self.__cfg.setdefault('savelogs', False)
         self.__numcores = 0
         self.__cpus = []
         self.__cyclicdata = {}
@@ -255,6 +257,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 +292,10 @@ class Cyclictest(rtevalModulePrototype):
             self.__cmd.append("--tracemark")
 
         # Buffer for cyclictest data written to stdout
-        self.__cyclicoutput = tempfile.SpooledTemporaryFile(mode='w+b')
+        if self.__save_logs:
+            self.__cyclicoutput = self._open_logfile('cyclictest.stdout')
+        else:
+            self.__cyclicoutput = tempfile.SpooledTemporaryFile(mode='w+b')
 
 
     def _WorkloadTask(self):
-- 
2.33.0

[PATCH v3 2/4] rteval: cyclictest.py Parse max latencies from cyclictest output

[Punit Agrawal]

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

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 ee1de883d844..d3a0b045b9dd 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):
@@ -332,6 +337,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
@@ -348,6 +365,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.33.0

[PATCH v3 3/4] rteval: cyclictest.py: Sort the list of 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
used by cyclictest.py module. 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 <punit1.agrawal@toshiba.co.jp>
---
 rteval/modules/measurement/cyclictest.py | 4 ++++
 1 file changed, 4 insertions(+)

diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
index d3a0b045b9dd..50a734c75047 100644
--- a/rteval/modules/measurement/cyclictest.py
+++ b/rteval/modules/measurement/cyclictest.py
@@ -216,6 +216,10 @@ class Cyclictest(rtevalModulePrototype):
         else:
             self.__cpus = online_cpus()
 
+        # Sort the list of cpus to align with the order reported by
+        # cyclictest
+        self.__cpus.sort(key=int)
+
         # Get the cpuset from the environment
         cpuset = os.sched_getaffinity(0)
 
-- 
2.33.0

[PATCH v3 4/4] rteval: cyclictest.py: Skip statistics reporting in case of an overflow

[Punit Agrawal]

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

The cyclictest.py module recently gained the capability to parse max
latency values as reported by cyclictest.

When the max latency exceeds the range of the latency histogram (or in
other words, the number of configured buckets), statistics such as
mean and standard deviation can not be calculated correctly due to
lost samples during measurement.

In the case of lost samples, skip statistics generation and report the
max latency warning the user to rerun the measurement.

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

diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
index 50a734c75047..7a619dd1c852 100644
--- a/rteval/modules/measurement/cyclictest.py
+++ b/rteval/modules/measurement/cyclictest.py
@@ -67,6 +67,9 @@ class RunData:
         retval += "mean:       %f\n" % self.__mean
         return retval
 
+    def get_max(self):
+        return self.__max
+
     def update_max(self, value):
         if value > self.__max:
             self.__max = value
@@ -423,6 +426,13 @@ class Cyclictest(rtevalModulePrototype):
         if abrt:
             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:
+            self._log(Log.ERR, "Max latency(%dus) exceeded histogram range(%dus). Skipping statistics" %
+                      (self.__cyclicdata["system"].get_max(), self.__buckets))
+            self._log(Log.ERR, "Increase number of buckets to avoid lost samples")
+            return rep_n
+
         rep_n.addChild(self.__cyclicdata["system"].MakeReport())
         for thr in self.__cpus:
             if str(thr) not in self.__cyclicdata:
-- 
2.33.0

Re: [PATCH v3 2/4] rteval: cyclictest.py Parse max latencies from cyclictest output

[John Kacur]

On Mon, 18 Oct 2021, Punit Agrawal wrote:

> From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> 
> 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 ee1de883d844..d3a0b045b9dd 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):
> @@ -332,6 +337,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
> @@ -348,6 +365,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.33.0
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

Thanks!

Re: [PATCH v3 3/4] rteval: cyclictest.py: Sort the list of cpus

[John Kacur]

On Mon, 18 Oct 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
> used by cyclictest.py module. 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 <punit1.agrawal@toshiba.co.jp>
> ---
>  rteval/modules/measurement/cyclictest.py | 4 ++++
>  1 file changed, 4 insertions(+)
> 
> diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
> index d3a0b045b9dd..50a734c75047 100644
> --- a/rteval/modules/measurement/cyclictest.py
> +++ b/rteval/modules/measurement/cyclictest.py
> @@ -216,6 +216,10 @@ class Cyclictest(rtevalModulePrototype):
>          else:
>              self.__cpus = online_cpus()
>  
> +        # Sort the list of cpus to align with the order reported by
> +        # cyclictest
> +        self.__cpus.sort(key=int)
> +
>          # Get the cpuset from the environment
>          cpuset = os.sched_getaffinity(0)
>  
> -- 
> 2.33.0
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

Re: [PATCH v3 4/4] rteval: cyclictest.py: Skip statistics reporting in case of an overflow

[John Kacur]

On Mon, 18 Oct 2021, Punit Agrawal wrote:

> From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> 
> The cyclictest.py module recently gained the capability to parse max
> latency values as reported by cyclictest.
> 
> When the max latency exceeds the range of the latency histogram (or in
> other words, the number of configured buckets), statistics such as
> mean and standard deviation can not be calculated correctly due to
> lost samples during measurement.
> 
> In the case of lost samples, skip statistics generation and report the
> max latency warning the user to rerun the measurement.
> 
> Signed-off-by: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> ---
>  rteval/modules/measurement/cyclictest.py | 10 ++++++++++
>  1 file changed, 10 insertions(+)
> 
> diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
> index 50a734c75047..7a619dd1c852 100644
> --- a/rteval/modules/measurement/cyclictest.py
> +++ b/rteval/modules/measurement/cyclictest.py
> @@ -67,6 +67,9 @@ class RunData:
>          retval += "mean:       %f\n" % self.__mean
>          return retval
>  
> +    def get_max(self):
> +        return self.__max
> +
>      def update_max(self, value):
>          if value > self.__max:
>              self.__max = value
> @@ -423,6 +426,13 @@ class Cyclictest(rtevalModulePrototype):
>          if abrt:
>              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:
> +            self._log(Log.ERR, "Max latency(%dus) exceeded histogram range(%dus). Skipping statistics" %
> +                      (self.__cyclicdata["system"].get_max(), self.__buckets))
> +            self._log(Log.ERR, "Increase number of buckets to avoid lost samples")
> +            return rep_n
> +
>          rep_n.addChild(self.__cyclicdata["system"].MakeReport())
>          for thr in self.__cpus:
>              if str(thr) not in self.__cyclicdata:
> -- 
> 2.33.0
> 
> 
Signed-off-by: John Kacur <jkacur@redhat.com>

Re: [PATCH v3 4/4] rteval: cyclictest.py: Skip statistics reporting in case of an overflow

[Punit Agrawal]

Hi John,

John Kacur <jkacur@redhat.com> writes:

> On Mon, 18 Oct 2021, Punit Agrawal wrote:
>
>> From: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
>> 
>> The cyclictest.py module recently gained the capability to parse max
>> latency values as reported by cyclictest.
>> 
>> When the max latency exceeds the range of the latency histogram (or in
>> other words, the number of configured buckets), statistics such as
>> mean and standard deviation can not be calculated correctly due to
>> lost samples during measurement.
>> 
>> In the case of lost samples, skip statistics generation and report the
>> max latency warning the user to rerun the measurement.
>> 
>> Signed-off-by: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
>> ---
>>  rteval/modules/measurement/cyclictest.py | 10 ++++++++++
>>  1 file changed, 10 insertions(+)
>> 
>> diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
>> index 50a734c75047..7a619dd1c852 100644
>> --- a/rteval/modules/measurement/cyclictest.py
>> +++ b/rteval/modules/measurement/cyclictest.py
>> @@ -67,6 +67,9 @@ class RunData:
>>          retval += "mean:       %f\n" % self.__mean
>>          return retval
>>  
>> +    def get_max(self):
>> +        return self.__max
>> +
>>      def update_max(self, value):
>>          if value > self.__max:
>>              self.__max = value
>> @@ -423,6 +426,13 @@ class Cyclictest(rtevalModulePrototype):
>>          if abrt:
>>              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:
>> +            self._log(Log.ERR, "Max latency(%dus) exceeded histogram range(%dus). Skipping statistics" %
>> +                      (self.__cyclicdata["system"].get_max(), self.__buckets))
>> +            self._log(Log.ERR, "Increase number of buckets to avoid lost samples")
>> +            return rep_n
>> +
>>          rep_n.addChild(self.__cyclicdata["system"].MakeReport())
>>          for thr in self.__cpus:
>>              if str(thr) not in self.__cyclicdata:
>> -- 
>> 2.33.0
>> 
>> 
> Signed-off-by: John Kacur <jkacur@redhat.com>

Thank you for picking this and other patches in the set.

Let me know if you had any comments on the first patch.

Thanks,
Punit

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

[Punit Agrawal]

Punit Agrawal <punitagrawal@gmail.com> writes:

> 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 information that can be useful for development
> or debugging, having the ability to persist the logs is useful.
>
> With this goal, introduce a configuration option for the cyclictest.py
> module, "savelogs", that can be used to enable persisting the
> cyclictest output to a logfile. As the logs an be quite large, the
> default is to not save them.
>
> Signed-off-by: Punit Agrawal <punit1.agrawal@toshiba.co.jp>
> ---
>  rteval/modules/measurement/cyclictest.py | 9 ++++++++-
>  1 file changed, 8 insertions(+), 1 deletion(-)
>
> diff --git a/rteval/modules/measurement/cyclictest.py b/rteval/modules/measurement/cyclictest.py
> index b1755d4f4421..ee1de883d844 100644
> --- a/rteval/modules/measurement/cyclictest.py
> +++ b/rteval/modules/measurement/cyclictest.py
> @@ -197,6 +197,8 @@ 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.__save_logs = self.__cfg.setdefault('savelogs', False)
>          self.__numcores = 0
>          self.__cpus = []
>          self.__cyclicdata = {}
> @@ -255,6 +257,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 +292,10 @@ class Cyclictest(rtevalModulePrototype):
>              self.__cmd.append("--tracemark")
>  
>          # Buffer for cyclictest data written to stdout
> -        self.__cyclicoutput = tempfile.SpooledTemporaryFile(mode='w+b')
> +        if self.__save_logs:
> +            self.__cyclicoutput = self._open_logfile('cyclictest.stdout')
> +        else:
> +            self.__cyclicoutput = tempfile.SpooledTemporaryFile(mode='w+b')
>  
>  
>      def _WorkloadTask(self):

Ping!

This patch was missed when reviewing / merging the other patches in the
series. Please consider merging if there are no issues.

Thanks.

(and apologies for the extra messages)