[PATCH 8/9] kvm-userspace: kvmtrace_format: add statistic section

ehrhardt
2008-07-10T10:56:05Z

Usually people don't want to read thousands of trace log lines to interpret
the data, a condensed statistic about the traced events is usually better
to read.
This patch adds a new command line switch -s that tells kvmtrace_format to
generate statistics while processing the trace records. Those statistics are
then printed at the end of the output.
This patch contains a statistic function for the ppc instruction emulation.
An example output might look like that:

mnemonic + count
---------------+-----------
wrteei | 1260
mfmsr | 977
mtspr | 895
wrtee | 742
mfspr | 534
rfi | 179
mtmsr | 90
lbz | 53
stb | 28
sum = 4758
[...] more detailed statistics about spr, dcr and tlb usage

Signed-off-by: Christian Ehrhardt <ehrhardt@linux.vnet.ibm.com>
---

[diffstat]
kvmtrace_format | 73 +++++++++++++++++++++++++++++++++++++++++++++++++++-----
1 file changed, 67 insertions(+), 6 deletions(-)

[diff]
diff --git a/user/kvmtrace_format b/user/kvmtrace_format
--- a/user/kvmtrace_format
+++ b/user/kvmtrace_format
@@ -4,7 +4,7 @@

# Program for reformatting trace buffer output according to user-supplied rules

-import re, sys, string, signal, struct, os, getopt
+import re, sys, string, signal, struct, os, getopt, operator

def usage():
print >> sys.stderr, \
@@ -29,6 +29,12 @@
this script may not be able to keep up with the output of kvmtrace
if it is piped directly. In these circumstances you should have
kvmtrace output to a file for processing off-line.
+
+ kvmtrace_format has the following additional switches
+ -c mhz - specifies the mhz of the traced machine used to convert
+ cycle data in trace records into time
+ -s - if this switch is set additional trace statistics are
+ created and printed at the end of the output
"""
sys.exit(1)

@@ -60,6 +66,33 @@
interrupted = 1

# ppc instruction decoding for event type 0x00020019 (PPC_INSTR)
+# some globals for statistic summaries
+stat_ppc_instr_mnemonic = {};
+stat_ppc_instr_spr = {};
+stat_ppc_instr_dcr = {};
+stat_ppc_instr_tlb = {};
+
+def ppc_instr_print_summary(sortedlist, colname):
+ print "\n\n%14s + %10s" % (colname, "count")
+ print "%s" % (15*"-"+"+"+11*"-")
+ sum = 0
+ for value, key in sortedlist:
+ sum += key
+ print "%14s | %10d" % (value, key)
+ print "%14s = %10d" % ("sum", sum)
+
+
+def ppc_instr_summary():
+ # don't print empty statistics
+ if stat_ppc_instr_mnemonic:
+ ppc_instr_print_summary(sorted(stat_ppc_instr_mnemonic.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic")
+ if stat_ppc_instr_spr:
+ ppc_instr_print_summary(sorted(stat_ppc_instr_spr.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic-spr")
+ if stat_ppc_instr_dcr:
+ ppc_instr_print_summary(sorted(stat_ppc_instr_dcr.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic-dcr")
+ if stat_ppc_instr_tlb:
+ ppc_instr_print_summary(sorted(stat_ppc_instr_tlb.iteritems(), key=operator.itemgetter(1), reverse=True), "mnemonic-tlb")
+
def get_op(instr):
return (instr >> 26);

@@ -293,28 +326,53 @@
return "UNKNOWN"

def get_special(instr):
+ name = get_name(instr);
+ if stat_ppc_instr_mnemonic.has_key(name):
+ stat_ppc_instr_mnemonic[name] += 1
+ else:
+ stat_ppc_instr_mnemonic[name] = 1
+
if get_op(instr) == 31:
if (get_xop(instr) == 339) or (get_xop(instr) == 467):
sprn = get_sprn(instr);
- return ("- sprn 0x%03x %8s" % (sprn, get_sprn_name(sprn)))
+ sprn_name = get_sprn_name(sprn);
+ stat_idx = name+"-"+sprn_name
+ if stat_ppc_instr_spr.has_key(stat_idx):
+ stat_ppc_instr_spr[stat_idx] += 1
+ else:
+ stat_ppc_instr_spr[stat_idx] = 1
+ return ("- sprn 0x%03x %8s" % (sprn, sprn_name))
elif (get_xop(instr) == 323 ) or (get_xop(instr) == 451):
- return ("- dcrn 0x%03x" % get_dcrn(instr))
+ dcrn = get_dcrn(instr);
+ stat_idx = name+"-"+("%04X"%dcrn)
+ if stat_ppc_instr_dcr.has_key(stat_idx):
+ stat_ppc_instr_dcr[stat_idx] += 1
+ else:
+ stat_ppc_instr_dcr[stat_idx] = 1
+ return ("- dcrn 0x%03x" % dcrn)
elif (get_xop(instr) == 978 ) or (get_xop(instr) == 451):
- return ("- ws -> %8s" % get_tlbwe_type(instr))
+ tlbwe_type = get_tlbwe_type(instr)
+ stat_idx = name+"-"+tlbwe_type
+ if stat_ppc_instr_tlb.has_key(stat_idx):
+ stat_ppc_instr_tlb[stat_idx] += 1
+ else:
+ stat_ppc_instr_tlb[stat_idx] = 1
+ return ("- ws -> %8s" % tlbwe_type)
return ""

##### Main code

mhz = 0
+summary = False

if len(sys.argv) < 2:
usage()

try:
- opts, arg = getopt.getopt(sys.argv[1:], "c:" )
-
+ opts, arg = getopt.getopt(sys.argv[1:], "sc:" )
for opt in opts:
if opt[0] == '-c' : mhz = int(opt[1])
+ if opt[0] == '-s' : summary = True

except getopt.GetoptError:
usage()
@@ -471,3 +529,6 @@
print args

except IOError, struct.error: sys.exit()
+
+if summary:
+ ppc_instr_summary()