* [PATCH 0/3] Further trace improvements
@ 2024-04-26 14:32 George Dunlap
2024-04-26 14:32 ` [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors George Dunlap
` (2 more replies)
0 siblings, 3 replies; 11+ messages in thread
From: George Dunlap @ 2024-04-26 14:32 UTC (permalink / raw)
To: xen-devel; +Cc: George Dunlap
Some further trace improvements:
- Remove the need to specify `--svm-mode` every time running xenalyze
on a trace generated on an AMD box.
- Get rid of warnings due to unhandled HVM_EMUL traces
- Completely remove obsolete xentrace_format
This series is meant to be applied on top of Andy's series "xen/trace:
Treewide API cleanup":
https://lore.kernel.org/xen-devel/20240318163552.3808695-1-andrew.cooper3@citrix.com/
George Dunlap (3):
x86/hvm/trace: Use a different trace type for AMD processors
tools/xenalyze: Ignore HVM_EMUL events harder
tools/xentrace: Remove xentrace_format
docs/man/xentrace.8.pod | 5 +-
docs/man/xentrace_format.1.pod | 46 ------
tools/xentrace/Makefile | 3 -
tools/xentrace/formats | 229 ----------------------------
tools/xentrace/xenalyze.c | 50 ++++---
tools/xentrace/xentrace.c | 2 +-
tools/xentrace/xentrace_format | 264 ---------------------------------
xen/arch/x86/hvm/svm/svm.c | 4 +-
xen/arch/x86/hvm/vmx/vmx.c | 4 +-
xen/include/public/trace.h | 6 +-
10 files changed, 41 insertions(+), 572 deletions(-)
delete mode 100644 docs/man/xentrace_format.1.pod
delete mode 100644 tools/xentrace/formats
delete mode 100644 tools/xentrace/xentrace_format
--
2.25.1
^ permalink raw reply [flat|nested] 11+ messages in thread
* [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors
2024-04-26 14:32 [PATCH 0/3] Further trace improvements George Dunlap
@ 2024-04-26 14:32 ` George Dunlap
2024-04-26 15:18 ` Andrew Cooper
2024-04-26 14:32 ` [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder George Dunlap
2024-04-26 14:32 ` [PATCH 3/3] tools/xentrace: Remove xentrace_format George Dunlap
2 siblings, 1 reply; 11+ messages in thread
From: George Dunlap @ 2024-04-26 14:32 UTC (permalink / raw)
To: xen-devel
Cc: George Dunlap, Andrew Cooper, Jan Beulich, Roger Pau Monne,
Anthony Perard, Stefano Stabellini, Julien Grall, Olaf Hering
A long-standing usability sub-optimality with xenalyze is the
necessity to specify `--svm-mode` when analyzing AMD processors. This
fundamentally comes about because the same trace event ID is used for
both VMX and SVM, but the contents of the trace must be interpreted
differently.
Instead, allocate separate trace events for VMX and SVM vmexits in
Xen; this will allow all readers to properly intrepret the meaning of
the vmexit reason.
In xenalyze, first remove the redundant call to init_hvm_data();
there's no way to get to hvm_vmexit_process() without it being already
initialized by the set_vcpu_type call in hvm_process().
Replace this with set_hvm_exit_reson_data(), and move setting of
hvm->exit_reason_* into that function.
Modify hvm_process and hvm_vmexit_process to handle all four potential
values appropriately.
If SVM entries are encountered, set opt.svm_mode so that other
SVM-specific functionality is triggered.
Also add lines in `formats` for xentrace_format.
Signed-off-by: George Dunlap <george.dunlap@cloud.com>
---
NB that this patch goes on top of Andrew's trace cleanup series:
https://lore.kernel.org/xen-devel/20240318163552.3808695-1-andrew.cooper3@citrix.com/
CC: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Jan Beulich <jbeulich@suse.com>
CC: Roger Pau Monne <roger.pau@cloud.com>
CC: Anthony Perard <anthony.perard@cloud.com>
CC: Stefano Stabellini <sstabellini@kernel.org>
CC: Julien Grall <julien@xen.org>
CC: Olaf Hering <olaf@aepfle.de>
---
tools/xentrace/formats | 6 ++++--
tools/xentrace/xenalyze.c | 32 +++++++++++++++++++-------------
xen/arch/x86/hvm/svm/svm.c | 4 ++--
xen/arch/x86/hvm/vmx/vmx.c | 4 ++--
xen/include/public/trace.h | 6 ++++--
5 files changed, 31 insertions(+), 21 deletions(-)
diff --git a/tools/xentrace/formats b/tools/xentrace/formats
index afb5ee0112..3381c1cda5 100644
--- a/tools/xentrace/formats
+++ b/tools/xentrace/formats
@@ -90,8 +90,10 @@
0x00041002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_destroy [ dom = 0x%(1)08x ]
0x00081001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY
-0x00081002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
-0x00081102 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMEXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
+0x00081002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMX_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
+0x00081102 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMX_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
+0x00081003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) SVM_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
+0x00081103 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) SVM_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
0x00081401 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) nVMENTRY
0x00081402 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) nVMEXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
0x00081502 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) nVMEXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index ce6a85d50b..ceb07229d1 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -1437,14 +1437,6 @@ void init_hvm_data(struct hvm_data *h, struct vcpu_data *v) {
h->init = 1;
- if(opt.svm_mode) {
- h->exit_reason_max = HVM_SVM_EXIT_REASON_MAX;
- h->exit_reason_name = hvm_svm_exit_reason_name;
- } else {
- h->exit_reason_max = HVM_VMX_EXIT_REASON_MAX;
- h->exit_reason_name = hvm_vmx_exit_reason_name;
- }
-
if(opt.histogram_interrupt_eip) {
int count = ((1ULL<<ADDR_SPACE_BITS)/opt.histogram_interrupt_increment);
size_t size = count * sizeof(int);
@@ -1462,6 +1454,18 @@ void init_hvm_data(struct hvm_data *h, struct vcpu_data *v) {
h->summary.guest_interrupt[i].count=0;
}
+void set_hvm_exit_reason_data(struct hvm_data *h, unsigned event) {
+ if (((event & ~TRC_64_FLAG) == TRC_HVM_SVM_EXIT) ||
+ opt.svm_mode) {
+ opt.svm_mode = 1;
+ h->exit_reason_max = HVM_SVM_EXIT_REASON_MAX;
+ h->exit_reason_name = hvm_svm_exit_reason_name;
+ } else {
+ h->exit_reason_max = HVM_VMX_EXIT_REASON_MAX;
+ h->exit_reason_name = hvm_vmx_exit_reason_name;
+ }
+}
+
/* PV data */
enum {
PV_HYPERCALL=1,
@@ -5088,13 +5092,13 @@ void hvm_vmexit_process(struct record_info *ri, struct hvm_data *h,
r = (typeof(r))ri->d;
- if(!h->init)
- init_hvm_data(h, v);
+ if(!h->exit_reason_name)
+ set_hvm_exit_reason_data(h, ri->event);
h->vmexit_valid=1;
bzero(&h->inflight, sizeof(h->inflight));
- if(ri->event == TRC_HVM_VMEXIT64) {
+ if(ri->event & TRC_64_FLAG) {
if(v->guest_paging_levels != 4)
{
if ( verbosity >= 6 )
@@ -5316,8 +5320,10 @@ void hvm_process(struct pcpu_info *p)
break;
default:
switch(ri->event) {
- case TRC_HVM_VMEXIT:
- case TRC_HVM_VMEXIT64:
+ case TRC_HVM_VMX_EXIT:
+ case TRC_HVM_VMX_EXIT64:
+ case TRC_HVM_SVM_EXIT:
+ case TRC_HVM_SVM_EXIT64:
UPDATE_VOLUME(p, hvm[HVM_VOL_VMEXIT], ri->size);
hvm_vmexit_process(ri, h, v);
break;
diff --git a/xen/arch/x86/hvm/svm/svm.c b/xen/arch/x86/hvm/svm/svm.c
index db530d55f2..988250dbc1 100644
--- a/xen/arch/x86/hvm/svm/svm.c
+++ b/xen/arch/x86/hvm/svm/svm.c
@@ -2571,10 +2571,10 @@ void asmlinkage svm_vmexit_handler(void)
exit_reason = vmcb->exitcode;
if ( hvm_long_mode_active(v) )
- TRACE_TIME(TRC_HVM_VMEXIT64 | (vcpu_guestmode ? TRC_HVM_NESTEDFLAG : 0),
+ TRACE_TIME(TRC_HVM_SVM_EXIT64 | (vcpu_guestmode ? TRC_HVM_NESTEDFLAG : 0),
exit_reason, regs->rip, regs->rip >> 32);
else
- TRACE_TIME(TRC_HVM_VMEXIT | (vcpu_guestmode ? TRC_HVM_NESTEDFLAG : 0),
+ TRACE_TIME(TRC_HVM_SVM_EXIT | (vcpu_guestmode ? TRC_HVM_NESTEDFLAG : 0),
exit_reason, regs->eip);
if ( vcpu_guestmode )
diff --git a/xen/arch/x86/hvm/vmx/vmx.c b/xen/arch/x86/hvm/vmx/vmx.c
index e5bfb2421e..c2b94e343f 100644
--- a/xen/arch/x86/hvm/vmx/vmx.c
+++ b/xen/arch/x86/hvm/vmx/vmx.c
@@ -4105,9 +4105,9 @@ void asmlinkage vmx_vmexit_handler(struct cpu_user_regs *regs)
__vmread(VM_EXIT_REASON, &exit_reason);
if ( hvm_long_mode_active(v) )
- TRACE_TIME(TRC_HVM_VMEXIT64, exit_reason, regs->rip, regs->rip >> 32);
+ TRACE_TIME(TRC_HVM_VMX_EXIT64, exit_reason, regs->rip, regs->rip >> 32);
else
- TRACE_TIME(TRC_HVM_VMEXIT, exit_reason, regs->eip);
+ TRACE_TIME(TRC_HVM_VMX_EXIT, exit_reason, regs->eip);
perfc_incra(vmexits, (uint16_t)exit_reason);
diff --git a/xen/include/public/trace.h b/xen/include/public/trace.h
index 3c9f9c3c18..141efa0ea7 100644
--- a/xen/include/public/trace.h
+++ b/xen/include/public/trace.h
@@ -178,8 +178,10 @@
/* trace events per subclass */
#define TRC_HVM_NESTEDFLAG (0x400)
#define TRC_HVM_VMENTRY (TRC_HVM_ENTRYEXIT + 0x01)
-#define TRC_HVM_VMEXIT (TRC_HVM_ENTRYEXIT + 0x02)
-#define TRC_HVM_VMEXIT64 (TRC_HVM_ENTRYEXIT + TRC_64_FLAG + 0x02)
+#define TRC_HVM_VMX_EXIT (TRC_HVM_ENTRYEXIT + 0x02)
+#define TRC_HVM_VMX_EXIT64 (TRC_HVM_ENTRYEXIT + TRC_64_FLAG + 0x02)
+#define TRC_HVM_SVM_EXIT (TRC_HVM_ENTRYEXIT + 0x03)
+#define TRC_HVM_SVM_EXIT64 (TRC_HVM_ENTRYEXIT + TRC_64_FLAG + 0x03)
#define TRC_HVM_PF_XEN (TRC_HVM_HANDLER + 0x01)
#define TRC_HVM_PF_XEN64 (TRC_HVM_HANDLER + TRC_64_FLAG + 0x01)
#define TRC_HVM_PF_INJECT (TRC_HVM_HANDLER + 0x02)
--
2.25.1
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder
2024-04-26 14:32 [PATCH 0/3] Further trace improvements George Dunlap
2024-04-26 14:32 ` [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors George Dunlap
@ 2024-04-26 14:32 ` George Dunlap
2024-04-26 15:06 ` Andrew Cooper
2024-04-26 14:32 ` [PATCH 3/3] tools/xentrace: Remove xentrace_format George Dunlap
2 siblings, 1 reply; 11+ messages in thread
From: George Dunlap @ 2024-04-26 14:32 UTC (permalink / raw)
To: xen-devel; +Cc: George Dunlap, Andrew Cooper, Anthony Perard, Olaf Hering
To unify certain common sanity checks, checks are done very early in
processing based only on the top-level type.
Unfortunately, when TRC_HVM_EMUL was introduced, it broke some of the
assumptions about how the top-level types worked. Namely, traces of
this type will show up outside of HVM contexts: in idle domains and in
PV domains.
Make an explicit exception for TRC_HVM_EMUL types in a number of places:
- Pass the record info pointer to toplevel_assert_check, so that it
can exclude TRC_HVM_EMUL records from idle and vcpu data_mode
checks
- Don't attempt to set the vcpu data_type in hvm_process for
TRC_HVM_EMUL records.
Signed-off-by: George Dunlap <george.dunlap@cloud.com>
---
CC: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Anthony Perard <anthony.perard@cloud.com>
CC: Olaf Hering <olaf@aepfle.de>
---
tools/xentrace/xenalyze.c | 18 ++++++++++++------
1 file changed, 12 insertions(+), 6 deletions(-)
diff --git a/tools/xentrace/xenalyze.c b/tools/xentrace/xenalyze.c
index ceb07229d1..8fb45dec76 100644
--- a/tools/xentrace/xenalyze.c
+++ b/tools/xentrace/xenalyze.c
@@ -21,6 +21,7 @@
#define _XOPEN_SOURCE 600
#include <stdio.h>
#include <stdlib.h>
+#include <stdbool.h>
#include <argp.h>
#include <inttypes.h>
#include <limits.h>
@@ -5305,8 +5306,11 @@ void hvm_process(struct pcpu_info *p)
assert(p->current);
- if(vcpu_set_data_type(p->current, VCPU_DATA_HVM))
- return;
+ /* HVM_EMUL types show up in all contexts */
+ if(ri->evt.sub != 0x4) {
+ if(vcpu_set_data_type(p->current, VCPU_DATA_HVM))
+ return;
+ }
switch ( ri->evt.sub ) {
case 2: /* HVM_HANDLER */
@@ -9447,9 +9451,10 @@ static struct tl_assert_mask tl_assert_checks[TOPLEVEL_MAX] = {
/* There are a lot of common assumptions for the various processing
* routines. Check them all in one place, doing something else if
* they don't pass. */
-int toplevel_assert_check(int toplevel, struct pcpu_info *p)
+int toplevel_assert_check(int toplevel, struct record_info *ri, struct pcpu_info *p)
{
struct tl_assert_mask mask;
+ bool is_hvm_emul = (toplevel == TOPLEVEL_HVM) && (ri->evt.sub == 0x4);
mask = tl_assert_checks[toplevel];
@@ -9459,7 +9464,7 @@ int toplevel_assert_check(int toplevel, struct pcpu_info *p)
goto fail;
}
- if( mask.not_idle_domain )
+ if( mask.not_idle_domain && !is_hvm_emul)
{
/* Can't do this check w/o first doing above check */
assert(mask.p_current);
@@ -9478,7 +9483,8 @@ int toplevel_assert_check(int toplevel, struct pcpu_info *p)
v = p->current;
if ( ! (v->data_type == VCPU_DATA_NONE
- || v->data_type == mask.vcpu_data_mode) )
+ || v->data_type == mask.vcpu_data_mode
+ || is_hvm_emul) )
{
/* This may happen for track_dirty_vram, which causes a SHADOW_WRMAP_BF trace f/ dom0 */
fprintf(warn, "WARNING: Unexpected vcpu data type for d%dv%d on proc %d! Expected %d got %d. Not processing\n",
@@ -9525,7 +9531,7 @@ void process_record(struct pcpu_info *p) {
return;
/* Unify toplevel assertions */
- if ( toplevel_assert_check(toplevel, p) )
+ if ( toplevel_assert_check(toplevel, ri, p) )
{
switch(toplevel) {
case TRC_GEN_MAIN:
--
2.25.1
^ permalink raw reply related [flat|nested] 11+ messages in thread
* [PATCH 3/3] tools/xentrace: Remove xentrace_format
2024-04-26 14:32 [PATCH 0/3] Further trace improvements George Dunlap
2024-04-26 14:32 ` [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors George Dunlap
2024-04-26 14:32 ` [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder George Dunlap
@ 2024-04-26 14:32 ` George Dunlap
2024-04-26 15:03 ` Andrew Cooper
2024-04-26 19:50 ` Olaf Hering
2 siblings, 2 replies; 11+ messages in thread
From: George Dunlap @ 2024-04-26 14:32 UTC (permalink / raw)
To: xen-devel
Cc: George Dunlap, Andrew Cooper, Jan Beulich, Roger Pau Monne,
Anthony Perard, Olaf Hering
xentrace_format was always of limited utility, since trace records
across pcpus were processed out of order; it was superseded by xenalyze
over a decade ago.
But for several releases, the `formats` file it has depended on for
proper operation has not even been included in `make install` (which
generally means it doesn't get picked up by distros either); yet
nobody has seemed to complain.
Simple remove xentrace_format, and point people to xenalyze instead.
NB that there is no man page for xenalyze, so the "see also" on the
xentrace man page is simply removed for now.
Signed-off-by: George Dunlap <george.dunlap@cloud.com>
---
CC: Andrew Cooper <andrew.cooper3@citrix.com>
CC: Jan Beulich <jbeulich@suse.com>
CC: Roger Pau Monne <roger.pau@cloud.com>
CC: Anthony Perard <anthony.perard@cloud.com>
CC: Olaf Hering <olaf@aepfle.de>
---
docs/man/xentrace.8.pod | 5 +-
docs/man/xentrace_format.1.pod | 46 ------
tools/xentrace/Makefile | 3 -
tools/xentrace/formats | 231 -----------------------------
tools/xentrace/xentrace.c | 2 +-
tools/xentrace/xentrace_format | 264 ---------------------------------
6 files changed, 2 insertions(+), 549 deletions(-)
diff --git a/docs/man/xentrace.8.pod b/docs/man/xentrace.8.pod
index 4c174a84c0..7c9f69c67f 100644
--- a/docs/man/xentrace.8.pod
+++ b/docs/man/xentrace.8.pod
@@ -20,7 +20,7 @@ D1...D5 are the trace data.
Data is dumped onto the standard output (which must not be a TTY) or a
I<FILE> specified on the command line.
-The output should be parsed using the tool xentrace_format, which can
+The output should be parsed using the tool xenalyze, which can
produce human-readable output in ASCII format.
@@ -157,6 +157,3 @@ B<xentrace> collects the following events from the trace buffer:
Mark A. Williamson <mark.a.williamson@intel.com>
-=head1 SEE ALSO
-
-xentrace_format(1)
diff --git a/docs/man/xentrace_format.1.pod b/docs/man/xentrace_format.1.pod
deleted file mode 100644
index e05479a83b..0000000000
--- a/docs/man/xentrace_format.1.pod
+++ /dev/null
@@ -1,46 +0,0 @@
-=head1 NAME
-
-xentrace_format - pretty-print Xen trace data
-
-=head1 SYNOPSIS
-
-B<xentrace_format> [ I<DEFS-FILE> ]
-
-=head1 DESCRIPTION
-
-B<xentrace_format> parses trace data in B<xentrace> binary format from
-standard input and reformats it according to the rules in a file of
-definitions (I<DEFS-FILE>), printing to standard output.
-
-The rules in I<DEFS-FILE> should have the format shown below:
-
-I<event_id> I<whitespace> I<format>
-
-Each rule should start on a new line.
-
-The format string may include format specifiers, such as:
-%(cpu)d, %(tsc)d, %(event)d, %(1)d, %(2)d, %(3)d, %(4)d, %(5)d
-
-[ the `d' format specifier output in decimal, alternatively `x'
- will output in hexadecimal and `o' will output in octal ]
-
-These correspond to the CPU number, event ID, timestamp counter and
-the 5 data fields from the trace record. There should be one such
-rule for each type of event to be pretty-printed (events which do not
-have formatting rules are ignored).
-
-A sample format file for Xen's predefined trace events is available
-in the file tools/xentrace/formats in the Xen source tree.
-
-Depending on your system and the rate at which trace data is produced,
-this script may not be able to keep up with the output of
-B<xentrace> if it is piped directly. In these circumstances you
-should have B<xentrace> output to a file for processing off-line.
-
-=head1 AUTHOR
-
-Mark A. Williamson <mark.a.williamson@intel.com>
-
-=head1 SEE ALSO
-
-xentrace(8)
diff --git a/tools/xentrace/Makefile b/tools/xentrace/Makefile
index d50d400472..bf960c0867 100644
--- a/tools/xentrace/Makefile
+++ b/tools/xentrace/Makefile
@@ -10,7 +10,6 @@ LDLIBS += $(ARGP_LDFLAGS)
BIN := xenalyze
SBIN := xentrace xentrace_setsize
LIBBIN := xenctx
-SCRIPTS := xentrace_format
TARGETS := $(BIN) $(SBIN) $(LIBBIN)
@@ -24,13 +23,11 @@ install: all
$(INSTALL_DIR) $(DESTDIR)$(LIBEXEC_BIN)
$(INSTALL_PROG) $(BIN) $(DESTDIR)$(bindir)
$(INSTALL_PROG) $(SBIN) $(DESTDIR)$(sbindir)
- $(INSTALL_PYTHON_PROG) $(SCRIPTS) $(DESTDIR)$(bindir)
$(INSTALL_PROG) $(LIBBIN) $(DESTDIR)$(LIBEXEC_BIN)
.PHONY: uninstall
uninstall:
rm -f $(addprefix $(DESTDIR)$(LIBEXEC_BIN)/, $(LIBBIN))
- rm -f $(addprefix $(DESTDIR)$(bindir)/, $(SCRIPTS))
rm -f $(addprefix $(DESTDIR)$(sbindir)/, $(SBIN))
rm -f $(addprefix $(DESTDIR)$(bindir)/, $(BIN))
diff --git a/tools/xentrace/formats b/tools/xentrace/formats
deleted file mode 100644
index 3381c1cda5..0000000000
--- a/tools/xentrace/formats
+++ /dev/null
@@ -1,231 +0,0 @@
-0x00000000 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) unknown (0x%(event)016x) [ 0x%(1)08x 0x%(2)08x 0x%(3)08x 0x%(4)08x 0x%(5)08x 0x%(6)08x 0x%(7)08x ]
-
-0x0001f001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) lost_records 0x%(1)08x
-0x0001f002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) wrap_buffer 0x%(1)08x
-0x0001f003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) cpu_change 0x%(1)08x
-0x0001f004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) trace_irq [ vector = %(1)d, count = %(2)d, tot_cycles = 0x%(3)08x, max_cycles = 0x%(4)08x ]
-
-0x00021002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) continue_running [ dom:vcpu = 0x%(1)08x ]
-0x00021011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) running_to_runnable [ dom:vcpu = 0x%(1)08x ]
-0x00021021 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) running_to_blocked [ dom:vcpu = 0x%(1)08x ]
-0x00021031 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) running_to_offline [ dom:vcpu = 0x%(1)08x ]
-0x00021101 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) runnable_to_running [ dom:vcpu = 0x%(1)08x ]
-0x00021121 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) runnable_to_blocked [ dom:vcpu = 0x%(1)08x ]
-0x00021131 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) runnable_to_offline [ dom:vcpu = 0x%(1)08x ]
-0x00021201 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) blocked_to_running [ dom:vcpu = 0x%(1)08x ]
-0x00021211 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) blocked_to_runnable [ dom:vcpu = 0x%(1)08x ]
-0x00021231 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) blocked_to_offline [ dom:vcpu = 0x%(1)08x ]
-0x00021301 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) offline_to_running [ dom:vcpu = 0x%(1)08x ]
-0x00021311 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) offline_to_runnable [ dom:vcpu = 0x%(1)08x ]
-0x00021321 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) offline_to_blocked [ dom:vcpu = 0x%(1)08x ]
-
-0x00028001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) sched_add_domain [ domid = 0x%(1)08x ]
-0x00028002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) sched_rem_domain [ domid = 0x%(1)08x ]
-0x00028003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_sleep [ dom:vcpu = 0x%(1)04x%(2)04x ]
-0x00028004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_wake [ dom:vcpu = 0x%(1)04x%(2)04x ]
-0x00028005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_yield [ dom:vcpu = 0x%(1)04x%(2)04x ]
-0x00028006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_block [ dom:vcpu = 0x%(1)04x%(2)04x ]
-0x00028007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_shutdown [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
-0x00028008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) sched_ctl
-0x00028009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) sched_adjdom [ domid = 0x%(1)08x ]
-0x0002800a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) __enter_scheduler [ prev<dom:vcpu> = 0x%(1)04x%(2)04x, next<dom:vcpu> = 0x%(3)04x%(4)04x ]
-0x0002800b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) s_timer_fn
-0x0002800c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) t_timer_fn
-0x0002800d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) dom_timer_fn
-0x0002800e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) switch_infprev [ dom:vcpu = 0x%(1)04x%(2)04x, runtime = %(3)d ]
-0x0002800f CPU%(cpu)d %(tsc)d (+%(reltsc)8d) switch_infnext [ new_dom:vcpu = 0x%(1)04x%(2)04x, time = %(3)d, r_time = %(4)d ]
-0x00028010 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_shutdown_code [ dom:vcpu = 0x%(1)04x%(2)04x, reason = 0x%(3)08x ]
-0x00028011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) switch_infcont [ dom:vcpu = 0x%(1)04x%(2)04x, runtime = %(3)d, r_time = %(4)d ]
-
-0x00022001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:sched_tasklet
-0x00022002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:account_start [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
-0x00022003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:account_stop [ dom:vcpu = 0x%(1)04x%(2)04x, active = %(3)d ]
-0x00022004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:stolen_vcpu [ dom:vcpu = 0x%(2)04x%(3)04x, from = %(1)d ]
-0x00022005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:picked_cpu [ dom:vcpu = 0x%(1)04x%(2)04x, cpu = %(3)d ]
-0x00022006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:tickle [ cpu = %(1)d ]
-0x00022007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:boost [ dom:vcpu = 0x%(1)04x%(2)04x ]
-0x00022008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:unboost [ dom:vcpu = 0x%(1)04x%(2)04x ]
-0x00022009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:schedule [ cpu[16]:tasklet[8]:idle[8] = %(1)08x ]
-0x0002200A CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:ratelimit [ dom:vcpu = 0x%(1)08x, runtime = %(2)d ]
-0x0002200B CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched:steal_check [ peer_cpu = %(1)d, checked = %(2)d ]
-
-0x00022201 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:tick
-0x00022202 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:runq_pos [ dom:vcpu = 0x%(1)08x, pos = %(2)d]
-0x00022203 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:credit burn [ dom:vcpu = 0x%(1)08x, credit = %(2)d, budget = %(3)d, delta = %(4)d ]
-0x00022204 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:credit_add
-0x00022205 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:tickle_check [ dom:vcpu = 0x%(1)08x, credit = %(2)d, score = %(3)d ]
-0x00022206 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:tickle [ cpu = %(1)d ]
-0x00022207 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:credit_reset [ dom:vcpu = 0x%(1)08x, cr_start = %(2)d, cr_end = %(3)d ]
-0x00022208 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:sched_tasklet
-0x00022209 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:update_load
-0x0002220a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:runq_assign [ dom:vcpu = 0x%(1)08x, rq_id = %(2)d ]
-0x0002220b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:updt_vcpu_load [ dom:vcpu = 0x%(3)08x, vcpuload = 0x%(2)08x%(1)08x, wshift = %(4)d ]
-0x0002220c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:updt_runq_load [ rq_load[16]:rq_id[8]:wshift[8] = 0x%(5)08x, rq_avgload = 0x%(2)08x%(1)08x, b_avgload = 0x%(4)08x%(3)08x ]
-0x0002220d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:tickle_new [ dom:vcpu = 0x%(1)08x, processor = %(2)d credit = %(3)d ]
-0x0002220e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:runq_max_weight [ rq_id[16]:max_weight[16] = 0x%(1)08x ]
-0x0002220f CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:migrrate [ dom:vcpu = 0x%(1)08x, rq_id[16]:trq_id[16] = 0x%(2)08x ]
-0x00022210 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:load_check [ lrq_id[16]:orq_id[16] = 0x%(1)08x, delta = %(2)d ]
-0x00022211 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:load_balance [ l_bavgload = 0x%(2)08x%(1)08x, o_bavgload = 0x%(4)08x%(3)08x, lrq_id[16]:orq_id[16] = 0x%(5)08x ]
-0x00022212 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:pick_cpu [ b_avgload = 0x%(2)08x%(1)08x, dom:vcpu = 0x%(3)08x, rq_id[16]:new_cpu[16] = %(4)d ]
-0x00022213 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:runq_candidate [ dom:vcpu = 0x%(1)08x, credit = %(3)d, tickled_cpu = %(2)d ]
-0x00022214 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:schedule [ rq:cpu = 0x%(1)08x, tasklet[8]:idle[8]:smt_idle[8]:tickled[8] = %(2)08x ]
-0x00022215 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:ratelimit [ dom:vcpu = 0x%(1)08x, runtime = %(2)d ]
-0x00022216 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) csched2:runq_cand_chk [ dom:vcpu = 0x%(1)08x ]
-
-0x00022801 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtds:tickle [ cpu = %(1)d ]
-0x00022802 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtds:runq_pick [ dom:vcpu = 0x%(1)08x, cur_deadline = 0x%(3)08x%(2)08x, cur_budget = 0x%(5)08x%(4)08x ]
-0x00022803 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtds:burn_budget [ dom:vcpu = 0x%(1)08x, cur_budget = 0x%(3)08x%(2)08x, delta = %(4)d ]
-0x00022804 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtds:repl_budget [ dom:vcpu = 0x%(1)08x, cur_deadline = 0x%(3)08x%(2)08x, cur_budget = 0x%(5)08x%(4)08x ]
-0x00022805 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtds:sched_tasklet
-0x00022806 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtds:schedule [ cpu[16]:tasklet[8]:idle[4]:tickled[4] = %(1)08x ]
-
-0x00022A01 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) null:pick_cpu [ dom:vcpu = 0x%(1)08x, new_cpu = %(2)d ]
-0x00022A02 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) null:assign [ dom:vcpu = 0x%(1)08x, cpu = %(2)d ]
-0x00022A03 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) null:deassign [ dom:vcpu = 0x%(1)08x, cpu = %(2)d ]
-0x00022A04 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) null:migrate [ dom:vcpu = 0x%(1)08x, new_cpu:cpu = 0x%(2)08x ]
-0x00022A05 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) null:schedule [ cpu[16]:tasklet[16] = %(1)08x, dom:vcpu = 0x%(2)08x ]
-0x00022A06 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) null:sched_tasklet
-
-0x00041001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_create [ dom = 0x%(1)08x ]
-0x00041002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) domain_destroy [ dom = 0x%(1)08x ]
-
-0x00081001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMENTRY
-0x00081002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMX_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
-0x00081102 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMX_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
-0x00081003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) SVM_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
-0x00081103 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) SVM_EXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
-0x00081401 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) nVMENTRY
-0x00081402 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) nVMEXIT [ exitcode = 0x%(1)08x, rIP = 0x%(2)08x ]
-0x00081502 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) nVMEXIT [ exitcode = 0x%(1)08x, rIP = 0x%(3)08x%(2)08x ]
-0x00082001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) PF_XEN [ errorcode = 0x%(2)02x, virt = 0x%(1)08x ]
-0x00082101 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) PF_XEN [ errorcode = 0x%(3)02x, virt = 0x%(2)08x%(1)08x ]
-0x00082002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) PF_INJECT [ errorcode = 0x%(1)02x, virt = 0x%(2)08x ]
-0x00082102 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) PF_INJECT [ errorcode = 0x%(1)02x, virt = 0x%(3)08x%(2)08x ]
-0x00082003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INJ_EXC [ vector = 0x%(1)02x, errorcode = 0x%(2)04x ]
-0x00082004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INJ_VIRQ [ vector = 0x%(1)02x, fake = %(2)d ]
-0x00082005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) REINJ_VIRQ [ vector = 0x%(1)02x ]
-0x00082006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) IO_READ [ port = 0x%(1)04x, size = %(2)d ]
-0x00082007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) IO_WRITE [ port = 0x%(1)04x, size = %(2)d ]
-0x00082008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CR_READ [ CR# = %(1)d, value = 0x%(2)08x ]
-0x00082108 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CR_READ [ CR# = %(1)d, value = 0x%(3)08x%(2)08x ]
-0x00082009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CR_WRITE [ CR# = %(1)d, value = 0x%(2)08x ]
-0x00082109 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CR_WRITE [ CR# = %(1)d, value = 0x%(3)08x%(2)08x ]
-0x0008200A CPU%(cpu)d %(tsc)d (+%(reltsc)8d) DR_READ
-0x0008200B CPU%(cpu)d %(tsc)d (+%(reltsc)8d) DR_WRITE
-0x0008200C CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MSR_READ [ MSR# = 0x%(1)08x, value = 0x%(3)08x%(2)08x ]
-0x0008200D CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MSR_WRITE [ MSR# = 0x%(1)08x, value = 0x%(3)08x%(2)08x ]
-0x0008200E CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CPUID [ func = 0x%(1)08x, eax = 0x%(2)08x, ebx = 0x%(3)08x, ecx=0x%(4)08x, edx = 0x%(5)08x ]
-0x0008200F CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INTR [ vector = 0x%(1)02x ]
-0x00082010 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) NMI
-0x00082011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) SMI
-0x00082012 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) VMMCALL [ func = 0x%(1)08x ]
-0x00082013 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) HLT [ intpending = %(1)d ]
-0x00082014 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INVLPG [ is invlpga? = %(1)d, virt = 0x%(2)08x ]
-0x00082114 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INVLPG [ is invlpga? = %(1)d, virt = 0x%(3)08x%(2)08x ]
-0x00082015 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MCE
-0x00082016 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) IOPORT_READ [ port = 0x%(1)04x, data = 0x%(2)08x ]
-0x00082216 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) IOPORT_WRITE [ port = 0x%(1)04x, data = 0x%(2)08x ]
-0x00082017 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MMIO_READ [ port = 0x%(1)08x, data = 0x%(2)08x ]
-0x00082217 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) MMIO_WRITE [ port = 0x%(1)08x, data = 0x%(2)08x ]
-0x00082018 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) CLTS
-0x00082019 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) LMSW [ value = 0x%(1)08x ]
-0x00082119 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) LMSW [ value = 0x%(2)08x%(1)08x ]
-0x0008201a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) RDTSC [ value = 0x%(2)08x%(1)08x ]
-0x00082020 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) INTR_WINDOW [ value = 0x%(1)08x ]
-0x00082021 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) NPF [ gpa = 0x%(2)08x%(1)08x mfn = 0x%(4)08x%(3)08x qual = 0x%(5)04x p2mt = 0x%(6)04x ]
-0x00082023 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) TRAP [ vector = 0x%(1)02x ]
-
-0x0010f001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) page_grant_map [ domid = %(1)d ]
-0x0010f002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) page_grant_unmap [ domid = %(1)d ]
-0x0010f003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) page_grant_transfer [ domid = %(1)d ]
-0x0010f005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) decrease_reservation [ d%(3)d gfn 0x%(2)08x%(1)08x, order %(4)u ]
-0x0010f010 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pod_populate [ d%(5)d gfn 0x%(2)08x%(1)08x => mfn 0x%(4)08x%(3)08x, order %(6)u ]
-0x0010f011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pod_zero_reclaim [ d%(5)d gfn 0x%(2)08x%(1)08x => mfn 0x%(4)08x%(3)08x, order %(6)u ]
-0x0010f012 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pod_superpage_splinter [ d%(3)d gfn 0x%(2)08x%(1)08x, order %(4)u ]
-
-0x00201001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hypercall [ eip = 0x%(1)08x, eax = 0x%(2)08x ]
-0x00201101 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hypercall [ rip = 0x%(2)08x%(1)08x, eax = 0x%(3)08x ]
-0x00201003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) trap [ eip = 0x%(1)08x, trapnr:error = 0x%(2)08x ]
-0x00201103 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) trap [ rip = 0x%(2)08x%(1)08x, trapnr:error = 0x%(3)08x ]
-0x00201004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) page_fault [ eip = 0x%(1)08x, addr = 0x%(2)08x, error = 0x%(3)08x ]
-0x00201104 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) page_fault [ rip = 0x%(2)08x%(1)08x, addr = 0x%(4)08x%(3)08x, error = 0x%(5)08x ]
-0x00201005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) forced_invalid_op [ eip = 0x%(1)08x ]
-0x00201105 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) forced_invalid_op [ rip = 0x%(2)08x%(1)08x ]
-0x00201006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) emulate_privop [ eip = 0x%(1)08x ]
-0x00201106 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) emulate_privop [ rip = 0x%(2)08x%(1)08x ]
-0x00201007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) emulate_4G [ eip = 0x%(1)08x ]
-0x00201107 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) emulate_4G [ rip = 0x%(2)08x%(1)08x ]
-0x00201008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) math_state_restore
-0x00201108 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) math_state_restore
-0x00201009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) paging_fixup [ eip = 0x%(1)08x, addr = 0x%(2)08x ]
-0x00201109 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) paging_fixup [ rip = 0x%(2)08x%(1)08x, addr = 0x%(4)08x%(3)08x ]
-0x0020100a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) gdt_ldt_mapping_fault [ eip = 0x%(1)08x, offset = 0x%(2)08x ]
-0x0020110a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) gdt_ldt_mapping_fault [ rip = 0x%(2)08x%(1)08x, offset = 0x%(4)08x%(3)08x ]
-0x0020100b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) ptwr_emulation [ addr = 0x%(3)08x, eip = 0x%(4)08x, npte = 0x%(2)08x%(1)08x ]
-0x0020110b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) ptwr_emulation [ addr = 0x%(4)08x%(3)08x, rip = 0x%(6)08x%(5)08x, npte = 0x%(2)08x%(1)08x ]
-0x0020100c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) ptwr_emulation_pae [ addr = 0x%(3)08x, eip = 0x%(4)08x, npte = 0x%(2)08x%(1)08x ]
-0x0020110c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) ptwr_emulation_pae [ addr = 0x%(4)08x%(3)08x, rip = 0x%(6)08x%(5)08x, npte = 0x%(2)08x%(1)08x ]
-0x0020100d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hypercall [ op = 0x%(1)08x ]
-0x0020200e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hypercall [ op = 0x%(1)08x ]
-
-0x0040f001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_not_shadow [ gl1e = 0x%(2)08x%(1)08x, va = 0x%(3)08x, flags = 0x%(4)08x ]
-0x0040f101 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_not_shadow [ gl1e = 0x%(2)08x%(1)08x, va = 0x%(4)08x%(3)08x, flags = 0x%(5)08x ]
-0x0040f002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_fast_propagate [ va = 0x%(1)08x ]
-0x0040f102 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_fast_propagate [ va = 0x%(2)08x%(1)08x ]
-0x0040f003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_fast_mmio [ va = 0x%(1)08x ]
-0x0040f103 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_fast_mmio [ va = 0x%(2)08x%(1)08x ]
-0x0040f004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_false_fast_path [ va = 0x%(1)08x ]
-0x0040f104 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_false_fast_path [ va = 0x%(2)08x%(1)08x ]
-0x0040f005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_mmio [ va = 0x%(1)08x ]
-0x0040f105 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_mmio [ va = 0x%(2)08x%(1)08x ]
-0x0040f006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_fixup [ gl1e = 0x%(1)08x, va = 0x%(2)08x, flags = 0x%(3)08x ]
-0x0040f106 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_fixup [ gl1e = 0x%(2)08x%(1)08x, va = 0x%(4)08x%(3)08x, flags = 0x%(3)08x ]
-0x0040f007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_domf_dying [ va = 0x%(1)08x ]
-0x0040f107 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_domf_dying [ va = 0x%(2)08x%(1)08x ]
-0x0040f008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate [ gl1e = 0x%(1)08x, write_val = 0x%(2)08x, va = 0x%(3)08x, flags = 0x%(4)08x ]
-0x0040f108 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate [ gl1e = 0x%(2)08x%(1)08x, write_val = 0x%(4)08x%(3)08x, va = 0x%(6)08x%(5)08x, flags = 0x%(7)08x ]
-0x0040f009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_unshadow_user [ va = 0x%(1)08x, gfn = 0x%(2)08x ]
-0x0040f109 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_unshadow_user [ va = 0x%(2)08x%(1)08x, gfn = 0x%(4)08x%(3)08x ]
-0x0040f00a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_unshadow_evtinj [ va = 0x%(1)08x, gfn = 0x%(2)08x ]
-0x0040f10a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_unshadow_evtinj [ va = 0x%(2)08x%(1)08x, gfn = 0x%(4)08x%(3)08x ]
-0x0040f00b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_unshadow_unhandled [ va = 0x%(1)08x, gfn = 0x%(2)08x ]
-0x0040f10b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_unshadow_unhandled [ va = 0x%(2)08x%(1)08x, gfn = 0x%(4)08x%(3)08x ]
-0x0040f00c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_wrmap_bf [ gfn = 0x%(1)08x ]
-0x0040f10c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_wrmap_bf [ gfn = 0x%(2)08x%(1)08x ]
-0x0040f00d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_prealloc_unpin [ gfn = 0x%(1)08x ]
-0x0040f10d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_prealloc_unpin [ gfn = 0x%(2)08x%(1)08x ]
-0x0040f00e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_resync_full [ gfn = 0x%(1)08x ]
-0x0040f10e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_resync_full [ gfn = 0x%(2)08x%(1)08x ]
-0x0040f00f CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_resync_only [ gfn = 0x%(1)08x ]
-0x0040f10f CPU%(cpu)d %(tsc)d (+%(reltsc)8d) shadow_emulate_resync_only [ gfn = 0x%(2)08x%(1)08x ]
-
-0x00801001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) cpu_freq_change [ %(1)dMHz -> %(2)dMHz ]
-0x00801002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) cpu_idle_entry [ C0 -> C%(1)d, acpi_pm_tick = %(2)d, expected = %(3)dus, predicted = %(4)dus ]
-0x00801003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) cpu_idle_exit [ C%(1)d -> C0, acpi_pm_tick = %(2)d, irq = %(3)d %(4)d %(5)d %(6)d ]
-
-0x00802001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) cleanup_move_delayed [ irq = %(1)d, vector 0x%(2)x on CPU%(3)d ]
-0x00802002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) cleanup_move [ irq = %(1)d, vector 0x%(2)x on CPU%(3)d ]
-0x00802003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) bind_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
-0x00802004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) clear_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
-0x00802005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) move_vector [ irq = %(1)d had vector 0x%(2)x on CPU%(3)d ]
-0x00802006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) assign_vector [ irq = %(1)d = vector 0x%(2)x, CPU mask: 0x%(3)08x ]
-0x00802007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) bogus_vector [ 0x%(1)x ]
-0x00802008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) do_irq [ irq = %(1)d, began = %(2)dus, ended = %(3)dus ]
-
-0x00084001 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hpet create [ tn = %(1)d, irq = %(2)d, delta = 0x%(4)08x%(3)08x, period = 0x%(6)08x%(5)08x ]
-0x00084002 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit create [ delta = 0x%(1)08x, period = 0x%(2)08x ]
-0x00084003 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtc create [ delta = 0x%(1)08x, period = 0x%(2)08x ]
-0x00084004 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic create [ delta = 0x%(2)08x%(1)08x , period = 0x%(4)08x%(3)08x, irq = %(5)d ]
-0x00084005 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) hpet destroy [ tn = %(1)d ]
-0x00084006 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit destroy [ ]
-0x00084007 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) rtc destroy [ ]
-0x00084008 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic destroy [ ]
-0x00084009 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) pit callback [ ]
-0x0008400a CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic callback [ ]
-0x0008400b CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_update_int_output [ int_output = %(1)d, is_master = %(2)d, irq = %(3)d ]
-0x0008400c CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic vcpu_kick [ irq = %(1)d ]
-0x0008400d CPU%(cpu)d %(tsc)d (+%(reltsc)8d) __vpic_intack [ is_master = %(1)d, irq = %(2)d ]
-0x0008400e CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_irq_positive_edge [ irq = %(1)d ]
-0x0008400f CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_irq_negative_edge [ irq = %(1)d ]
-0x00084010 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vpic_ack_pending_irq [ accept_pic_intr = %(1)d, int_output = %(2)d ]
-0x00084011 CPU%(cpu)d %(tsc)d (+%(reltsc)8d) vlapic_accept_pic_intr [ i8259_target = %(1)d, accept_pic_int = %(2)d ]
diff --git a/tools/xentrace/xentrace.c b/tools/xentrace/xentrace.c
index be6226f088..63b29f8442 100644
--- a/tools/xentrace/xentrace.c
+++ b/tools/xentrace/xentrace.c
@@ -848,7 +848,7 @@ static void usage(int status)
"\n" \
" CPU(uint) TSC(uint64_t) EVENT(uint32_t) D1 D2 D3 D4 D5 (all uint32_t)\n" \
"\n" \
-"The output should be parsed using the tool xentrace_format,\n" \
+"The output should be parsed using the tool xenalyze,\n" \
"which can produce human-readable output in ASCII format.\n"
printf(USAGE_STR);
diff --git a/tools/xentrace/xentrace_format b/tools/xentrace/xentrace_format
deleted file mode 100644
index 21be16b7e4..0000000000
--- a/tools/xentrace/xentrace_format
+++ /dev/null
@@ -1,264 +0,0 @@
-#!/usr/bin/env python
-
-# by Mark Williamson, (C) 2004 Intel Research Cambridge
-
-# Program for reformatting trace buffer output according to user-supplied rules
-
-from __future__ import division
-from __future__ import print_function
-from __future__ import unicode_literals
-from builtins import str
-import re, sys, string, signal, struct, os, getopt
-
-def usage():
- print("Usage: " + sys.argv[0] + """ defs-file
- Parses trace data in binary format, as output by Xentrace and
- reformats it according to the rules in a file of definitions. The
- rules in this file should have the format ({ and } show grouping
- and are not part of the syntax):
-
- {event_id}{whitespace}{text format string}
-
- The textual format string may include format specifiers, such as:
- %(cpu)d, %(tsc)d, %(event)d, %(1)d, %(2)d, %(3)d, %(4)d, ...
- [ the 'd' format specifier outputs in decimal, alternatively 'x'
- will output in hexadecimal and 'o' will output in octal ]
-
- Which correspond to the CPU number, event ID, timestamp counter and
- the 7 data fields from the trace record. There should be one such
- rule for each type of event.
-
- Depending on your system and the volume of trace buffer data,
- this script may not be able to keep up with the output of xentrace
- if it is piped directly. In these circumstances you should have
- xentrace output to a file for processing off-line.
- """, file=sys.stderr)
- sys.exit(1)
-
-def read_defs(defs_file):
- defs = {}
-
- fd = open(defs_file)
-
- reg = re.compile('(\S+)\s+(\S.*)')
-
- while True:
- line = fd.readline()
- if not line:
- break
-
- if line[0] == '#' or line[0] == '\n':
- continue
-
- m = reg.match(line)
-
- if not m: print("Bad format file", file=sys.stderr) ; sys.exit(1)
-
- defs[str(eval(m.group(1)))] = m.group(2)
-
- return defs
-
-def sighand(x,y):
- global interrupted
- interrupted = 1
-
-##### Main code
-
-mhz = 0
-
-if len(sys.argv) < 2:
- usage()
-
-try:
- opts, arg = getopt.getopt(sys.argv[1:], "c:" )
-
- for opt in opts:
- if opt[0] == '-c' : mhz = int(opt[1])
-
-except getopt.GetoptError:
- usage()
-
-signal.signal(signal.SIGTERM, sighand)
-signal.signal(signal.SIGHUP, sighand)
-signal.signal(signal.SIGINT, sighand)
-
-interrupted = 0
-
-try:
- defs = read_defs(arg[0])
-except IOError as exn:
- print(exn)
- sys.exit(1)
-
-# structure of trace record (as output by xentrace):
-# HDR(I) {TSC(Q)} D1(I) D2(I) D3(I) D4(I) D5(I) D6(I) D7(I)
-#
-# HDR consists of EVENT:28:, n_data:3:, tsc_in:1:
-# 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.
-#
-# CPU ID exists on trace data of EVENT=0x0001f003
-#
-HDRREC = "I"
-TSCREC = "Q"
-D1REC = "I"
-D2REC = "II"
-D3REC = "III"
-D4REC = "IIII"
-D5REC = "IIIII"
-D6REC = "IIIIII"
-D7REC = "IIIIIII"
-
-last_tsc = [0]
-
-TRC_TRACE_IRQ = 0x1f004
-TRC_PV_HYPERCALL_V2 = 0x20100d
-TRC_PV_HYPERCALL_SUBCALL = 0x20100e
-
-NR_VECTORS = 256
-irq_measure = [{'count':0, 'tot_cycles':0, 'max_cycles':0}] * NR_VECTORS
-
-if sys.version_info >= (3, 0):
- stdin_bytes = sys.stdin.buffer
-else:
- stdin_bytes = sys.stdin
-
-i=0
-
-while not interrupted:
- try:
- i=i+1
- line = stdin_bytes.read(struct.calcsize(HDRREC))
- if not line:
- break
- event = struct.unpack(HDRREC, line)[0]
- n_data = event >> 28 & 0x7
- tsc_in = event >> 31
-
- d1 = 0
- d2 = 0
- d3 = 0
- d4 = 0
- d5 = 0
- d6 = 0
- d7 = 0
-
- tsc = 0
-
- if tsc_in == 1:
- line = stdin_bytes.read(struct.calcsize(TSCREC))
- if not line:
- break
- tsc = struct.unpack(TSCREC, line)[0]
-
- if n_data == 1:
- line = stdin_bytes.read(struct.calcsize(D1REC))
- if not line:
- break
- d1 = struct.unpack(D1REC, line)[0]
- if n_data == 2:
- line = stdin_bytes.read(struct.calcsize(D2REC))
- if not line:
- break
- (d1, d2) = struct.unpack(D2REC, line)
- if n_data == 3:
- line = stdin_bytes.read(struct.calcsize(D3REC))
- if not line:
- break
- (d1, d2, d3) = struct.unpack(D3REC, line)
- if n_data == 4:
- line = stdin_bytes.read(struct.calcsize(D4REC))
- if not line:
- break
- (d1, d2, d3, d4) = struct.unpack(D4REC, line)
- if n_data == 5:
- line = stdin_bytes.read(struct.calcsize(D5REC))
- if not line:
- break
- (d1, d2, d3, d4, d5) = struct.unpack(D5REC, line)
- if n_data == 6:
- line = stdin_bytes.read(struct.calcsize(D6REC))
- if not line:
- break
- (d1, d2, d3, d4, d5, d6) = struct.unpack(D6REC, line)
- if n_data == 7:
- line = stdin_bytes.read(struct.calcsize(D7REC))
- if not line:
- break
- (d1, d2, d3, d4, d5, d6, d7) = struct.unpack(D7REC, line)
-
- # Event field is 28bit of 'uint32_t' in header, not 'long'.
- event &= 0x0fffffff
- if event == 0x1f003:
- cpu = d1
-
- if event == TRC_TRACE_IRQ:
- # IN - d1:vector, d2:tsc_in, d3:tsc_out
- # OUT - d1:vector, d2:count, d3:tot_cycles, d4:max_cycles
- tsc_diff = d3 - d2
- if tsc_diff < 0:
- break
- irq_measure[d1]['count'] += 1
- irq_measure[d1]['tot_cycles'] += tsc_diff
- if irq_measure[d1]['max_cycles'] < tsc_diff:
- irq_measure[d1]['max_cycles'] = tsc_diff
- d2 = irq_measure[d1]['count']
- d3 = irq_measure[d1]['tot_cycles']
- d4 = irq_measure[d1]['max_cycles']
-
- if event == TRC_PV_HYPERCALL_V2 or event == TRC_PV_HYPERCALL_SUBCALL:
- # Mask off the argument present bits.
- d1 &= 0x000fffff
-
- #tsc = (tscH<<32) | tscL
-
- #print i, tsc
-
- if cpu >= len(last_tsc):
- last_tsc += [0] * (cpu - len(last_tsc) + 1)
- elif tsc < last_tsc[cpu] and tsc_in == 1:
- print("TSC stepped backward cpu %d ! %d %d" % (cpu,tsc,last_tsc[cpu]))
-
- # provide relative TSC
- if last_tsc[cpu] > 0 and tsc_in == 1:
- reltsc = tsc - last_tsc[cpu]
- else:
- reltsc = 0
-
- if tsc_in == 1:
- last_tsc[cpu] = tsc
-
- if mhz:
- tsc = tsc / (mhz*1000000.0)
-
- args = {'cpu' : cpu,
- 'tsc' : tsc,
- 'event' : event,
- 'reltsc': reltsc,
- '1' : d1,
- '2' : d2,
- '3' : d3,
- '4' : d4,
- '5' : d5,
- '6' : d6,
- '7' : d7 }
-
- try:
-
- if str(event) in defs:
- print(defs[str(event)] % args)
- else:
- if str(0) in defs: print(defs[str(0)] % args)
- except TypeError:
- if str(event) in defs:
- print(defs[str(event)])
- print(args)
- else:
- if str(0) in defs:
- print(defs[str(0)])
- print(args)
-
-
- except (IOError, struct.error): sys.exit()
--
2.25.1
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH 3/3] tools/xentrace: Remove xentrace_format
2024-04-26 14:32 ` [PATCH 3/3] tools/xentrace: Remove xentrace_format George Dunlap
@ 2024-04-26 15:03 ` Andrew Cooper
2024-04-26 19:50 ` Olaf Hering
1 sibling, 0 replies; 11+ messages in thread
From: Andrew Cooper @ 2024-04-26 15:03 UTC (permalink / raw)
To: George Dunlap, xen-devel
Cc: Jan Beulich, Roger Pau Monne, Anthony Perard, Olaf Hering
On 26/04/2024 3:32 pm, George Dunlap wrote:
> xentrace_format was always of limited utility, since trace records
> across pcpus were processed out of order; it was superseded by xenalyze
> over a decade ago.
>
> But for several releases, the `formats` file it has depended on for
> proper operation has not even been included in `make install` (which
> generally means it doesn't get picked up by distros either); yet
> nobody has seemed to complain.
>
> Simple remove xentrace_format, and point people to xenalyze instead.
>
> NB that there is no man page for xenalyze, so the "see also" on the
> xentrace man page is simply removed for now.
>
> Signed-off-by: George Dunlap <george.dunlap@cloud.com>
Acked-by: Andrew Cooper <andrew.cooper3@citrix.com>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder
2024-04-26 14:32 ` [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder George Dunlap
@ 2024-04-26 15:06 ` Andrew Cooper
2024-04-26 15:13 ` George Dunlap
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Cooper @ 2024-04-26 15:06 UTC (permalink / raw)
To: George Dunlap, xen-devel; +Cc: Anthony Perard, Olaf Hering
On 26/04/2024 3:32 pm, George Dunlap wrote:
> To unify certain common sanity checks, checks are done very early in
> processing based only on the top-level type.
>
> Unfortunately, when TRC_HVM_EMUL was introduced, it broke some of the
> assumptions about how the top-level types worked. Namely, traces of
> this type will show up outside of HVM contexts: in idle domains and in
> PV domains.
>
> Make an explicit exception for TRC_HVM_EMUL types in a number of places:
>
> - Pass the record info pointer to toplevel_assert_check, so that it
> can exclude TRC_HVM_EMUL records from idle and vcpu data_mode
> checks
>
> - Don't attempt to set the vcpu data_type in hvm_process for
> TRC_HVM_EMUL records.
>
> Signed-off-by: George Dunlap <george.dunlap@cloud.com>
Acked-by: Andrew Cooper <andrew.cooper3@citrix.com>
Although I'm tempted to say that if records of this type show up outside
of HVM context, then it's misnamed or we've got an error in Xen. Any
view on which?
~Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder
2024-04-26 15:06 ` Andrew Cooper
@ 2024-04-26 15:13 ` George Dunlap
0 siblings, 0 replies; 11+ messages in thread
From: George Dunlap @ 2024-04-26 15:13 UTC (permalink / raw)
To: Andrew Cooper; +Cc: xen-devel, Anthony Perard, Olaf Hering
On Fri, Apr 26, 2024 at 4:06 PM Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>
> On 26/04/2024 3:32 pm, George Dunlap wrote:
> > To unify certain common sanity checks, checks are done very early in
> > processing based only on the top-level type.
> >
> > Unfortunately, when TRC_HVM_EMUL was introduced, it broke some of the
> > assumptions about how the top-level types worked. Namely, traces of
> > this type will show up outside of HVM contexts: in idle domains and in
> > PV domains.
> >
> > Make an explicit exception for TRC_HVM_EMUL types in a number of places:
> >
> > - Pass the record info pointer to toplevel_assert_check, so that it
> > can exclude TRC_HVM_EMUL records from idle and vcpu data_mode
> > checks
> >
> > - Don't attempt to set the vcpu data_type in hvm_process for
> > TRC_HVM_EMUL records.
> >
> > Signed-off-by: George Dunlap <george.dunlap@cloud.com>
>
> Acked-by: Andrew Cooper <andrew.cooper3@citrix.com>
>
> Although I'm tempted to say that if records of this type show up outside
> of HVM context, then it's misnamed or we've got an error in Xen. Any
> view on which?
I didn't add them; they seem to be about doing emulation of devices on
behalf of an HVM domain. But since some of these are things like
timers and such, the actual code ends up being run in random contexts;
probably interrupt contexts (which of course can occur when a non-HVM
guest is running).
One example of an event that showed up this way was
TRC_HVM_EMUL_RTC_STOP_TIMER, which is traced from
xen/arch/x86/hvm/rtc.c:rtc_pf_callback(). I didn't trace back how it
came to be called while a PV guest was running, but it was pretty
obvious that it was legit.
It would certainly make the xenalyze code cleaner to make a separate
top-level tracing category for them; but they certainly do seem to be
directly related to HVM, so doing so would seem to be putting the cart
before the horse, as they say (although I could be convinced
otherwise).
-George
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors
2024-04-26 14:32 ` [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors George Dunlap
@ 2024-04-26 15:18 ` Andrew Cooper
2024-04-26 15:29 ` George Dunlap
0 siblings, 1 reply; 11+ messages in thread
From: Andrew Cooper @ 2024-04-26 15:18 UTC (permalink / raw)
To: George Dunlap, xen-devel
Cc: Jan Beulich, Roger Pau Monne, Anthony Perard, Stefano Stabellini,
Julien Grall, Olaf Hering
On 26/04/2024 3:32 pm, George Dunlap wrote:
> A long-standing usability sub-optimality with xenalyze is the
> necessity to specify `--svm-mode` when analyzing AMD processors. This
> fundamentally comes about because the same trace event ID is used for
> both VMX and SVM, but the contents of the trace must be interpreted
> differently.
>
> Instead, allocate separate trace events for VMX and SVM vmexits in
> Xen; this will allow all readers to properly intrepret the meaning of
interpret ?
> the vmexit reason.
>
> In xenalyze, first remove the redundant call to init_hvm_data();
> there's no way to get to hvm_vmexit_process() without it being already
> initialized by the set_vcpu_type call in hvm_process().
>
> Replace this with set_hvm_exit_reson_data(), and move setting of
> hvm->exit_reason_* into that function.
>
> Modify hvm_process and hvm_vmexit_process to handle all four potential
> values appropriately.
>
> If SVM entries are encountered, set opt.svm_mode so that other
> SVM-specific functionality is triggered.
Given that xenalyze is now closely tied to Xen, and that we're
technically changing the ABI here, is there any point keeping `--svm-mode` ?
I'm unsure of the utility of reading the buggy trace records from an
older version of Xen.
> Also add lines in `formats` for xentrace_format.
Personally I'd have put patch 3 first, and reduced the churn here.
> Signed-off-by: George Dunlap <george.dunlap@cloud.com>
> ---
> NB that this patch goes on top of Andrew's trace cleanup series:
>
> https://lore.kernel.org/xen-devel/20240318163552.3808695-1-andrew.cooper3@citrix.com/
The delta in Xen is trivial. I'm happy if you want to commit this, and
I can rebase over it.
~Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors
2024-04-26 15:18 ` Andrew Cooper
@ 2024-04-26 15:29 ` George Dunlap
2024-04-26 15:45 ` Andrew Cooper
0 siblings, 1 reply; 11+ messages in thread
From: George Dunlap @ 2024-04-26 15:29 UTC (permalink / raw)
To: Andrew Cooper
Cc: xen-devel, Jan Beulich, Roger Pau Monne, Anthony Perard,
Stefano Stabellini, Julien Grall, Olaf Hering
On Fri, Apr 26, 2024 at 4:18 PM Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>
> On 26/04/2024 3:32 pm, George Dunlap wrote:
> > A long-standing usability sub-optimality with xenalyze is the
> > necessity to specify `--svm-mode` when analyzing AMD processors. This
> > fundamentally comes about because the same trace event ID is used for
> > both VMX and SVM, but the contents of the trace must be interpreted
> > differently.
> >
> > Instead, allocate separate trace events for VMX and SVM vmexits in
> > Xen; this will allow all readers to properly intrepret the meaning of
>
> interpret ?
Oops, yes.
> > In xenalyze, first remove the redundant call to init_hvm_data();
> > there's no way to get to hvm_vmexit_process() without it being already
> > initialized by the set_vcpu_type call in hvm_process().
> >
> > Replace this with set_hvm_exit_reson_data(), and move setting of
> > hvm->exit_reason_* into that function.
> >
> > Modify hvm_process and hvm_vmexit_process to handle all four potential
> > values appropriately.
> >
> > If SVM entries are encountered, set opt.svm_mode so that other
> > SVM-specific functionality is triggered.
>
> Given that xenalyze is now closely tied to Xen, and that we're
> technically changing the ABI here, is there any point keeping `--svm-mode` ?
>
> I'm unsure of the utility of reading the buggy trace records from an
> older version of Xen.
Yeah, I thought about that. If nobody argues to keep it, I guess I'll
rip it out for v2.
> > Also add lines in `formats` for xentrace_format.
>
> Personally I'd have put patch 3 first, and reduced the churn here.
I actually meant to add an `RFC` to the third patch. I'd already
implemented this by the time you suggested ripping it out. Doing it
this way doesn't add much overhead if we do end up ripping out
xentrace_format, and does save time if we don't.
> > Signed-off-by: George Dunlap <george.dunlap@cloud.com>
> > ---
> > NB that this patch goes on top of Andrew's trace cleanup series:
> >
> > https://lore.kernel.org/xen-devel/20240318163552.3808695-1-andrew.cooper3@citrix.com/
>
> The delta in Xen is trivial. I'm happy if you want to commit this, and
> I can rebase over it.
It's trivial in part *because of* your series. Without your series I
would have had to do a bunch of munging around with DO_TRC_BLAH_BLAH
to make it compile. In fact, I started doing it directly on staging,
but quickly moved onto your series to save myself some time. :-)
Since I'm planning on re-submitting your series if you don't (unless
you really object), this way should minimize churn.
I'm happy to post a branch to gitlab if anyone wants to see the combined result.
-George
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors
2024-04-26 15:29 ` George Dunlap
@ 2024-04-26 15:45 ` Andrew Cooper
0 siblings, 0 replies; 11+ messages in thread
From: Andrew Cooper @ 2024-04-26 15:45 UTC (permalink / raw)
To: George Dunlap
Cc: xen-devel, Jan Beulich, Roger Pau Monne, Anthony Perard,
Stefano Stabellini, Julien Grall, Olaf Hering
On 26/04/2024 4:29 pm, George Dunlap wrote:
> On Fri, Apr 26, 2024 at 4:18 PM Andrew Cooper <andrew.cooper3@citrix.com> wrote:
>> On 26/04/2024 3:32 pm, George Dunlap wrote:
>>> In xenalyze, first remove the redundant call to init_hvm_data();
>>> there's no way to get to hvm_vmexit_process() without it being already
>>> initialized by the set_vcpu_type call in hvm_process().
>>>
>>> Replace this with set_hvm_exit_reson_data(), and move setting of
>>> hvm->exit_reason_* into that function.
>>>
>>> Modify hvm_process and hvm_vmexit_process to handle all four potential
>>> values appropriately.
>>>
>>> If SVM entries are encountered, set opt.svm_mode so that other
>>> SVM-specific functionality is triggered.
>> Given that xenalyze is now closely tied to Xen, and that we're
>> technically changing the ABI here, is there any point keeping `--svm-mode` ?
>>
>> I'm unsure of the utility of reading the buggy trace records from an
>> older version of Xen.
> Yeah, I thought about that. If nobody argues to keep it, I guess I'll
> rip it out for v2.
That's the way I'd suggest going.
>>> Signed-off-by: George Dunlap <george.dunlap@cloud.com>
>>> ---
>>> NB that this patch goes on top of Andrew's trace cleanup series:
>>>
>>> https://lore.kernel.org/xen-devel/20240318163552.3808695-1-andrew.cooper3@citrix.com/
>> The delta in Xen is trivial. I'm happy if you want to commit this, and
>> I can rebase over it.
> It's trivial in part *because of* your series. Without your series I
> would have had to do a bunch of munging around with DO_TRC_BLAH_BLAH
> to make it compile. In fact, I started doing it directly on staging,
> but quickly moved onto your series to save myself some time. :-)
Ah. I'll be refreshing mine next week. Given that it's missed
everything since 4.16, I'm not intending to let it miss this one...
But I've still got a few things which need to go out before the
past-post deadline.
~Andrew
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: [PATCH 3/3] tools/xentrace: Remove xentrace_format
2024-04-26 14:32 ` [PATCH 3/3] tools/xentrace: Remove xentrace_format George Dunlap
2024-04-26 15:03 ` Andrew Cooper
@ 2024-04-26 19:50 ` Olaf Hering
1 sibling, 0 replies; 11+ messages in thread
From: Olaf Hering @ 2024-04-26 19:50 UTC (permalink / raw)
To: George Dunlap
Cc: xen-devel, Andrew Cooper, Jan Beulich, Roger Pau Monne, Anthony Perard
[-- Attachment #1: Type: text/plain, Size: 200 bytes --]
Fri, 26 Apr 2024 15:32:31 +0100 George Dunlap <george.dunlap@cloud.com>:
> Simple remove xentrace_format, and point people to xenalyze instead.
Acked-by: Olaf Hering <olaf@aepfle.de>
Olaf
[-- Attachment #2: Digitale Signatur von OpenPGP --]
[-- Type: application/pgp-signature, Size: 833 bytes --]
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2024-04-26 19:50 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2024-04-26 14:32 [PATCH 0/3] Further trace improvements George Dunlap
2024-04-26 14:32 ` [PATCH 1/3] x86/hvm/trace: Use a different trace type for AMD processors George Dunlap
2024-04-26 15:18 ` Andrew Cooper
2024-04-26 15:29 ` George Dunlap
2024-04-26 15:45 ` Andrew Cooper
2024-04-26 14:32 ` [PATCH 2/3] tools/xenalyze: Ignore HVM_EMUL events harder George Dunlap
2024-04-26 15:06 ` Andrew Cooper
2024-04-26 15:13 ` George Dunlap
2024-04-26 14:32 ` [PATCH 3/3] tools/xentrace: Remove xentrace_format George Dunlap
2024-04-26 15:03 ` Andrew Cooper
2024-04-26 19:50 ` Olaf Hering
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).