Updates made recently. Improved areas include: * Handling of generic records * Handling of VMEXITs that have multiple kinds of traces * Handling of MMIO records for non-pagefault traces * Handling of cr3 enumeration avlues * Speed improvement for dump mode
George Dunlap
2011-Nov-28 16:17 UTC
[PATCH 01 of 12] xenalyze: Allow several summary handlers to register on a single vmexit
VMX tends to have several distinct kinds of handlers for a single vmexit type; notably, EXCEPTION_NMI gets page faults, other traps, emulations, and sometimes other kinds of traps as well; while for SVM, each different trap has a different call type. This patch introduces a signal-style callback mechanism that allows several callbacks to be attached to a given exit reason. Each of these callbacks will be called in the case of a summary event. In order to distinguish different kinds of callbacks, the callback also includes a value which is passed as-is to the function when it''s called. It''s the size of a pointer so that it can be used as a pointer if necessary; typically it will probably be a small integer value. Each vmexit should only register a handler once with any given data value; there is some syntactic sugar to make sure this happens. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 288573cb0f11 -r 2e85d4c4042e xenalyze.c --- a/xenalyze.c Fri Oct 07 11:49:04 2011 +0100 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -1308,6 +1308,14 @@ struct pcpu_info; #define RESYNCS_MAX 17 #define PF_XEN_FIXUP_UNSYNC_RESYNC_MAX 2 +struct hvm_data; + +struct hvm_summary_handler_node { + void (*handler)(struct hvm_data *, void* data); + void *data; + struct hvm_summary_handler_node *next; +}; + struct hvm_data { /* Summary information */ int init; @@ -1318,7 +1326,7 @@ struct hvm_data { /* SVM / VMX compatibility. FIXME - should be global */ char ** exit_reason_name; int exit_reason_max; - void (* exit_reason_summary_handler[HVM_EXIT_REASON_MAX])(struct hvm_data *); + struct hvm_summary_handler_node *exit_reason_summary_handler_list[HVM_EXIT_REASON_MAX]; /* Information about particular exit reasons */ struct { @@ -3011,23 +3019,58 @@ void hvm_short_summary(struct hvm_short_ } } -void hvm_set_summary_handler(struct hvm_data *h, void (*s)(struct hvm_data *h)) { +/* Wrapper to try to make sure this is only called once per + * call site, rather than walking through the list each time */ +#define hvm_set_summary_handler(_h, _s, _d) \ + do { \ + static int done=0; \ + int ret; \ + if(!done) { \ + if ((ret=__hvm_set_summary_handler(_h, _s, _d))) \ + fprintf(stderr, "%s: hvm_set_summary_handler returned %d\n", \ + __func__, ret); \ + done=1; \ + } \ + } while(0) + +int __hvm_set_summary_handler(struct hvm_data *h, void (*s)(struct hvm_data *h, void*d), void*d) { /* Set summary handler */ if(h->exit_reason < h->exit_reason_max) { - if(h->exit_reason_summary_handler[h->exit_reason]) + struct hvm_summary_handler_node *p, **q; + + /* Find the end of the list, checking to make sure there are no + * duplicates along the way */ + q=&h->exit_reason_summary_handler_list[h->exit_reason]; + p = *q; + while(p) { - if(h->exit_reason_summary_handler[h->exit_reason]!= s) - fprintf(warn, "Strange, unexpected summary handler for exit_reason %s (%d!)\n", - h->exit_reason_name[h->exit_reason], h->exit_reason); - } - else - { - h->exit_reason_summary_handler[h->exit_reason] = s; - fprintf(warn, "Setting exit_reason %s (%d) summary handler\n", - h->exit_reason_name[h->exit_reason], h->exit_reason); - } - } + if(p->handler == s && p->data == d) + { + fprintf(stderr, "%s: Unexpected duplicate handler %p,%p\n", + __func__, s, d); + error(ERR_STRICT, NULL); + return -EBUSY; + } + q=&p->next; + p=*q; + } + + assert(p==NULL); + + /* Insert the new handler */ + p=malloc(sizeof(*p)); + if (!p) { + fprintf(stderr, "%s: Malloc failed!\n", __func__); + error(ERR_SYSTEM, NULL); + } + p->handler=s; + p->data = d; + p->next=*q; + *q=p; + return 0; + } + return -EINVAL; } #define SIGN_EXTENDED_BITS (~((1ULL<<48)-1)) @@ -3040,7 +3083,7 @@ static inline int is_valid_addr64(unsign return ((va & SIGN_EXTENDED_BITS) == 0); } -void hvm_pf_xen_summary(struct hvm_data *h) { +void hvm_pf_xen_summary(struct hvm_data *h, void *d) { int i,j, k; for(i=0; i<PF_XEN_MAX; i++) @@ -3314,7 +3357,7 @@ void hvm_pf_xen_postprocess(struct hvm_d } /* Set summary handler */ - hvm_set_summary_handler(h, hvm_pf_xen_summary); + hvm_set_summary_handler(h, hvm_pf_xen_summary, NULL); } if(opt.dump_cooked) @@ -4061,7 +4104,7 @@ void cr3_dump_list(struct cr3_value_stru free(qsort_array); } -void hvm_cr3_write_summary(struct hvm_data *h) { +void hvm_cr3_write_summary(struct hvm_data *h, void *data) { int j; for(j=0; j<RESYNCS_MAX; j++) @@ -4071,7 +4114,7 @@ void hvm_cr3_write_summary(struct hvm_da " *[MAX] "); } -void hvm_cr_write_summary(struct hvm_data *h) +void hvm_cr_write_summary(struct hvm_data *h, void *data) { int i; @@ -4081,7 +4124,7 @@ void hvm_cr_write_summary(struct hvm_dat " cr%d ", i); switch(i) { case 3: - hvm_cr3_write_summary(h); + hvm_cr3_write_summary(h, NULL); break; } } @@ -4168,11 +4211,11 @@ void hvm_cr_write_postprocess(struct hvm if ( opt.svm_mode ) { /* For svm, only need a summary for cr3 */ if ( h->exit_reason == VMEXIT_CR3_WRITE ) - hvm_set_summary_handler(h, hvm_cr3_write_summary); + hvm_set_summary_handler(h, hvm_cr3_write_summary, NULL); } else { /* For vmx, real mode may cause EXNMI exits on cr accesses */ if ( h->exit_reason != EXIT_REASON_EXCEPTION_NMI ) - hvm_set_summary_handler(h, hvm_cr_write_summary); + hvm_set_summary_handler(h, hvm_cr_write_summary, NULL); } } } @@ -4229,7 +4272,7 @@ void hvm_cr_write_process(struct record_ } /* msr_write */ -void hvm_msr_write_summary(struct hvm_data *h) +void hvm_msr_write_summary(struct hvm_data *h, void *d) { } @@ -4247,7 +4290,7 @@ void hvm_msr_write_postprocess(struct hv } /* Set summary handler */ - hvm_set_summary_handler(h, hvm_msr_write_summary); + hvm_set_summary_handler(h, hvm_msr_write_summary, NULL); } void hvm_msr_write_process(struct record_info *ri, struct hvm_data *h) @@ -4274,7 +4317,7 @@ void hvm_msr_write_process(struct record } /* msr_read */ -void hvm_msr_read_summary(struct hvm_data *h) +void hvm_msr_read_summary(struct hvm_data *h, void *d) { } @@ -4292,7 +4335,7 @@ void hvm_msr_read_postprocess(struct hvm } /* Set summary handler */ - hvm_set_summary_handler(h, hvm_msr_read_summary); + hvm_set_summary_handler(h, hvm_msr_read_summary, NULL); } void hvm_msr_read_process(struct record_info *ri, struct hvm_data *h) @@ -4318,7 +4361,7 @@ void hvm_msr_read_process(struct record_ h->post_process = hvm_msr_read_postprocess; } -void hvm_vmcall_summary(struct hvm_data *h) +void hvm_vmcall_summary(struct hvm_data *h, void *d) { int i; @@ -4343,6 +4386,7 @@ void hvm_vmcall_postprocess(struct hvm_d else update_summary(&h->summary.vmcall[HYPERCALL_MAX], h->arc_cycles); + hvm_set_summary_handler(h, hvm_vmcall_summary, NULL); } } @@ -4365,7 +4409,6 @@ void hvm_vmcall_process(struct record_in } if(opt.summary) { - hvm_set_summary_handler(h, hvm_vmcall_summary); h->inflight.vmcall.eax = r->eax; h->post_process = hvm_vmcall_postprocess; } @@ -4391,7 +4434,7 @@ void hvm_inj_exc_process(struct record_i } -void hvm_intr_summary(struct hvm_data *h) +void hvm_intr_summary(struct hvm_data *h, void *d) { int i; @@ -4483,7 +4526,7 @@ void hvm_intr_process(struct hvm_data *h if(opt.summary_info) { if(opt.summary) - hvm_set_summary_handler(h, hvm_intr_summary); + hvm_set_summary_handler(h, hvm_intr_summary, NULL); if(vec < EXTERNAL_INTERRUPT_MAX) h->summary.extint[vec]++; @@ -5321,6 +5364,8 @@ void hvm_summary(struct hvm_data *h) { printf("Exit reasons:\n"); for(i=0; i<h->exit_reason_max; i++) { + struct hvm_summary_handler_node *p; + if ( h->exit_reason_name[i] ) PRINT_SUMMARY(h->summary.exit_reason[i], " %-20s ", h->exit_reason_name[i]); @@ -5328,8 +5373,12 @@ void hvm_summary(struct hvm_data *h) { PRINT_SUMMARY(h->summary.exit_reason[i], " %20d ", i); - if(h->exit_reason_summary_handler[i]) - h->exit_reason_summary_handler[i](h); + p=h->exit_reason_summary_handler_list[i]; + while(p) + { + p->handler(h, p->data); + p=p->next; + } } printf("Guest interrupt counts:\n"); @@ -6238,7 +6287,7 @@ void shadow_process(struct pcpu_info *p) if(sevt.minor <= PF_XEN_LAST_FAULT) { h->inflight.pf_xen.pf_case = sevt.minor; if(opt.summary) { - hvm_set_summary_handler(h, hvm_pf_xen_summary); + hvm_set_summary_handler(h, hvm_pf_xen_summary, NULL); } }
George Dunlap
2011-Nov-28 16:17 UTC
[PATCH 02 of 12] xenalyze: Reorganize cr trace handling
Reorganize the CR trace handling to take advantage of the new summary handling. In particular, SVM has an exit per CR register, while VMX has one exit for all CR accesses. This allows them to coexist. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 2e85d4c4042e -r 6650e492be5d xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -4104,7 +4104,7 @@ void cr3_dump_list(struct cr3_value_stru free(qsort_array); } -void hvm_cr3_write_summary(struct hvm_data *h, void *data) { +void hvm_cr3_write_summary(struct hvm_data *h) { int j; for(j=0; j<RESYNCS_MAX; j++) @@ -4116,18 +4116,12 @@ void hvm_cr3_write_summary(struct hvm_da void hvm_cr_write_summary(struct hvm_data *h, void *data) { - int i; - - for(i=0; i<CR_MAX; i++) - { - PRINT_SUMMARY(h->summary.cr_write[i], - " cr%d ", i); - switch(i) { - case 3: - hvm_cr3_write_summary(h, NULL); - break; - } - } + int cr=(int)data; + + PRINT_SUMMARY(h->summary.cr_write[cr], + " cr%d ", cr); + if ( cr==3 ) + hvm_cr3_write_summary(h); } void hvm_cr_write_postprocess(struct hvm_data *h) @@ -4208,20 +4202,39 @@ void hvm_cr_write_postprocess(struct hvm /* FIXME - deal with cr_read_summary */ if(h->exit_reason < h->exit_reason_max) { - if ( opt.svm_mode ) { - /* For svm, only need a summary for cr3 */ - if ( h->exit_reason == VMEXIT_CR3_WRITE ) - hvm_set_summary_handler(h, hvm_cr3_write_summary, NULL); - } else { - /* For vmx, real mode may cause EXNMI exits on cr accesses */ - if ( h->exit_reason != EXIT_REASON_EXCEPTION_NMI ) - hvm_set_summary_handler(h, hvm_cr_write_summary, NULL); + /* Want a different "set" for each cr */ + switch(h->inflight.cr_write.cr) + { +#define case_cr(_x) \ + case (_x): \ + hvm_set_summary_handler(h, hvm_cr_write_summary, (void *)(_x)); \ + break + case_cr(0); + case_cr(1); + case_cr(2); + case_cr(3); + case_cr(4); + case_cr(5); + case_cr(6); + case_cr(7); + case_cr(8); + case_cr(9); + case_cr(10); + case_cr(11); + case_cr(12); + case_cr(13); + case_cr(14); + case_cr(15); +#undef case_cr + default: + fprintf(stderr, "Unexpected cr: %d\n", h->inflight.cr_write.cr); + error(ERR_SANITY, NULL); + break; } } } void hvm_exception_nmi_generic_postprocess(struct hvm_data *h); - void hvm_cr_write_process(struct record_info *ri, struct hvm_data *h) { union {
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 03 of 12] xenalyze: Function-ize setting of h->post_process
Introduce hvm_set_postprocess, so that we can make changes to the setting and warning all in one place. Special-case hvm_exception_nmi_generic_postprocess for now to avoid regression; will get rid of it in the next c/s Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 6650e492be5d -r 47d436ca14d1 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -3073,6 +3073,20 @@ int __hvm_set_summary_handler(struct hvm return -EINVAL; } +void hvm_exception_nmi_generic_postprocess(struct hvm_data *h); + +static int hvm_set_postprocess(struct hvm_data *h, void (*s)(struct hvm_data *h)) +{ + if ( h->post_process == NULL + || h->post_process == hvm_exception_nmi_generic_postprocess ) + { + h->post_process = s; + return 0; + } + else + return 1; +} + #define SIGN_EXTENDED_BITS (~((1ULL<<48)-1)) #define HIGH_BIT(_v) ((_v) & (1ULL<<47)) static inline int is_valid_addr64(unsigned long long va) @@ -3416,7 +3430,8 @@ void hvm_pf_xen_process(struct record_in e->pt_index[4]); } - h->post_process = hvm_pf_xen_postprocess; + if ( hvm_set_postprocess(h, hvm_pf_xen_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } char * hvm_vlapic_icr_dest_shorthand_name[4] = { @@ -3703,10 +3718,9 @@ void hvm_mmio_assist_process(struct reco if((e->gpa & 0xfffff000) == 0xfee00000) hvm_vlapic_handler(h); - /* Catch MMIOs that don''t go through the shadow code */ - if ( h->post_process == NULL ) - h->post_process = hvm_mmio_assist_postprocess; - + /* Catch MMIOs that don''t go through the shadow code; tolerate + * failures to set (probably shadow_mmio) */ + hvm_set_postprocess(h, hvm_mmio_assist_postprocess); } void hvm_inj_virq_process(struct record_info *ri, struct hvm_data *h) { @@ -3889,10 +3903,12 @@ void hvm_io_assist_process(struct record if(mevt.write) { h->inflight.io.is_write = 1; - h->post_process = hvm_io_write_postprocess; + if ( hvm_set_postprocess(h, hvm_io_write_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } else { h->inflight.io.is_write = 0; - h->post_process = hvm_io_read_postprocess; + if ( hvm_set_postprocess(h, hvm_io_read_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } if(opt.dump_all) @@ -4234,7 +4250,6 @@ void hvm_cr_write_postprocess(struct hvm } } -void hvm_exception_nmi_generic_postprocess(struct hvm_data *h); void hvm_cr_write_process(struct record_info *ri, struct hvm_data *h) { union { @@ -4258,13 +4273,11 @@ void hvm_cr_write_process(struct record_ h->inflight.cr_write.val = val = r->x32.val; } - /* In real mode, cr accesses may cause EXNMI vmexits */ - if ( !h->post_process - || (!opt.svm_mode - && h->post_process == hvm_exception_nmi_generic_postprocess) ) - h->post_process = hvm_cr_write_postprocess; - else - fprintf(warn, "Strange, h->postprocess already set!\n"); + /* In vmx, in real mode, cr accesses may cause EXNMI vmexits. + * Account them under that heading; otherwise, complain */ + if ( hvm_set_postprocess(h, hvm_cr_write_postprocess) ) + fprintf(warn, "%s: Strange, h->postprocess already set!\n", + __func__); if(opt.dump_all) { @@ -4326,7 +4339,8 @@ void hvm_msr_write_process(struct record r->addr, r->val); } - h->post_process = hvm_msr_write_postprocess; + if ( hvm_set_postprocess(h, hvm_msr_write_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } /* msr_read */ @@ -4371,7 +4385,8 @@ void hvm_msr_read_process(struct record_ r->addr, r->val); } - h->post_process = hvm_msr_read_postprocess; + if ( hvm_set_postprocess(h, hvm_msr_read_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void hvm_vmcall_summary(struct hvm_data *h, void *d) @@ -4421,10 +4436,10 @@ void hvm_vmcall_process(struct record_in r->eax); } - if(opt.summary) { - h->inflight.vmcall.eax = r->eax; - h->post_process = hvm_vmcall_postprocess; - } + h->inflight.vmcall.eax = r->eax; + + if ( hvm_set_postprocess(h, hvm_vmcall_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void hvm_inj_exc_process(struct record_info *ri, struct hvm_data *h) @@ -5640,8 +5655,8 @@ void shadow_emulate_process(struct recor flag_string(e), e->flags, e->pt_level, e->corresponding_va); - h->post_process = shadow_emulate_postprocess; - + if ( hvm_set_postprocess(h, shadow_emulate_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } struct shadow_emulate_other { @@ -5776,7 +5791,8 @@ void shadow_unsync_process(struct record e->pt_level, e->corresponding_va); - h->post_process = shadow_unsync_postprocess; + if ( hvm_set_postprocess(h, shadow_unsync_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } #endif @@ -5802,7 +5818,8 @@ void shadow_emulate_other_process(struct e->gfn, e->va); - h->post_process = shadow_fault_generic_postprocess; + if ( hvm_set_postprocess(h, shadow_fault_generic_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void shadow_fixup_postprocess(struct hvm_data *h) @@ -5962,7 +5979,8 @@ void shadow_fixup_process(struct record_ flag_string(e)); } - h->post_process = shadow_fixup_postprocess; + if ( hvm_set_postprocess(h, shadow_fixup_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void shadow_mmio_postprocess(struct hvm_data *h) @@ -6058,7 +6076,8 @@ void shadow_mmio_process(struct record_i (e->pf_case==PF_XEN_FAST_MMIO)?"fast ":"", e->va); - h->post_process = shadow_mmio_postprocess; + if ( hvm_set_postprocess(h, shadow_mmio_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void shadow_propagate_postprocess(struct hvm_data *h) @@ -6150,7 +6169,8 @@ void shadow_propagate_process(struct rec e->va, e->gl1e, e->flags, flag_string(e)); - h->post_process = shadow_propagate_postprocess; + if ( hvm_set_postprocess(h, shadow_propagate_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void shadow_fault_generic_dump(unsigned int event, uint32_t *d, char *prefix, @@ -6216,7 +6236,8 @@ void shadow_fault_generic_process(struct "]", ri->dump_header); h->inflight.pf_xen.pf_case = sevt.minor; - h->post_process = shadow_fault_generic_postprocess; + if ( hvm_set_postprocess(h, shadow_fault_generic_postprocess) ) + fprintf(warn, "%s: Strange, postprocess already set\n", __func__); } void shadow_resync_process(struct record_info *ri, struct hvm_data *h)
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 04 of 12] xenalyze: Introduce generic summary functionality
Allow generic processing of hvm traces to generate summary information, connected to specific exit reasons. This makes hvm_generic_postprocess the default handler (which means it can be overriden in hvm_set_postprocess()), and also replaces hvm_exception_nmi_generic_postprocess with the hvm_generic_postprocess. Also add a handler for exits without an HVM trace, and make a header for hvm_pf_xen_summary(). Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 47d436ca14d1 -r 844117c5a51e xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -953,6 +953,7 @@ char * hvm_trap_name[HVM_TRAP_MAX] = { enum { + HVM_EVENT_HANDLER_NONE = 0, HVM_EVENT_HANDLER_PF_XEN = 1, HVM_EVENT_HANDLER_PF_INJECT, HVM_EVENT_HANDLER_INJ_EXC, @@ -984,7 +985,7 @@ enum { HVM_EVENT_HANDLER_MAX }; char * hvm_event_handler_name[HVM_EVENT_HANDLER_MAX] = { - NULL, + "(no handler)", "pf_xen", "pf_inject", "inj_exc", @@ -1343,6 +1344,7 @@ struct hvm_data { struct event_cycle_summary cr_write[CR_MAX]; struct event_cycle_summary cr3_write_resyncs[RESYNCS_MAX+1]; struct event_cycle_summary vmcall[HYPERCALL_MAX+1]; + struct event_cycle_summary generic[HVM_EVENT_HANDLER_MAX]; struct hvm_gi_struct { int count; struct cycle_summary runtime[GUEST_INTERRUPT_CASE_MAX]; @@ -3073,12 +3075,12 @@ int __hvm_set_summary_handler(struct hvm return -EINVAL; } -void hvm_exception_nmi_generic_postprocess(struct hvm_data *h); +void hvm_generic_postprocess(struct hvm_data *h); static int hvm_set_postprocess(struct hvm_data *h, void (*s)(struct hvm_data *h)) { if ( h->post_process == NULL - || h->post_process == hvm_exception_nmi_generic_postprocess ) + || h->post_process == hvm_generic_postprocess ) { h->post_process = s; return 0; @@ -3099,26 +3101,35 @@ static inline int is_valid_addr64(unsign void hvm_pf_xen_summary(struct hvm_data *h, void *d) { int i,j, k; - + + printf(" page_fault\n"); for(i=0; i<PF_XEN_MAX; i++) { - PRINT_SUMMARY(h->summary.pf_xen[i], - " %-25s ", pf_xen_name[i]); + if( pf_xen_name[i] ) + { + PRINT_SUMMARY(h->summary.pf_xen[i], + " %-25s ", pf_xen_name[i]); + } + else + { + PRINT_SUMMARY(h->summary.pf_xen[i], + " [%23d] ", i); + } switch(i){ case PF_XEN_NON_EMULATE: for(j=0; j<PF_XEN_NON_EMUL_MAX; j++) PRINT_SUMMARY(h->summary.pf_xen_non_emul[j], - " *%-13s ", pf_xen_non_emul_name[j]); + " *%-13s ", pf_xen_non_emul_name[j]); break; case PF_XEN_EMULATE: for(j=0; j<PF_XEN_EMUL_MAX; j++) { PRINT_SUMMARY(h->summary.pf_xen_emul[j], - " *%-13s ", pf_xen_emul_name[j]); + " *%-13s ", pf_xen_emul_name[j]); if(j == PF_XEN_EMUL_EARLY_UNSHADOW) { int k; for(k=0; k<5; k++) { PRINT_SUMMARY(h->summary.pf_xen_emul_early_unshadow[k], - " +[%d] ", k); + " +[%d] ", k); } } } @@ -3126,14 +3137,14 @@ void hvm_pf_xen_summary(struct hvm_data case PF_XEN_FIXUP: for(j=0; j<PF_XEN_FIXUP_MAX; j++) { PRINT_SUMMARY(h->summary.pf_xen_fixup[j], - " *%-13s ", pf_xen_fixup_name[j]); + " *%-13s ", pf_xen_fixup_name[j]); if(j == PF_XEN_FIXUP_UNSYNC ) { for(k=0; k<PF_XEN_FIXUP_UNSYNC_RESYNC_MAX; k++) { PRINT_SUMMARY(h->summary.pf_xen_fixup_unsync_resync[k], - " +[%3d] ", k); + " +[%3d] ", k); } PRINT_SUMMARY(h->summary.pf_xen_fixup_unsync_resync[k], - " +[max] "); + " +[max] "); } } break; @@ -4552,6 +4563,10 @@ void hvm_intr_process(struct hvm_data *h update_eip(&h->v->d->interrupt_eip_list, rip, 0, 0, NULL); } + /* Disable generic postprocessing */ + /* FIXME: Do the summary stuff in a post-processor */ + h->post_process = NULL; + if(opt.summary_info) { if(opt.summary) hvm_set_summary_handler(h, hvm_intr_summary, NULL); @@ -4631,25 +4646,6 @@ void hvm_pf_inject_process(struct record } } -void hvm_exception_nmi_generic_postprocess(struct hvm_data *h) -{ - static int warned = 0; - if(opt.dump_cooked) - { - printf(" %s exnmi no_handler\n", - h->dump_header); - } - - if(opt.summary_info) - update_summary(&h->summary.pf_xen[PF_XEN_NO_HANDLER], - h->arc_cycles); - - if(!warned) { - warned++; - fprintf(warn, "Strange, no handler for exnmi!\n"); - } -} - void hvm_npf_process(struct record_info *ri, struct hvm_data *h) { struct { @@ -4694,31 +4690,86 @@ void hvm_rdtsc_process(struct record_inf h->last_rdtsc = r->tsc; } +void hvm_generic_summary(struct hvm_data *h, void *data) +{ + int evt = (int)data; + + assert(evt < HVM_EVENT_HANDLER_MAX); + + PRINT_SUMMARY(h->summary.generic[evt], + " %s ", hvm_event_handler_name[evt]); + +} + void hvm_generic_postprocess(struct hvm_data *h) { + int evt = 0; + static unsigned registered[HVM_EVENT_HANDLER_MAX] = { 0 }; + + if ( h->inflight.generic.event ) + evt = (h->inflight.generic.event - TRC_HVM_HANDLER) & ~TRC_64_FLAG; + else { + static unsigned warned[HVM_EXIT_REASON_MAX] = { 0 }; + /* Some exits we don''t expect a handler; just return */ + if(opt.svm_mode) + { + } + else + { + switch(h->exit_reason) + { + /* These just need us to go through the return path */ + case EXIT_REASON_PENDING_INTERRUPT: + case EXIT_REASON_TPR_BELOW_THRESHOLD: + /* Not much to log now; may need later */ + case EXIT_REASON_WBINVD: + return; + default: + break; + } + } + if ( !warned[h->exit_reason] ) + { + /* If we aren''t a known exception, warn and log results */ + fprintf(warn, "%s: Strange, exit %x missing a handler\n", + __func__, h->exit_reason); + warned[h->exit_reason]=1; + } + } + + if ( evt > HVM_EVENT_HANDLER_MAX || evt < 0) + { + fprintf(warn, "%s: invalid hvm event %x\n", + __func__, h->inflight.generic.event); + error(ERR_RECORD, NULL); + return; + } + if(opt.summary_info) { + update_summary(&h->summary.generic[evt], + h->arc_cycles); + + /* NB that h->exit_reason may be 0, so we offset by 1 */ + if ( registered[evt] ) + { + static unsigned warned[HVM_EXIT_REASON_MAX] = { 0 }; + if ( registered[evt] != h->exit_reason+1 && !warned[h->exit_reason]) + { + fprintf(warn, "%s: HVM evt %x in %x and %x!\n", + __func__, evt, registered[evt]-1, h->exit_reason); + warned[h->exit_reason]=1; + } + } + else + { + int ret; + if((ret=__hvm_set_summary_handler(h, hvm_generic_summary, (void *)evt))) + fprintf(stderr, "%s: hvm_set_summary_handler returned %d\n", + __func__, ret); + registered[evt]=h->exit_reason+1; + } /* HLT checked at hvm_vmexit_close() */ } - - if(opt.dump_cooked) - { - int i, evt = h->event_handler; - - if(evt < HVM_EVENT_HANDLER_MAX) - printf(" %s %s [", - h->dump_header, - hvm_event_handler_name[evt]); - else - printf(" %s %d [", - h->dump_header, - evt); - - for(i=0; i<4; i++) { - printf(" %x", h->inflight.generic.d[i]); - } - - printf(" ]\n"); - } } void hvm_generic_dump(struct record_info *ri, char * prefix) @@ -4878,18 +4929,15 @@ needs_vmexit: case TRC_HVM_CLTS: case TRC_HVM_LMSW: case TRC_HVM_LMSW64: - default: - if ( h->post_process != NULL ) - fprintf(warn, "Strange, h->postprocess already set!\n"); - /* Guest NMI should expect h->postprocess to be set. - FIXME: Handle NMI specially. */ + case TRC_HVM_NMI: case TRC_HVM_CR_READ: case TRC_HVM_CR_READ64: - case TRC_HVM_NMI: - /* FIXME: Really should check to make sure post_process is NULL or the exnmi default... */ + default: + if ( h->post_process != hvm_generic_postprocess ) + fprintf(warn, "%s: Strange, h->postprocess set!\n", + __func__); h->inflight.generic.event = ri->event; bcopy(h->d, h->inflight.generic.d, sizeof(unsigned int) * 4); - h->post_process = hvm_generic_postprocess; if(opt.dump_all) { hvm_generic_dump(ri, "]"); @@ -5168,18 +5216,8 @@ void hvm_vmexit_process(struct record_in h->wrmap_bf = 0; h->short_summary_done = 0; - h->post_process = NULL; - if(!opt.svm_mode) - { - switch(h->exit_reason) - { - case EXIT_REASON_EXCEPTION_NMI: - h->post_process = hvm_exception_nmi_generic_postprocess; - break; - default: - ; - } - } + h->post_process = hvm_generic_postprocess; + h->inflight.generic.event = 0; { struct time_struct t;
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 05 of 12] xenalyze: Handle new hvm_event traces
Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 844117c5a51e -r 463ac7003722 trace.h --- a/trace.h Mon Nov 28 16:16:23 2011 +0000 +++ b/trace.h Mon Nov 28 16:16:23 2011 +0000 @@ -162,6 +162,9 @@ #define TRC_HVM_RDTSC (TRC_HVM_HANDLER + 0x1a) #define TRC_HVM_INTR_WINDOW (TRC_HVM_HANDLER + 0x20) #define TRC_HVM_NPF (TRC_HVM_HANDLER + 0x21) +#define TRC_HVM_REALMODE_EMULATE (TRC_HVM_HANDLER + 0x22) +#define TRC_HVM_TRAP (TRC_HVM_HANDLER + 0x23) +#define TRC_HVM_TRAP_DEBUG (TRC_HVM_HANDLER + 0x24) #define TRC_HVM_IOPORT_WRITE (TRC_HVM_HANDLER + 0x216) #define TRC_HVM_IOMEM_WRITE (TRC_HVM_HANDLER + 0x217) diff -r 844117c5a51e -r 463ac7003722 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -982,6 +982,9 @@ enum { HVM_EVENT_RDTSC, HVM_EVENT_INTR_WINDOW=0x20, /* Oops... skipped 0x1b-1f */ HVM_EVENT_NPF, + HVM_EVENT_REALMODE_EMULATE, + HVM_EVENT_TRAP, + HVM_EVENT_TRAP_DEBUG, HVM_EVENT_HANDLER_MAX }; char * hvm_event_handler_name[HVM_EVENT_HANDLER_MAX] = { @@ -1014,6 +1017,9 @@ char * hvm_event_handler_name[HVM_EVENT_ "rdtsc", [HVM_EVENT_INTR_WINDOW]="intr_window", "npf", + "realmode_emulate", + "trap", + "trap_debug", }; enum { @@ -4930,6 +4936,9 @@ needs_vmexit: case TRC_HVM_LMSW: case TRC_HVM_LMSW64: case TRC_HVM_NMI: + case TRC_HVM_REALMODE_EMULATE: + case TRC_HVM_TRAP: + case TRC_HVM_TRAP_DEBUG: case TRC_HVM_CR_READ: case TRC_HVM_CR_READ64: default:
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 06 of 12] xenalyze: Relocate pio and mmio enumaration structs to their own sub-struct
In preparation for the next patch, which does some MMIO reorganizing. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 463ac7003722 -r 910605f7ade3 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -1361,7 +1361,9 @@ struct hvm_data { /* IPI Latency */ struct event_cycle_summary ipi_latency; int ipi_count[256]; - struct io_address *mmio, *pio; + struct { + struct io_address *mmio, *pio; + } io; } summary; /* In-flight accumulation information */ @@ -3674,7 +3676,7 @@ void enumerate_mmio(struct hvm_data *h) struct pf_xen_extra *e = &h->inflight.pf_xen; if ( e->mmio_data_valid ) - update_io_address(&h->summary.mmio, e->gpa, e->mmio_is_write, h->arc_cycles, e->va); + update_io_address(&h->summary.io.mmio, e->gpa, e->mmio_is_write, h->arc_cycles, e->va); } void hvm_mmio_assist_postprocess(struct hvm_data *h) @@ -3874,7 +3876,7 @@ void hvm_io_write_postprocess(struct hvm h->inflight.io.val); } if(opt.with_pio_enumeration) - update_io_address(&h->summary.pio, h->inflight.io.port, 1, h->arc_cycles, 0); + update_io_address(&h->summary.io.pio, h->inflight.io.port, 1, h->arc_cycles, 0); } void hvm_io_read_postprocess(struct hvm_data *h) @@ -3886,7 +3888,7 @@ void hvm_io_read_postprocess(struct hvm_ h->inflight.io.val); } if(opt.with_pio_enumeration) - update_io_address(&h->summary.pio, h->inflight.io.port, 0, h->arc_cycles, 0); + update_io_address(&h->summary.io.pio, h->inflight.io.port, 0, h->arc_cycles, 0); if(opt.scatterplot_io && h->inflight.io.port == opt.scatterplot_io_port) scatterplot_vs_time(h->exit_tsc, P.now - h->exit_tsc); } @@ -5492,8 +5494,8 @@ void hvm_summary(struct hvm_data *h) { if(h->summary.ipi_count[i]) printf(" [%3d] %10d\n", i, h->summary.ipi_count[i]); - hvm_io_address_summary(h->summary.pio, "IO address summary:"); - hvm_io_address_summary(h->summary.mmio, "MMIO address summary:"); + hvm_io_address_summary(h->summary.io.pio, "IO address summary:"); + hvm_io_address_summary(h->summary.io.mmio, "MMIO address summary:"); } /* ---- Shadow records ---- */
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 07 of 12] xenalyze: Handle MMIO records from different vmexits
handle_mmio() is called in Xen as a generic way to do emulation; in VMX, this at least includes not only EXCEPTION_NMI (page faults in shadow mode) and NPF (nested page fault in HAP mode), but also APIC_ACCESS and sometimes even CR_ACCESS. This patch allows xenalyze to process and summarize mmio records for different vmexits separately. The change that causes the biggest number of line changes is pulling the MMIO information out of pf_xen_extra and in its own struct, which is kept separate from the inflight union. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 910605f7ade3 -r c9f583c65e07 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -1252,6 +1252,20 @@ char * pf_xen_name[PF_XEN_MAX] = { #define CORR_VA_INVALID (0ULL-1) +enum { + NONPF_MMIO_APIC, + NONPF_MMIO_NPF, + NONPF_MMIO_UNKNOWN, + NONPF_MMIO_MAX +}; + +struct mmio_info { + unsigned long long gpa; + unsigned long long va; /* Filled only by shadow */ + unsigned data; + unsigned data_valid:1, is_write:1; +}; + struct pf_xen_extra { unsigned long long va; union { @@ -1302,9 +1316,7 @@ struct pf_xen_extra { /* Flags */ unsigned corr_valid:1, corr_is_kernel:1, - va_is_kernel:1, - mmio_data_valid:1, - mmio_is_write:1; + va_is_kernel:1; }; struct pcpu_info; @@ -1351,6 +1363,7 @@ struct hvm_data { struct event_cycle_summary cr3_write_resyncs[RESYNCS_MAX+1]; struct event_cycle_summary vmcall[HYPERCALL_MAX+1]; struct event_cycle_summary generic[HVM_EVENT_HANDLER_MAX]; + struct event_cycle_summary mmio[NONPF_MMIO_MAX]; struct hvm_gi_struct { int count; struct cycle_summary runtime[GUEST_INTERRUPT_CASE_MAX]; @@ -1367,33 +1380,37 @@ struct hvm_data { } summary; /* In-flight accumulation information */ - union { - struct { - unsigned port:31, - is_write:1; - unsigned int val; - } io; - struct pf_xen_extra pf_xen; - struct { - unsigned cr; - unsigned long long val; - int repromote; - } cr_write; - struct { - unsigned addr; - unsigned long long val; - } msr; - struct { - unsigned int event; - uint32_t d[4]; - } generic; - struct { - unsigned eax; - } vmcall; - struct { - unsigned vec; - } intr; - } inflight; + struct { + union { + struct { + unsigned port:31, + is_write:1; + unsigned int val; + } io; + struct pf_xen_extra pf_xen; + struct { + unsigned cr; + unsigned long long val; + int repromote; + } cr_write; + struct { + unsigned addr; + unsigned long long val; + } msr; + struct { + unsigned int event; + uint32_t d[4]; + } generic; + struct { + unsigned eax; + } vmcall; + struct { + unsigned vec; + } intr; + }; + /* MMIO gets its separate area, since many exits may use it */ + struct mmio_info mmio; + }inflight; int resyncs; void (*post_process)(struct hvm_data *); tsc_t exit_tsc, arc_cycles, entry_tsc; @@ -3309,6 +3326,7 @@ void pf_preprocess(struct pf_xen_extra * void hvm_pf_xen_preprocess(unsigned event, struct hvm_data *h) { struct pf_xen_extra *e = &h->inflight.pf_xen; + struct mmio_info *m = &h->inflight.mmio; struct hvm_pf_xen_record *r = (typeof(r))h->d; if(event == TRC_HVM_PF_XEN64) @@ -3325,7 +3343,7 @@ void hvm_pf_xen_preprocess(unsigned even e->error_code = r->x32.error_code; } - if(e->mmio_data_valid) + if(m->data_valid) e->pf_case = PF_XEN_MMIO; else { @@ -3363,8 +3381,11 @@ void hvm_pf_xen_postprocess(struct hvm_d struct pf_xen_extra *e = &h->inflight.pf_xen; if(opt.summary_info) { - update_summary(&h->summary.pf_xen[e->pf_case], - h->arc_cycles); + if(e->pf_case) + update_summary(&h->summary.pf_xen[e->pf_case], + h->arc_cycles); + else + fprintf(warn, "Strange, pf_case 0!\n"); switch(e->pf_case) { case PF_XEN_EMULATE: @@ -3530,7 +3551,7 @@ struct outstanding_ipi *find_vec(struct void hvm_vlapic_icr_handler(struct hvm_data *h) { - struct pf_xen_extra *e = &h->inflight.pf_xen; + struct mmio_info *m = &h->inflight.mmio; union { unsigned int val; struct { @@ -3544,7 +3565,7 @@ void hvm_vlapic_icr_handler(struct hvm_d _res2:2, dest_shorthand:2; }; - } icr = { .val = e->data }; + } icr = { .val = m->data }; void ipi_send(struct vcpu_data *ov, int vec) { @@ -3590,7 +3611,7 @@ void hvm_vlapic_icr_handler(struct hvm_d o->count); } - if(e->mmio_is_write) { + if(m->is_write) { if(opt.dump_all || opt.dump_cooked) { printf(" [vla] d%dv%d icr vec %d %s\n", h->v->d->did, h->v->vid, @@ -3657,9 +3678,9 @@ void hvm_vlapic_eoi_handler(struct hvm_d void hvm_vlapic_handler(struct hvm_data *h) { - struct pf_xen_extra *e = &h->inflight.pf_xen; - - switch(e->gpa) { + struct mmio_info *m = &h->inflight.mmio; + + switch(m->gpa) { case 0xfee00300: hvm_vlapic_icr_handler(h); break; @@ -3673,14 +3694,56 @@ void hvm_vlapic_handler(struct hvm_data /* Also called by shadow_mmio_postprocess */ void enumerate_mmio(struct hvm_data *h) { - struct pf_xen_extra *e = &h->inflight.pf_xen; - - if ( e->mmio_data_valid ) - update_io_address(&h->summary.io.mmio, e->gpa, e->mmio_is_write, h->arc_cycles, e->va); + struct mmio_info *m = &h->inflight.mmio; + + if ( m->data_valid ) + update_io_address(&h->summary.io.mmio, m->gpa, m->is_write, h->arc_cycles, m->va); +} + +void hvm_mmio_summary(struct hvm_data *h, void *data) +{ + int reason=(int)data; + + PRINT_SUMMARY(h->summary.mmio[reason], + " mmio "); } void hvm_mmio_assist_postprocess(struct hvm_data *h) { + int reason; + + switch(h->exit_reason) + { + case VMEXIT_NPF: + case EXIT_REASON_EPT_VIOLATION: + reason=NONPF_MMIO_NPF; + hvm_set_summary_handler(h, hvm_mmio_summary, (void *)reason); + break; + case EXIT_REASON_APIC_ACCESS: + reason=NONPF_MMIO_APIC; + hvm_set_summary_handler(h, hvm_mmio_summary, (void *)reason); + break; + default: + { + static int warned = 0; + if (!warned) + { + fprintf(stderr, "%s: Strange, MMIO with unexpected exit reason %d\n", + __func__, h->exit_reason); + warned=1; + } + reason=NONPF_MMIO_UNKNOWN; + hvm_set_summary_handler(h, hvm_mmio_summary, (void *)reason); + break; + } + } + + if(opt.summary_info) + { + update_summary(&h->summary.mmio[reason], + h->arc_cycles); + } + if ( opt.with_mmio_enumeration ) enumerate_mmio(h); } @@ -3688,8 +3751,7 @@ void hvm_mmio_assist_postprocess(struct #define HVM_IO_ASSIST_WRITE 0x200 void hvm_mmio_assist_process(struct record_info *ri, struct hvm_data *h) { - struct pf_xen_extra *e = &h->inflight.pf_xen; - + struct mmio_info *m = &h->inflight.mmio; union { struct { unsigned int gpa; @@ -3711,30 +3773,32 @@ void hvm_mmio_assist_process(struct reco } mevt = { .event = ri->event }; if(mevt.x64) { - e->gpa = r->x64.gpa; - e->data = r->x64.data; + m->gpa = r->x64.gpa; + m->data = r->x64.data; if(ri->extra_words*(sizeof(unsigned int))==sizeof(r->x64)) - e->mmio_data_valid=1; + m->data_valid=1; } else { - e->gpa = r->x32.gpa; - e->data = r->x32.data; + m->gpa = r->x32.gpa; + m->data = r->x32.data; if(ri->extra_words*(sizeof(unsigned int))==sizeof(r->x32)) - e->mmio_data_valid=1; - } - - e->mmio_is_write = mevt.write; + m->data_valid=1; + } + + m->is_write = mevt.write; if(opt.dump_all) { - if(e->mmio_data_valid) - printf("]%s mmio_assist %c gpa %llx data %x\n", h->dump_header, - mevt.write?''w'':''r'', e->gpa, e->data); + if(m->data_valid) + printf("]%s mmio_assist %c gpa %llx data %x\n", + h->dump_header, + mevt.write?''w'':''r'', + m->gpa, m->data); else printf("]%s mmio_assist %c gpa %llx (no data)\n", h->dump_header, - mevt.write?''w'':''r'', e->gpa); - } - - if((e->gpa & 0xfffff000) == 0xfee00000) + mevt.write?''w'':''r'', m->gpa); + } + + if((m->gpa & 0xfffff000) == 0xfee00000) hvm_vlapic_handler(h); /* Catch MMIOs that don''t go through the shadow code; tolerate @@ -5857,6 +5921,7 @@ void shadow_emulate_other_process(struct e->gfn = r.gfn; e->va = r.va; + e->pf_case = sevt.minor; pf_preprocess(e, h->v->guest_paging_levels); @@ -6035,10 +6100,15 @@ void shadow_fixup_process(struct record_ void shadow_mmio_postprocess(struct hvm_data *h) { struct pf_xen_extra *e = &h->inflight.pf_xen; + struct mmio_info *m = &h->inflight.mmio; if ( opt.summary_info ) { - update_summary(&h->summary.pf_xen[e->pf_case], h->arc_cycles); + if(e->pf_case) + update_summary(&h->summary.pf_xen[e->pf_case], + h->arc_cycles); + else + fprintf(warn, "Strange, pf_case 0!\n"); hvm_update_short_summary(h, HVM_SHORT_SUMMARY_MMIO); } @@ -6048,23 +6118,23 @@ void shadow_mmio_postprocess(struct hvm_ if ( opt.dump_cooked ) { - if(e->mmio_data_valid) + if(m->data_valid) printf(" %s %smmio %s va %llx eip %llx%s gpa %llx data %x\n", h->dump_header, (e->pf_case==PF_XEN_FAST_MMIO)?"fast ":"", - e->mmio_is_write?"write":"read", + m->is_write?"write":"read", e->va, h->rip, find_symbol(h->rip), - e->gpa, - e->data); + m->gpa, + m->data); else printf(" %s %smmio %s va %llx eip %llx%s gpa %llx (no data)\n", h->dump_header, (e->pf_case==PF_XEN_FAST_MMIO)?"fast ":"", - e->mmio_is_write?"write":"read", - e->va, + m->is_write?"write":"read", + m->va, h->rip, find_symbol(h->rip), - e->gpa); + m->gpa); } } @@ -6072,6 +6142,7 @@ void shadow_mmio_postprocess(struct hvm_ void shadow_mmio_process(struct record_info *ri, struct hvm_data *h) { struct pf_xen_extra *e = &h->inflight.pf_xen; + struct mmio_info *m = &h->inflight.mmio; union { /* for PAE, guest_l1e may be 64 while guest_va may be 32; so put it first for alignment sake. */ @@ -6104,7 +6175,7 @@ void shadow_mmio_process(struct record_i error(ERR_RECORD, ri); return; } - e->va = r->gpl2.va; + e->va = m->va = r->gpl2.va; break; case 4: if(sizeof(r->gpl4) != ri->extra_words * 4) @@ -6115,7 +6186,7 @@ void shadow_mmio_process(struct record_i error(ERR_RECORD, ri); return; } - e->va = r->gpl4.va; + e->va = m->va = r->gpl4.va; break; } @@ -6135,7 +6206,11 @@ void shadow_propagate_postprocess(struct if ( opt.summary_info ) { - update_summary(&h->summary.pf_xen[e->pf_case], h->arc_cycles); + if(e->pf_case) + update_summary(&h->summary.pf_xen[e->pf_case], + h->arc_cycles); + else + fprintf(warn, "Strange, pf_case 0!\n"); hvm_update_short_summary(h, HVM_SHORT_SUMMARY_PROPAGATE); } @@ -6255,20 +6330,20 @@ void shadow_fault_generic_dump(unsigned void shadow_fault_generic_postprocess(struct hvm_data *h) { - union shadow_event sevt = { .event = h->inflight.generic.event }; + struct pf_xen_extra *e = &h->inflight.pf_xen; + if ( e->pf_case < PF_XEN_NOT_SHADOW || e->pf_case > PF_XEN_LAST_FAULT ) + { + fprintf(warn, "%s: Strange, unexpected case %d\n", + __func__, e->pf_case); + return; + } + if(opt.summary_info) { - update_summary(&h->summary.pf_xen[sevt.minor], - h->arc_cycles); + update_summary(&h->summary.pf_xen[e->pf_case], + h->arc_cycles); hvm_update_short_summary(h, HVM_SHORT_SUMMARY_PROPAGATE); } - - if(opt.dump_cooked) - { - shadow_fault_generic_dump(h->inflight.generic.event, - h->inflight.generic.d, - " ", h->dump_header); - } } void shadow_fault_generic_process(struct record_info *ri, struct hvm_data *h)
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 08 of 12] xenalyze: Add option to skip vga range in MMIO enumeration
Emulations to the VGA range during boot can be extremely numerous, sometimes causing out-of-memory errors. Add an option to skip the VGA range (0xa0000-0xbffff) during enumeration, and enable it by default. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r c9f583c65e07 -r 3c6da152c844 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -48,6 +48,15 @@ struct array_struct { int count; }; +#define warn_once(_x...) \ + do { \ + static int _w=1; \ + if ( _w ) { \ + _w=0; \ + fprintf(warn, ##_x); \ + } \ + } while(0) \ + /* -- Global variables -- */ struct { int fd; @@ -160,6 +169,7 @@ struct { with_mmio_enumeration:1, with_interrupt_eip_enumeration:1, show_default_domain_summary:1, + mmio_enumeration_skip_vga:1, progress:1, svm_mode:1, summary:1, @@ -234,6 +244,7 @@ struct { .with_mmio_enumeration = 0, .with_interrupt_eip_enumeration = 0, .show_default_domain_summary = 0, + .mmio_enumeration_skip_vga = 1, .progress = 0, .svm_mode = 0, .summary = 0, @@ -3692,10 +3703,21 @@ void hvm_vlapic_handler(struct hvm_data } /* Also called by shadow_mmio_postprocess */ +#define MMIO_VGA_START (0xa0000) +#define MMIO_VGA_END (0xbffff) void enumerate_mmio(struct hvm_data *h) { struct mmio_info *m = &h->inflight.mmio; + /* Skip vga area */ + if ( opt.mmio_enumeration_skip_vga + && m->gpa >= MMIO_VGA_START + && m->gpa < MMIO_VGA_END) + { + warn_once("WARNING: Not enumerationg MMIO in VGA range. Use --mmio-enumeration-skip-vga=0 to override.\n"); + return; + } + if ( m->data_valid ) update_io_address(&h->summary.io.mmio, m->gpa, m->is_write, h->arc_cycles, m->va); } @@ -9464,6 +9486,7 @@ enum { OPT_INTERVAL_DOMAIN_GRANT_MAPS, /* Summary info */ OPT_SHOW_DEFAULT_DOMAIN_SUMMARY, + OPT_MMIO_ENUMERATION_SKIP_VGA, OPT_SAMPLE_SIZE, OPT_REPORT_PCPU, /* Guest info */ @@ -9649,6 +9672,14 @@ error_t cmd_parser(int key, char *arg, s argp_usage(state); break; } + case OPT_MMIO_ENUMERATION_SKIP_VGA: + { + char * inval; + opt.mmio_enumeration_skip_vga = (int)strtol(arg, &inval, 0); + if( inval == arg ) + argp_usage(state); + break; + } case OPT_SCATTERPLOT_INTERRUPT_EIP: { char * inval; @@ -10182,6 +10213,12 @@ const struct argp_option cmd_opts[] = { .group = OPT_GROUP_SUMMARY, .doc = "Show default domain information on summary", }, + { .name = "mmio-enumeration-skip-vga", + .key = OPT_MMIO_ENUMERATION_SKIP_VGA, + .arg = "[0|1]", + .group = OPT_GROUP_SUMMARY, + .doc = "Control whether we enumerate MMIO accesses to the VGA area, which can be extremly high during boot. Default: 0", }, + { .name = "sample-size", .key = OPT_SAMPLE_SIZE, .arg = "size",
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 09 of 12] xenalyze: Sort cr3 enumerated values by start time
Add a new sort method to sort by start time, rather than by total time, and make it the default. Really should make it command-line switchable, but I''ll leave that improvement until later. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 3c6da152c844 -r 46c366d71c74 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -4144,7 +4144,7 @@ void cr3_dump_list(struct cr3_value_stru struct cr3_value_struct **qsort_array; int i, N=0; - int cr3_compare(const void *_a, const void *_b) { + int cr3_compare_total(const void *_a, const void *_b) { struct cr3_value_struct *a=*(typeof(&a))_a; struct cr3_value_struct *b=*(typeof(&a))_b; @@ -4161,6 +4161,18 @@ void cr3_dump_list(struct cr3_value_stru return -1; } + int cr3_compare_start(const void *_a, const void *_b) { + struct cr3_value_struct *a=*(typeof(&a))_a; + struct cr3_value_struct *b=*(typeof(&a))_b; + + if(a->first_time > b->first_time) + return 1; + else if(b->first_time == a->first_time) + return 0; + else + return -1; + } + if(!head) return; @@ -4180,7 +4192,7 @@ void cr3_dump_list(struct cr3_value_stru /* Sort the array by time */ qsort(qsort_array, N, sizeof(struct eip_list_struct *), - cr3_compare); + cr3_compare_start); /* WARNING: don''t use N after this point unless you copy this variable */ #if 0
Some of the cr3 ouptut was #if 0''d out. Put it back in. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r 46c366d71c74 -r dab5ba28630a xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -4220,8 +4220,7 @@ void cr3_dump_list(struct cr3_value_stru print_cycle_percent_summary(&p->hv_time, p->run_time, desc); hvm_short_summary(&p->hvm, p->run_time, " + "); -#if 0 - printf(" Seen: %4lu.%09lu-%4lu.%09lu switch %d flush %d\n", + printf(" Seen: %4u.%09u-%4u.%09u switch %d flush %d\n", first.s, first.ns, last.s, last.ns, p->switch_count, p->flush_count); @@ -4231,7 +4230,6 @@ void cr3_dump_list(struct cr3_value_stru p->destroy.switch_count, p->destroy.fixup_user, p->destroy.emulate_corr_user); -#endif } free(qsort_array);
pcpu_string() is called on every line of the dump output, and the basic loop is O(N) with the number of pcpus. There was an optimization that would be O(1), but it had a bug so that it never actually went into effect. Put the optimization into effect, so that only the bits that need to change are changed. This means, however, that when other things change, like power states or lost records, that other parts of the string need to be redrawn. Put in hooks to redraw when these kinds of things change. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r dab5ba28630a -r b7d88a8858b7 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -1942,6 +1942,7 @@ struct { /* Function prototypes */ char * pcpu_string(int pcpu); +void pcpu_string_draw(struct pcpu_info *p); void process_generic(struct record_info *ri); void dump_generic(FILE *f, struct record_info *ri); ssize_t __read_record(int fd, struct trace_record *rec, loff_t offset); @@ -6970,6 +6971,7 @@ void vcpu_prev_update(struct pcpu_info * set: pcpu_runstate_update(p, tsc); p->current = NULL; + pcpu_string_draw(p); runstate_update(prev, new_runstate, tsc); } @@ -7051,6 +7053,7 @@ void vcpu_next_update(struct pcpu_info * next->p = p; p->current = next; + pcpu_string_draw(p); p->time.tsc = tsc; p->lost_record.seen_valid_schedule = 1; } @@ -7089,6 +7092,7 @@ void vcpu_start(struct pcpu_info *p, str runstate_update(v, RUNSTATE_RUNNING, p->first_tsc); p->time.tsc = p->first_tsc; p->current = v; + pcpu_string_draw(p); v->p = p; } @@ -7524,6 +7528,7 @@ void sched_default_vcpu_activate(struct v->runstate.state = RUNSTATE_RUNNING; p->current = v; + pcpu_string_draw(p); } void sched_default_domain_init(void) @@ -7825,7 +7830,10 @@ void pm_process(struct pcpu_info *p) { ri->dump_header, ri->d[0]); if ( ri->d[0] <= CSTATE_MAX ) + { p->power_state=ri->d[0]; + pcpu_string_draw(p); + } break; case TRC_PM_IDLE_EXIT: if (opt.dump_all ) @@ -7837,6 +7845,7 @@ void pm_process(struct pcpu_info *p) { printf("Strange, pm_idle_end %d, power_state %d!\n", ri->d[0], p->power_state); p->power_state = 0; + pcpu_string_draw(p); break; default: if(opt.dump_all || opt.dump_cooked) { @@ -8437,6 +8446,7 @@ void process_lost_records(struct pcpu_in p->lost_record.active = 1; p->lost_record.tsc = first_tsc; + pcpu_string_draw(p); { /* Any vcpu which is not actively running may be scheduled on the @@ -8520,6 +8530,7 @@ void process_lost_records_end(struct pcp p->lost_record.active = 0; + pcpu_string_draw(p); P.lost_cpus--; if(P.lost_cpus < 0) { fprintf(warn, "ERROR: lost_cpus fell below 0 for pcpu %d!\n", @@ -9230,38 +9241,59 @@ ssize_t read_record(int fd, struct pcpu_ return ri->size; } -/* WARNING not thread-safe */ +/* + * This funciton gets called for every record when doing dump. Try to + * make it efficient by changing the minimum amount from the last + * call. Do this by: + * - Keeping track of the last pcpu called, so we can just set that to - + * - Keeping track of how many pcpus we''ve "drawn", and only "drawing" new ones + * - Updating the current one + * + * FIXME: Need to deal with pcpu states changing... + * + * WARNING not thread-safe + */ + +char __pcpu_string[MAX_CPUS+1] = { 0 }; +void pcpu_string_draw(struct pcpu_info *p) +{ + char *s = __pcpu_string; + int i=p->pid; + + if(p->lost_record.active) + s[i]=''l''; + else if (!p->current) + s[i]='' ''; + else if (p->current->d->did == DEFAULT_DOMAIN) + s[i]=''.''; + else if (p->current->d->did == IDLE_DOMAIN) + { + if ( opt.dump_show_power_states ) + s[i]=p->power_state+''0''; + else + s[i]=''-''; + } + else + s[i]=''|''; +} + char * pcpu_string(int pcpu) { - static char s[MAX_CPUS+1] = { 0 }; + char *s = __pcpu_string; static int max_active_pcpu=-1, last_pcpu=-1; assert(P.max_active_pcpu < MAX_CPUS); assert(pcpu <= P.max_active_pcpu); if(last_pcpu >= 0) - s[last_pcpu]=''-''; + pcpu_string_draw(P.pcpu+last_pcpu); if(P.max_active_pcpu > max_active_pcpu) { int i; - for(i=max_active_pcpu + 1; i<= P.max_active_pcpu; i++) { - if(P.pcpu[i].lost_record.active) - s[i]=''l''; - else if (!P.pcpu[i].current) - s[i]='' ''; - else if (P.pcpu[i].current->d->did == DEFAULT_DOMAIN) - s[i]=''.''; - else if (P.pcpu[i].current->d->did == IDLE_DOMAIN) - { - if ( opt.dump_show_power_states ) - s[i]=P.pcpu[i].power_state+''0''; - else - s[i]=''-''; - } - else - s[i]=''|''; - } + for(i=max_active_pcpu + 1; i<= P.max_active_pcpu; i++) + pcpu_string_draw(P.pcpu+i); + max_active_pcpu=P.max_active_pcpu; } s[pcpu]=''x'';
George Dunlap
2011-Nov-28 16:18 UTC
[PATCH 12 of 12] xenalyze: Make max_active_pcpu calculation smarter
oprofile reports that during summary runs, over 30% of the time processing is spent in choose_next_record. As a first step towards eliminating the loop found in that function, take out the calculation of P.max_active_pcpu, and make it smarter. Signed-off-by: George Dunlap <george.dunlap@eu.citrix.com> diff -r b7d88a8858b7 -r 223e8ad4c755 xenalyze.c --- a/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 +++ b/xenalyze.c Mon Nov 28 16:16:23 2011 +0000 @@ -8675,6 +8675,21 @@ void deactivate_pcpu(struct pcpu_info *p lose_vcpu(p->current, p->last_tsc); } p->active = 0; + if ( p->pid == P.max_active_pcpu ) + { + int i, max_active_pcpu = -1; + for(i=0; i<=P.max_active_pcpu; i++) + { + if(!P.pcpu[i].active) + continue; + + max_active_pcpu = i; + } + P.max_active_pcpu = max_active_pcpu; + fprintf(warn, "%s: Setting max_active_pcpu to %d\n", + __func__, max_active_pcpu); + } + } /* Helper function to process tsc-related record info */ @@ -9304,17 +9319,20 @@ char * pcpu_string(int pcpu) struct pcpu_info * choose_next_record(void) { - int i, max_active_pcpu = -1; + int i; struct pcpu_info * p, *min_p=NULL; loff_t min_offset = 0; + /* Need to: + * - find the pcpu with the lowest order_tsc + * - Find the lowest file offset + */ for(i=0; i<=P.max_active_pcpu; i++) { p = P.pcpu+i; if(!p->active) continue; - max_active_pcpu = i; if(!min_p || p->order_tsc < min_p->order_tsc) min_p = p; @@ -9322,13 +9340,11 @@ struct pcpu_info * choose_next_record(vo min_offset = p->file_offset; } - P.max_active_pcpu = max_active_pcpu; - if(opt.progress && min_offset >= G.progress.update_offset) progress_update(min_offset); /* If there are active pcpus, make sure we chose one */ - assert(min_p || (max_active_pcpu==-1)); + assert(min_p || (P.max_active_pcpu==-1)); return min_p; }