#!/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 global i := $1 source tools/testing/selftests/rcutorture/bin/functions.sh if test $[grep -c 'rcu_exp_grace_period.*start' < $i/console.log] -lt 100 { exit 10 } 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 (CommandList children: [ (Assignment keyword: Assign_None pairs: [(assign_pair lhs:(LhsName name:i) op:Equal rhs:{(DQ ($ VSub_Number "$1"))} spids:[79])] spids: [79] ) (C {(.)} {(tools/testing/selftests/rcutorture/bin/functions.sh)}) (If arms: [ (if_arm cond: [ (C {(test)} { (DQ (CommandSubPart command_list: (CommandList children: [ (SimpleCommand words: [{(grep)} {(-c)} {(SQ <"rcu_exp_grace_period.*start">)}] redirects: [ (Redir op_id: Redir_Less fd: -1 arg_word: {($ VSub_Name "$i") (/console.log)} spids: [103] ) ] ) ] ) left_token: spids: [94 107] ) ) } {(-lt)} {(100)} ) ] action: [(C {(exit)} {(10)})] spids: [-1 114] ) ] spids: [-1 121] ) (Pipeline children: [ (SimpleCommand words: [{(sed)} {(-e)} {(SQ <"s/^\\[[^]]*]//">)}] redirects: [ (Redir op_id: Redir_Less fd: -1 arg_word: {($ VSub_Name "$i") (/console.log)} spids: [132] ) ] ) (C {(grep)} {(SQ <"us : rcu_exp_grace_period">)}) (C {(sed)} {(-e)} {(SQ <"s/us : / : /">)}) (C {(tr)} {(-d)} {(SQ <"\\015">)}) (C {(awk)} { (SQ <"\n"> <"$8 == \"start\" {\n"> <"\tif (starttask != \"\")\n"> <"\t\tnlost++;\n"> <"\tstarttask = $1;\n"> <"\tstarttime = $3;\n"> <"\tstartseq = $7;\n"> <"}\n"> <"\n"> <"$8 == \"end\" {\n"> <"\tif (starttask == $1 && startseq == $7) {\n"> <"\t\tcurgpdur = $3 - starttime;\n"> <"\t\tgptimes[++n] = curgpdur;\n"> <"\t\tgptaskcnt[starttask]++;\n"> <"\t\tsum += curgpdur;\n"> <"\t\tif (curgpdur > 1000)\n"> <"\t\t\tprint \"Long GP \" starttime \"us to \" $3 \"us (\" curgpdur \"us)\";\n"> <"\t\tstarttask = \"\";\n"> <"\t} else {\n"> <"\t\t# Lost a message or some such, reset.\n"> <"\t\tstarttask = \"\";\n"> <"\t\tnlost++;\n"> <"\t}\n"> <"}\n"> <"\n"> <"$8 == \"done\" {\n"> <"\tpiggybackcnt[$1]++;\n"> <"}\n"> <"\n"> <"END {\n"> <"\tnewNR = asort(gptimes);\n"> <"\tif (newNR <= 0) {\n"> <"\t\tprint \"No ftrace records found???\"\n"> <"\t\texit 10;\n"> <"\t}\n"> <"\tpct50 = int(newNR * 50 / 100);\n"> <"\tif (pct50 < 1)\n"> <"\t\tpct50 = 1;\n"> <"\tpct90 = int(newNR * 90 / 100);\n"> <"\tif (pct90 < 1)\n"> <"\t\tpct90 = 1;\n"> <"\tpct99 = int(newNR * 99 / 100);\n"> <"\tif (pct99 < 1)\n"> <"\t\tpct99 = 1;\n"> <"\tdiv = 10 ** int(log(gptimes[pct90]) / log(10) + .5) / 100;\n"> <"\tprint \"Histogram bucket size: \" div;\n"> <"\tlast = gptimes[1] - 10;\n"> <"\tcount = 0;\n"> <"\tfor (i = 1; i <= newNR; i++) {\n"> <"\t\tcurrent = div * int(gptimes[i] / div);\n"> <"\t\tif (last == current) {\n"> <"\t\t\tcount++;\n"> <"\t\t} else {\n"> <"\t\t\tif (count > 0)\n"> <"\t\t\t\tprint last, count;\n"> <"\t\t\tcount = 1;\n"> <"\t\t\tlast = current;\n"> <"\t\t}\n"> <"\t}\n"> <"\tif (count > 0)\n"> <"\t\tprint last, count;\n"> <"\tprint \"Distribution of grace periods across tasks:\";\n"> <"\tfor (i in gptaskcnt) {\n"> <"\t\tprint \"\\t\" i, gptaskcnt[i];\n"> <"\t\tnbatches += gptaskcnt[i];\n"> <"\t}\n"> <"\tngps = nbatches;\n"> <"\tprint \"Distribution of piggybacking across tasks:\";\n"> <"\tfor (i in piggybackcnt) {\n"> <"\t\tprint \"\\t\" i, piggybackcnt[i];\n"> <"\t\tngps += piggybackcnt[i];\n"> <"\t}\n"> <"\tprint \"Average grace-period duration: \" sum / newNR \" microseconds\";\n"> <"\tprint \"Minimum grace-period duration: \" gptimes[1];\n"> <"\tprint \"50th percentile grace-period duration: \" gptimes[pct50];\n"> <"\tprint \"90th percentile grace-period duration: \" gptimes[pct90];\n"> <"\tprint \"99th percentile grace-period duration: \" gptimes[pct99];\n"> <"\tprint \"Maximum grace-period duration: \" gptimes[newNR];\n"> < "\tprint \"Grace periods: \" ngps + 0 \" Batches: \" nbatches + 0 \" Ratio: \" ngps / nbatches \" Lost: \" nlost + 0;\n" > <"\tprint \"Computed from ftrace data.\";\n"> <"}"> ) } ) ] negated: False ) (C {(exit)} {(0)}) ] )