rcutorture: Make scripts analyze rcuperf trace data, if present

The rcuperf event-trace data is more accurate than are the rcuperf
printk()s because locking keeps things ordered.  This commit therefore
parses and analyzes this event-trace data if present, and falls back on
the printk()s otherwise.

Signed-off-by: Paul E. McKenney <paulmck@linux.vnet.ibm.com>

diff --git a/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf-ftrace.sh b/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf-ftrace.sh
new file mode 100755 (executable)
index 0000000..f79b0e9
--- /dev/null
+++ b/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf-ftrace.sh
@@ -0,0 +1,121 @@
+#!/bin/bash
+#
+# Analyze a given results directory for rcuperf performance measurements,
+# looking for ftrace data.  Exits with 0 if data was found, analyzed, and
+# printed.  Intended to be invoked from kvm-recheck-rcuperf.sh after
+# argument checking.
+#
+# Usage: kvm-recheck-rcuperf-ftrace.sh resdir
+#
+# This program is free software; you can redistribute it and/or modify
+# it under the terms of the GNU General Public License as published by
+# the Free Software Foundation; either version 2 of the License, or
+# (at your option) any later version.
+#
+# This program is distributed in the hope that it will be useful,
+# but WITHOUT ANY WARRANTY; without even the implied warranty of
+# MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+# GNU General Public License for more details.
+#
+# You should have received a copy of the GNU General Public License
+# along with this program; if not, you can access it online at
+# http://www.gnu.org/licenses/gpl-2.0.html.
+#
+# Copyright (C) IBM Corporation, 2016
+#
+# Authors: Paul E. McKenney <paulmck@linux.vnet.ibm.com>
+
+i="$1"
+. tools/testing/selftests/rcutorture/bin/functions.sh
+
+if test "`grep -c 'rcu_exp_grace_period.*start' < $i/console.log`" -lt 100
+then
+       exit 10
+fi
+
+sed -e 's/^\[[^]]*]//' < $i/console.log |
+grep 'us : rcu_exp_grace_period' |
+sed -e 's/us : / : /' |
+tr -d '\015' |
+awk '
+$8 == "start" {
+       if (starttask != "")
+               nlost++;
+       starttask = $1;
+       starttime = $3;
+       startseq = $7;
+}
+
+$8 == "end" {
+       if (starttask == $1 && startseq == $7) {
+               curgpdur = $3 - starttime;
+               gptimes[++n] = curgpdur;
+               gptaskcnt[starttask]++;
+               sum += curgpdur;
+               if (curgpdur > 1000)
+                       print "Long GP " starttime "us to " $3 "us (" curgpdur "us)";
+               starttask = "";
+       } else {
+               # Lost a message or some such, reset.
+               starttask = "";
+               nlost++;
+       }
+}
+
+$8 == "done" {
+       piggybackcnt[$1]++;
+}
+
+END {
+       newNR = asort(gptimes);
+       if (newNR <= 0) {
+               print "No ftrace records found???"
+               exit 10;
+       }
+       pct50 = int(newNR * 50 / 100);
+       if (pct50 < 1)
+               pct50 = 1;
+       pct90 = int(newNR * 90 / 100);
+       if (pct90 < 1)
+               pct90 = 1;
+       pct99 = int(newNR * 99 / 100);
+       if (pct99 < 1)
+               pct99 = 1;
+       div = 10 ** int(log(gptimes[pct90]) / log(10) + .5) / 100;
+       print "Histogram bucket size: " div;
+       last = gptimes[1] - 10;
+       count = 0;
+       for (i = 1; i <= newNR; i++) {
+               current = div * int(gptimes[i] / div);
+               if (last == current) {
+                       count++;
+               } else {
+                       if (count > 0)
+                               print last, count;
+                       count = 1;
+                       last = current;
+               }
+       }
+       if (count > 0)
+               print last, count;
+       print "Distribution of grace periods across tasks:";
+       for (i in gptaskcnt) {
+               print "\t" i, gptaskcnt[i];
+               nbatches += gptaskcnt[i];
+       }
+       ngps = nbatches;
+       print "Distribution of piggybacking across tasks:";
+       for (i in piggybackcnt) {
+               print "\t" i, piggybackcnt[i];
+               ngps += piggybackcnt[i];
+       }
+       print "Average grace-period duration: " sum / newNR " microseconds";
+       print "Minimum grace-period duration: " gptimes[1];
+       print "50th percentile grace-period duration: " gptimes[pct50];
+       print "90th percentile grace-period duration: " gptimes[pct90];
+       print "99th percentile grace-period duration: " gptimes[pct99];
+       print "Maximum grace-period duration: " gptimes[newNR];
+       print "Grace periods: " ngps + 0 " Batches: " nbatches + 0 " Ratio: " ngps / nbatches " Lost: " nlost + 0;
+       print "Computed from ftrace data.";
+}'
+exit 0

diff --git a/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf.sh b/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf.sh
index 1f72df8eedc74f81f1530be4718d8e9e8f0e1ad6..8f3121afc716d4d5e0295b501d76bb9e662d76d8 100755 (executable)
--- a/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf.sh
+++ b/tools/testing/selftests/rcutorture/bin/kvm-recheck-rcuperf.sh
@@ -30,8 +30,15 @@ else
        echo Unreadable results directory: $i
        exit 1
 fi
+PATH=`pwd`/tools/testing/selftests/rcutorture/bin:$PATH; export PATH
 . tools/testing/selftests/rcutorture/bin/functions.sh
 
+if kvm-recheck-rcuperf-ftrace.sh $i
+then
+       # ftrace data was successfully analyzed, call it good!
+       exit 0
+fi
+
 configfile=`echo $i | sed -e 's/^.*\///'`
 
 sed -e 's/^\[[^]]*]//' < $i/console.log |
@@ -85,4 +92,5 @@ END {
        print "99th percentile grace-period duration: " gptimes[pct99];
        print "Maximum grace-period duration: " gptimes[newNR];
        print "Grace periods: " ngps + 0 " Batches: " nbatches + 0 " Ratio: " ngps / nbatches;
+       print "Computed from rcuperf printk output.";
 }'