[PATCH 9/9] kvm-userspace: kvmtrace: rename cycles to timestamp

ehrhardt
2008-07-10T10:54:27Z

Due to the fact that the cycle counter is now completely replaced by the more
generic time based code (getnstimeofday) this patch renames all occurances of
the old cycle code to make it clear that this is now a timestamp.
Due to some values now growing a big larger (relts) the patch also
increases the print width of those values.

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

[diffstat]
formats | 50 +++++++++++++++++++++++++-------------------------
kvmtrace_format | 41 +++++++++++++++++------------------------
2 files changed, 42 insertions(+), 49 deletions(-)

[diff]

diff --git a/user/formats b/user/formats
--- a/user/formats
+++ b/user/formats
@@ -1,31 +1,31 @@
-0x00000000 %(tsc)d (+%(reltsc)8d) unknown (0x%(event)016x) vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x ]
+0x00000000 %(ts)d (+%(relts)12d) unknown (0x%(event)016x) vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x ]

-0x00010001 %(tsc)d (+%(reltsc)8d) VMENTRY vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
-0x00010002 %(tsc)d (+%(reltsc)8d) VMEXIT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ exitcode = 0x%(1)08x, rip = 0x%(3)08x %(2)08x ]
-0x00020001 %(tsc)d (+%(reltsc)8d) PAGE_FAULT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
-0x00020002 %(tsc)d (+%(reltsc)8d) INJ_VIRQ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x00020003 %(tsc)d (+%(reltsc)8d) REDELIVER_EVT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x00020004 %(tsc)d (+%(reltsc)8d) PEND_INTR vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x00020005 %(tsc)d (+%(reltsc)8d) IO_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
-0x00020006 %(tsc)d (+%(reltsc)8d) IO_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
-0x00020007 %(tsc)d (+%(reltsc)8d) CR_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
-0x00020008 %(tsc)d (+%(reltsc)8d) CR_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
-0x00020009 %(tsc)d (+%(reltsc)8d) DR_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
-0x0002000A %(tsc)d (+%(reltsc)8d) DR_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
-0x0002000B %(tsc)d (+%(reltsc)8d) MSR_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
-0x0002000C %(tsc)d (+%(reltsc)8d) MSR_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
-0x0002000D %(tsc)d (+%(reltsc)8d) CPUID vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ func = 0x%(1)08x, eax = 0x%(2)08x, ebx = 0x%(3)08x, ecx = 0x%(4)08x edx = 0x%(5)08x]
-0x0002000E %(tsc)d (+%(reltsc)8d) INTR vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
-0x0002000F %(tsc)d (+%(reltsc)8d) NMI vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
-0x00020010 %(tsc)d (+%(reltsc)8d) VMMCALL vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ func = 0x%(1)08x ]
-0x00020011 %(tsc)d (+%(reltsc)8d) HLT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
-0x00020012 %(tsc)d (+%(reltsc)8d) CLTS vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
-0x00020013 %(tsc)d (+%(reltsc)8d) LMSW vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ value = 0x%(1)08x ]
-0x00020014 %(tsc)d (+%(reltsc)8d) APIC_ACCESS vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ offset = 0x%(1)08x ]
-0x00020015 %(tsc)d (+%(reltsc)8d) TDP_FAULT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
+0x00010001 %(ts)d (+%(relts)12d) VMENTRY vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
+0x00010002 %(ts)d (+%(relts)12d) VMEXIT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ exitcode = 0x%(1)08x, rip = 0x%(3)08x %(2)08x ]
+0x00020001 %(ts)d (+%(relts)12d) PAGE_FAULT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
+0x00020002 %(ts)d (+%(relts)12d) INJ_VIRQ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x00020003 %(ts)d (+%(relts)12d) REDELIVER_EVT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x00020004 %(ts)d (+%(relts)12d) PEND_INTR vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x00020005 %(ts)d (+%(relts)12d) IO_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
+0x00020006 %(ts)d (+%(relts)12d) IO_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ port = 0x%(1)04x, size = %(2)d ]
+0x00020007 %(ts)d (+%(relts)12d) CR_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
+0x00020008 %(ts)d (+%(relts)12d) CR_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ CR# = %(1)d, value = 0x%(3)08x %(2)08x ]
+0x00020009 %(ts)d (+%(relts)12d) DR_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
+0x0002000A %(ts)d (+%(relts)12d) DR_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ DR# = %(1)d, value = 0x%(2)08x ]
+0x0002000B %(ts)d (+%(relts)12d) MSR_READ vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
+0x0002000C %(ts)d (+%(relts)12d) MSR_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ MSR# = 0x%(1)08x, data = 0x%(3)08x %(2)08x ]
+0x0002000D %(ts)d (+%(relts)12d) CPUID vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ func = 0x%(1)08x, eax = 0x%(2)08x, ebx = 0x%(3)08x, ecx = 0x%(4)08x edx = 0x%(5)08x]
+0x0002000E %(ts)d (+%(relts)12d) INTR vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ vector = 0x%(1)02x ]
+0x0002000F %(ts)d (+%(relts)12d) NMI vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
+0x00020010 %(ts)d (+%(relts)12d) VMMCALL vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ func = 0x%(1)08x ]
+0x00020011 %(ts)d (+%(relts)12d) HLT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
+0x00020012 %(ts)d (+%(relts)12d) CLTS vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x
+0x00020013 %(ts)d (+%(relts)12d) LMSW vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ value = 0x%(1)08x ]
+0x00020014 %(ts)d (+%(relts)12d) APIC_ACCESS vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ offset = 0x%(1)08x ]
+0x00020015 %(ts)d (+%(relts)12d) TDP_FAULT vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ errorcode = 0x%(1)08x, virt = 0x%(3)08x %(2)08x ]
# ppc: tlb traces
0x00020016 GTLB_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
0x00020017 STLB_WRITE vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
0x00020018 STLB_INVAL vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ index = 0x%(1)08x, tid = 0x%(2)08x, word1=0x%(3)08x, word2=0x%(4)08x, word3=0x%(5)08x ]
# ppc: instruction emulation - this type is handled more complex in kvmtrace_format, but listed to show the eventid and transported data
-#0x00020019 %(tsc)d (+%(reltsc)8d) PPC_INSTR vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ instr = 0x%(1)08x, pc = 0x%(2)08x, emul = 0x%(3)08x, nsec = %(4)08d ]
+#0x00020019 %(ts)d (+%(relts)12d) PPC_INSTR vcpu = 0x%(vcpu)08x pid = 0x%(pid)08x [ instr = 0x%(1)08x, pc = 0x%(2)08x, emul = 0x%(3)08x, nsec = %(4)08d ]
diff --git a/user/kvmtrace_format b/user/kvmtrace_format
--- a/user/kvmtrace_format
+++ b/user/kvmtrace_format
@@ -17,7 +17,7 @@
{event_id}{whitespace}{text format string}

The textual format string may include format specifiers, such as:
- %(tsc)d, %(event)d, %(pid)d %(vcpu)d %(1)d, %(2)d,
+ %(ts)d, %(event)d, %(pid)d %(vcpu)d %(1)d, %(2)d,
%(3)d, %(4)d, %(5)d
[ the 'd' format specifier outputs in decimal, alternatively 'x'
will output in hexadecimal and 'o' will output in octal ]
@@ -31,8 +31,6 @@
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
"""
@@ -362,7 +360,6 @@

##### Main code

-mhz = 0
summary = False

if len(sys.argv) < 2:
@@ -371,7 +368,6 @@
try:
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:
@@ -388,12 +384,12 @@
# structure of trace record (as output by kvmtrace):
# HDR(I) {TSC(Q)} D1(I) D2(I) D3(I) D4(I) D5(I)
#
-# HDR consists of EVENT:28:, n_data:3:, tsc_in:1:
+# HDR consists of EVENT:28:, n_data:3:, ts_in:1:
# pid:32, vcpu_id:32
# EVENT means Event ID
# n_data means number of data (like D1, D2, ...)
-# tsc_in means TSC data exists(1) or not(0).
-# if tsc_in == 0, TSC(Q) does not exists.
+# ts_in means Timestamp data exists(1) or not(0).
+# if ts_in == 0, TSC(Q) does not exists.
#
HDRREC = "<III"
TSCREC = "<Q"
@@ -404,7 +400,7 @@
D5REC = "<IIIII"
KMAGIC = "<I"

-last_tsc = 0
+last_ts = 0

i=0

@@ -441,7 +437,7 @@
(event, pid, vcpu_id) = struct.unpack(HDRREC, line)

n_data = event >> 28 & 0x7
- tsc_in = event >> 31
+ ts_in = event >> 31

d1 = 0
d2 = 0
@@ -449,13 +445,13 @@
d4 = 0
d5 = 0

- tsc = 0
+ ts = 0

- if tsc_in == 1:
+ if ts_in == 1:
line = sys.stdin.read(struct.calcsize(TSCREC))
if not line:
break
- tsc = struct.unpack(TSCREC, line)[0]
+ ts = struct.unpack(TSCREC, line)[0]
if n_data == 1:
line = sys.stdin.read(struct.calcsize(D1REC))
if not line:
@@ -486,20 +482,17 @@

# provide relative TSC

- if last_tsc > 0 and tsc_in == 1:
- reltsc = tsc - last_tsc
+ if last_ts > 0 and ts_in == 1:
+ relts = ts - last_ts
else:
- reltsc = 0
+ relts = 0

- if tsc_in == 1:
- last_tsc = tsc
+ if ts_in == 1:
+ last_ts = ts

- if mhz:
- tsc = tsc / (mhz*1000000.0)
-
- args = {'tsc' : tsc,
+ args = {'ts' : ts,
'event' : event,
- 'reltsc': reltsc,
+ 'relts': relts,
'pid' : pid,
'vcpu' : vcpu_id,
'1' : d1,
@@ -511,7 +504,7 @@
# some event types need more than just formats mapping they are if/elif
# chained here and the last default else is the mapping via formats
if event == 0x00020019:
- pdata = (tsc, reltsc, vcpu_id, pid, d1, d2, d3, get_name(d1), get_special(d1))
+ pdata = (ts, relts, vcpu_id, pid, d1, d2, d3, get_name(d1), get_special(d1))
print "%d (+%12d) PPC_INSTR vcpu = 0x%08x pid = 0x%08x [ instr = 0x%08x, pc = 0x%08x, emul = %01d, mnemonic = %8s %s" % pdata