From a62f71bad597e69213bc2b94cba057c274833f7d Mon Sep 17 00:00:00 2001 From: Keir Fraser Date: Mon, 24 Sep 2007 13:43:25 +0100 Subject: Xen tracing cleanups and fixes. Signed-off-by: Keir Fraser --- tools/xenmon/xenbaked.c | 603 ++++++++++++++++++++++++------------------------ 1 file changed, 304 insertions(+), 299 deletions(-) (limited to 'tools/xenmon') diff --git a/tools/xenmon/xenbaked.c b/tools/xenmon/xenbaked.c index 1587016335..27125a3142 100644 --- a/tools/xenmon/xenbaked.c +++ b/tools/xenmon/xenbaked.c @@ -12,7 +12,8 @@ * Authors: Diwaker Gupta, diwaker.gupta@hp.com * Rob Gardner, rob.gardner@hp.com * Lucy Cherkasova, lucy.cherkasova.hp.com - * Much code based on xentrace, authored by Mark Williamson, mark.a.williamson@intel.com + * Much code based on xentrace, authored by Mark Williamson, + * mark.a.williamson@intel.com * Date: November, 2005 * * This program is free software; you can redistribute it and/or modify @@ -107,31 +108,31 @@ int NCPU = 0; void init_current(int ncpu) { - running = calloc(ncpu, sizeof(int)); - NCPU = ncpu; - printf("Initialized with %d %s\n", ncpu, (ncpu == 1) ? "cpu" : "cpu's"); + running = calloc(ncpu, sizeof(int)); + NCPU = ncpu; + printf("Initialized with %d %s\n", ncpu, (ncpu == 1) ? "cpu" : "cpu's"); } int is_current(int domain, int cpu) { - // int i; + // int i; - // for (i=0; icycles, x->event, x->data[0]); + cpu, x->cycles, x->event, x->data[0]); } #endif @@ -198,15 +199,15 @@ void check_gotten_sum(void) int i; for (i=0; i ns_gotten = %7.3f%%\n", percent); + new_qos = cpu_qos_data[i]; + ns = billion; + sum = total_ns_gotten(&ns); + + printf("[cpu%d] ns_gotten over all domains = %lldns, over %lldns\n", + i, sum, ns); + percent = (double) sum; + percent = (100.0*percent) / (double)ns; + printf(" ==> ns_gotten = %7.3f%%\n", percent); } #endif } @@ -229,7 +230,7 @@ void dump_stats(void) } printf("processed %d total records in %d seconds (%ld per second)\n", - rec_count, (int)run_time, rec_count/run_time); + rec_count, (int)run_time, rec_count/run_time); printf("woke up %d times in %d seconds (%ld per second)\n", wakeups, (int) run_time, wakeups/run_time); @@ -261,56 +262,56 @@ int xce_handle = -1; /* Stolen from xenstore code */ int eventchn_init(void) { - int rc; + int rc; - // to revert to old way: - if (0) - return -1; + // to revert to old way: + if (0) + return -1; - xce_handle = xc_evtchn_open(); + xce_handle = xc_evtchn_open(); - if (xce_handle < 0) - perror("Failed to open evtchn device"); + if (xce_handle < 0) + perror("Failed to open evtchn device"); - if ((rc = xc_evtchn_bind_virq(xce_handle, VIRQ_TBUF)) == -1) - perror("Failed to bind to domain exception virq port"); - virq_port = rc; + if ((rc = xc_evtchn_bind_virq(xce_handle, VIRQ_TBUF)) == -1) + perror("Failed to bind to domain exception virq port"); + virq_port = rc; - return xce_handle; + return xce_handle; } void wait_for_event(void) { - int ret; - fd_set inset; - evtchn_port_t port; - struct timeval tv; - int evtchn_fd; + int ret; + fd_set inset; + evtchn_port_t port; + struct timeval tv; + int evtchn_fd; - if (xce_handle < 0) { - nanosleep(&opts.poll_sleep, NULL); - return; - } - - evtchn_fd = xc_evtchn_fd(xce_handle); - - FD_ZERO(&inset); - FD_SET(evtchn_fd, &inset); - tv.tv_sec = 1; - tv.tv_usec = 0; - // tv = millis_to_timespec(&opts.poll_sleep); - ret = select(evtchn_fd+1, &inset, NULL, NULL, &tv); + if (xce_handle < 0) { + nanosleep(&opts.poll_sleep, NULL); + return; + } + + evtchn_fd = xc_evtchn_fd(xce_handle); + + FD_ZERO(&inset); + FD_SET(evtchn_fd, &inset); + tv.tv_sec = 1; + tv.tv_usec = 0; + // tv = millis_to_timespec(&opts.poll_sleep); + ret = select(evtchn_fd+1, &inset, NULL, NULL, &tv); - if ( (ret == 1) && FD_ISSET(evtchn_fd, &inset)) { - if ((port = xc_evtchn_pending(xce_handle)) == -1) - perror("Failed to read from event fd"); + if ( (ret == 1) && FD_ISSET(evtchn_fd, &inset)) { + if ((port = xc_evtchn_pending(xce_handle)) == -1) + perror("Failed to read from event fd"); - // if (port == virq_port) - // printf("got the event I was looking for\r\n"); + // if (port == virq_port) + // printf("got the event I was looking for\r\n"); - if (xc_evtchn_unmask(xce_handle, port) == -1) - perror("Failed to write to event fd"); - } + if (xc_evtchn_unmask(xce_handle, port) == -1) + perror("Failed to write to event fd"); + } } static void get_tbufs(unsigned long *mfn, unsigned long *size) @@ -336,9 +337,9 @@ static void get_tbufs(unsigned long *mfn, unsigned long *size) void disable_tracing(void) { - int xc_handle = xc_interface_open(); - xc_tbuf_disable(xc_handle); - xc_interface_close(xc_handle); + int xc_handle = xc_interface_open(); + xc_tbuf_disable(xc_handle); + xc_interface_close(xc_handle); } /** @@ -387,7 +388,7 @@ struct t_buf *map_tbufs(unsigned long tbufs_mfn, unsigned int num, * mapped region containing all trace buffers. */ struct t_buf **init_bufs_ptrs(void *bufs_mapped, unsigned int num, - unsigned long size) + unsigned long size) { int i; struct t_buf **user_ptrs; @@ -472,7 +473,7 @@ unsigned int get_num_cpus(void) int monitor_tbufs(void) { int i; - extern void process_record(int, struct t_rec *); + extern int process_record(int, struct t_rec *); extern void alloc_qos_data(int ncpu); void *tbufs_mapped; /* pointer to where the tbufs are mapped */ @@ -483,7 +484,7 @@ int monitor_tbufs(void) unsigned int num; /* number of trace buffers / logical CPUS */ unsigned long size; /* size of a single trace buffer */ - int size_in_recs; + unsigned long data_size, rec_size; /* get number of logical CPUs (and therefore number of trace buffers) */ num = get_num_cpus(); @@ -496,34 +497,32 @@ int monitor_tbufs(void) /* setup access to trace buffers */ get_tbufs(&tbufs_mfn, &size); - // printf("from dom0op: %ld, t_buf: %d, t_rec: %d\n", - // size, sizeof(struct t_buf), sizeof(struct t_rec)); - tbufs_mapped = map_tbufs(tbufs_mfn, num, size); - size_in_recs = (size - sizeof(struct t_buf)) / sizeof(struct t_rec); - // fprintf(stderr, "size_in_recs = %d\n", size_in_recs); + data_size = size - sizeof(struct t_buf); /* build arrays of convenience ptrs */ meta = init_bufs_ptrs (tbufs_mapped, num, size); data = init_rec_ptrs(meta, num); - // Set up event channel for select() - if (eventchn_init() < 0) { - fprintf(stderr, "Failed to initialize event channel; Using POLL method\r\n"); - } + if ( eventchn_init() < 0 ) + fprintf(stderr, "Failed to initialize event channel; " + "Using POLL method\r\n"); /* now, scan buffers for events */ while ( !interrupted ) { - for ( i = 0; ( i < num ) && !interrupted; i++ ) + for ( i = 0; (i < num) && !interrupted; i++ ) + { while ( meta[i]->cons != meta[i]->prod ) { rmb(); /* read prod, then read item. */ - process_record(i, data[i] + meta[i]->cons % size_in_recs); + rec_size = process_record( + i, data[i] + meta[i]->cons % data_size); mb(); /* read item, then update cons. */ - meta[i]->cons++; + meta[i]->cons += rec_size; } + } wait_for_event(); wakeups++; @@ -550,44 +549,44 @@ error_t cmd_parser(int key, char *arg, struct argp_state *state) switch ( key ) { - case 't': /* set new records threshold for logging */ - { - char *inval; - setup->new_data_thresh = strtol(arg, &inval, 0); - if ( inval == arg ) - argp_usage(state); - } - break; + case 't': /* set new records threshold for logging */ + { + char *inval; + setup->new_data_thresh = strtol(arg, &inval, 0); + if ( inval == arg ) + argp_usage(state); + } + break; - case 's': /* set sleep time (given in milliseconds) */ - { - char *inval; - setup->poll_sleep = millis_to_timespec(strtol(arg, &inval, 0)); - if ( inval == arg ) - argp_usage(state); - } - break; + case 's': /* set sleep time (given in milliseconds) */ + { + char *inval; + setup->poll_sleep = millis_to_timespec(strtol(arg, &inval, 0)); + if ( inval == arg ) + argp_usage(state); + } + break; - case 'm': /* set ms_per_sample */ - { - char *inval; - setup->ms_per_sample = strtol(arg, &inval, 0); - if ( inval == arg ) - argp_usage(state); - } - break; + case 'm': /* set ms_per_sample */ + { + char *inval; + setup->ms_per_sample = strtol(arg, &inval, 0); + if ( inval == arg ) + argp_usage(state); + } + break; - case ARGP_KEY_ARG: - { - if ( state->arg_num == 0 ) - setup->outfile = arg; - else - argp_usage(state); - } - break; + case ARGP_KEY_ARG: + { + if ( state->arg_num == 0 ) + setup->outfile = arg; + else + argp_usage(state); + } + break; - default: - return ARGP_ERR_UNKNOWN; + default: + return ARGP_ERR_UNKNOWN; } return 0; @@ -614,27 +613,27 @@ void alloc_qos_data(int ncpu) for (n=0; nnext_datapoint = 0; - advance_next_datapoint(0); - new_qos->structlen = i; - new_qos->ncpu = ncpu; - // printf("structlen = 0x%x\n", i); - cpu_qos_data[n] = new_qos; + for (i=0; inext_datapoint = 0; + advance_next_datapoint(0); + new_qos->structlen = i; + new_qos->ncpu = ncpu; + // printf("structlen = 0x%x\n", i); + cpu_qos_data[n] = new_qos; } free(dummy); new_qos = NULL; @@ -647,19 +646,19 @@ void alloc_qos_data(int ncpu) const struct argp_option cmd_opts[] = { { .name = "log-thresh", .key='t', .arg="l", - .doc = - "Set number, l, of new records required to trigger a write to output " - "(default " xstr(NEW_DATA_THRESH) ")." }, + .doc = + "Set number, l, of new records required to trigger a write to output " + "(default " xstr(NEW_DATA_THRESH) ")." }, { .name = "poll-sleep", .key='s', .arg="p", - .doc = - "Set sleep time, p, in milliseconds between polling the trace buffer " - "for new data (default " xstr(POLL_SLEEP_MILLIS) ")." }, + .doc = + "Set sleep time, p, in milliseconds between polling the trace buffer " + "for new data (default " xstr(POLL_SLEEP_MILLIS) ")." }, { .name = "ms_per_sample", .key='m', .arg="MS", - .doc = - "Specify the number of milliseconds per sample " - " (default " xstr(MS_PER_SAMPLE) ")." }, + .doc = + "Specify the number of milliseconds per sample " + " (default " xstr(MS_PER_SAMPLE) ")." }, {0} }; @@ -670,10 +669,10 @@ const struct argp parser_def = .parser = cmd_parser, // .args_doc = "[output file]", .doc = - "Tool to capture and partially process Xen trace buffer data" - "\v" - "This tool is used to capture trace buffer data from Xen. The data is " - "saved in a shared memory structure to be further processed by xenmon." + "Tool to capture and partially process Xen trace buffer data" + "\v" + "This tool is used to capture trace buffer data from Xen. The data is " + "saved in a shared memory structure to be further processed by xenmon." }; @@ -716,101 +715,101 @@ int main(int argc, char **argv) void qos_init_domain(int domid, int idx) { - int i; - - memset(&new_qos->domain_info[idx], 0, sizeof(_domain_info)); - new_qos->domain_info[idx].last_update_time = global_now; - // runnable_start_time[idx] = 0; - new_qos->domain_info[idx].runnable_start_time = 0; // invalidate - new_qos->domain_info[idx].in_use = 1; - new_qos->domain_info[idx].blocked_start_time = 0; - new_qos->domain_info[idx].id = domid; - if (domid == IDLE_DOMAIN_ID) - sprintf(new_qos->domain_info[idx].name, "Idle Task%d", global_cpu); - else - sprintf(new_qos->domain_info[idx].name, "Domain#%d", domid); + int i; + + memset(&new_qos->domain_info[idx], 0, sizeof(_domain_info)); + new_qos->domain_info[idx].last_update_time = global_now; + // runnable_start_time[idx] = 0; + new_qos->domain_info[idx].runnable_start_time = 0; // invalidate + new_qos->domain_info[idx].in_use = 1; + new_qos->domain_info[idx].blocked_start_time = 0; + new_qos->domain_info[idx].id = domid; + if (domid == IDLE_DOMAIN_ID) + sprintf(new_qos->domain_info[idx].name, "Idle Task%d", global_cpu); + else + sprintf(new_qos->domain_info[idx].name, "Domain#%d", domid); - for (i=0; iqdata[i].ns_gotten[idx] = 0; - new_qos->qdata[i].ns_allocated[idx] = 0; - new_qos->qdata[i].ns_waiting[idx] = 0; - new_qos->qdata[i].ns_blocked[idx] = 0; - new_qos->qdata[i].switchin_count[idx] = 0; - new_qos->qdata[i].io_count[idx] = 0; - } + for (i=0; iqdata[i].ns_gotten[idx] = 0; + new_qos->qdata[i].ns_allocated[idx] = 0; + new_qos->qdata[i].ns_waiting[idx] = 0; + new_qos->qdata[i].ns_blocked[idx] = 0; + new_qos->qdata[i].switchin_count[idx] = 0; + new_qos->qdata[i].io_count[idx] = 0; + } } void global_init_domain(int domid, int idx) { - int cpu; - _new_qos_data *saved_qos; + int cpu; + _new_qos_data *saved_qos; - saved_qos = new_qos; + saved_qos = new_qos; - for (cpu=0; cpudomain_info[idx].id == domid) && new_qos->domain_info[idx].in_use) - return idx; + for (idx=0; idxdomain_info[idx].id == domid) && new_qos->domain_info[idx].in_use) + return idx; - // not found, make a new entry - for (idx=0; idxdomain_info[idx].in_use == 0) { - global_init_domain(domid, idx); - return idx; - } + // not found, make a new entry + for (idx=0; idxdomain_info[idx].in_use == 0) { + global_init_domain(domid, idx); + return idx; + } + + // call domaininfo hypercall to try and garbage collect unused entries + xc_handle = xc_interface_open(); + ndomains = xc_domain_getinfo(xc_handle, 0, NDOMAINS, dominfo); + xc_interface_close(xc_handle); - // call domaininfo hypercall to try and garbage collect unused entries - xc_handle = xc_interface_open(); - ndomains = xc_domain_getinfo(xc_handle, 0, NDOMAINS, dominfo); - xc_interface_close(xc_handle); - - // for each domain in our data, look for it in the system dominfo structure - // and purge the domain's data from our state if it does not exist in the - // dominfo structure - for (idx=0; idxdomain_info[idx].id; - int jdx; + // for each domain in our data, look for it in the system dominfo structure + // and purge the domain's data from our state if it does not exist in the + // dominfo structure + for (idx=0; idxdomain_info[idx].id; + int jdx; - for (jdx=0; jdxdomain_info[idx].in_use == 0) { - global_init_domain(domid, idx); - return idx; - } + // look again for a free slot + for (idx=0; idxdomain_info[idx].in_use == 0) { + global_init_domain(domid, idx); + return idx; + } - // still no space found, so bail - fprintf(stderr, "out of space in domain table, increase NDOMAINS\r\n"); - exit(2); + // still no space found, so bail + fprintf(stderr, "out of space in domain table, increase NDOMAINS\r\n"); + exit(2); } int domain_runnable(int domid) @@ -879,25 +878,25 @@ void qos_update_thread(int cpu, int domid, uint64_t now) time_since_update = now - last_update_time; if (time_since_update < 0) { - // what happened here? either a timestamp wraparound, or more likely, - // a slight inconsistency among timestamps from various cpu's - if (-time_since_update < billion) { - // fairly small difference, let's just adjust 'now' to be a little - // beyond last_update_time - time_since_update = -time_since_update; - } - else if ( ((~0ULL - last_update_time) < billion) && (now < billion) ) { - // difference is huge, must be a wraparound - // last_update time should be "near" ~0ULL, - // and now should be "near" 0 - time_since_update = now + (~0ULL - last_update_time); - printf("time wraparound\n"); - } - else { - // none of the above, may be an out of order record - // no good solution, just ignore and update again later - return; - } + // what happened here? either a timestamp wraparound, or more likely, + // a slight inconsistency among timestamps from various cpu's + if (-time_since_update < billion) { + // fairly small difference, let's just adjust 'now' to be a little + // beyond last_update_time + time_since_update = -time_since_update; + } + else if ( ((~0ULL - last_update_time) < billion) && (now < billion) ) { + // difference is huge, must be a wraparound + // last_update time should be "near" ~0ULL, + // and now should be "near" 0 + time_since_update = now + (~0ULL - last_update_time); + printf("time wraparound\n"); + } + else { + // none of the above, may be an out of order record + // no good solution, just ignore and update again later + return; + } } new_qos->domain_info[id].last_update_time = now; @@ -985,7 +984,7 @@ void qos_switch_in(int cpu, int domid, uint64_t now, unsigned long ns_alloc, uns // count up page flips for dom0 execution if (domid == 0) - dom0_flips = 0; + dom0_flips = 0; } // called when the current thread is taken off the cpu @@ -1011,8 +1010,8 @@ void qos_switch_out(int cpu, int domid, uint64_t now, unsigned long gotten) #if 0 new_qos->qdata[n].ns_gotten[idx] += gotten; if (gotten > new_qos->qdata[n].ns_passed) - printf("inconsistency #257, diff = %lld\n", - gotten - new_qos->qdata[n].ns_passed ); + printf("inconsistency #257, diff = %lld\n", + gotten - new_qos->qdata[n].ns_passed ); #endif new_qos->domain_info[idx].ns_oncpu_since_boot += gotten; new_qos->domain_info[idx].runnable_start_time = now; @@ -1021,8 +1020,8 @@ void qos_switch_out(int cpu, int domid, uint64_t now, unsigned long gotten) // process dom0 page flips if (domid == 0) - if (dom0_flips == 0) - new_qos->qdata[n].flip_free_periods++; + if (dom0_flips == 0) + new_qos->qdata[n].flip_free_periods++; } // called when domain is put to sleep, may also be called @@ -1047,11 +1046,11 @@ void qos_state_sleeping(int cpu, int domid, uint64_t now) // domain died, presume it's dead on all cpu's, not just mostly dead void qos_kill_thread(int domid) { - int cpu; + int cpu; - for (cpu=0; cpudomain_info[indexof(domid)].in_use = 0; - } + for (cpu=0; cpudomain_info[indexof(domid)].in_use = 0; + } } @@ -1060,7 +1059,7 @@ void qos_kill_thread(int domid) // when thread is already runnable void qos_state_runnable(int cpu, int domid, uint64_t now) { - int idx; + int idx; qos_update_thread_stats(cpu, domid, now); @@ -1080,79 +1079,85 @@ void qos_state_runnable(int cpu, int domid, uint64_t now) void qos_count_packets(domid_t domid, uint64_t now) { - int i, idx = indexof(domid); - _new_qos_data *cpu_data; + int i, idx = indexof(domid); + _new_qos_data *cpu_data; - for (i=0; idomain_info[idx].in_use) { - cpu_data->qdata[cpu_data->next_datapoint].io_count[idx]++; + for (i=0; idomain_info[idx].in_use) { + cpu_data->qdata[cpu_data->next_datapoint].io_count[idx]++; + } } - } - new_qos->qdata[new_qos->next_datapoint].io_count[0]++; - dom0_flips++; + new_qos->qdata[new_qos->next_datapoint].io_count[0]++; + dom0_flips++; } -void process_record(int cpu, struct t_rec *r) +int process_record(int cpu, struct t_rec *r) { - uint64_t now; + uint64_t now = 0; + uint32_t *extra_u32 = r->u.nocycles.extra_u32; - new_qos = cpu_qos_data[cpu]; + new_qos = cpu_qos_data[cpu]; - rec_count++; + rec_count++; - now = ((double)r->cycles) / (opts.cpu_freq / 1000.0); + if ( r->cycles_included ) + { + now = ((uint64_t)r->u.cycles.cycles_hi << 32) | r->u.cycles.cycles_lo; + now = ((double)now) / (opts.cpu_freq / 1000.0); + extra_u32 = r->u.cycles.extra_u32; + } - global_now = now; - global_cpu = cpu; + global_now = now; + global_cpu = cpu; - log_event(r->event); + log_event(r->event); - switch (r->event) { + switch (r->event) { - case TRC_SCHED_SWITCH_INFPREV: - // domain data[0] just switched out and received data[1] ns of cpu time - qos_switch_out(cpu, r->data[0], now, r->data[1]); - // printf("ns_gotten %ld\n", r->data[1]); - break; + case TRC_SCHED_SWITCH_INFPREV: + // domain data[0] just switched out and received data[1] ns of cpu time + qos_switch_out(cpu, extra_u32[0], now, extra_u32[1]); + // printf("ns_gotten %ld\n", extra_u32[1]); + break; - case TRC_SCHED_SWITCH_INFNEXT: - // domain data[0] just switched in and - // waited data[1] ns, and was allocated data[2] ns of cpu time - qos_switch_in(cpu, r->data[0], now, r->data[2], r->data[1]); - break; + case TRC_SCHED_SWITCH_INFNEXT: + // domain data[0] just switched in and + // waited data[1] ns, and was allocated data[2] ns of cpu time + qos_switch_in(cpu, extra_u32[0], now, extra_u32[2], extra_u32[1]); + break; - case TRC_SCHED_DOM_ADD: - (void) indexof(r->data[0]); - break; + case TRC_SCHED_DOM_ADD: + (void) indexof(extra_u32[0]); + break; - case TRC_SCHED_DOM_REM: - qos_kill_thread(r->data[0]); - break; + case TRC_SCHED_DOM_REM: + qos_kill_thread(extra_u32[0]); + break; - case TRC_SCHED_SLEEP: - qos_state_sleeping(cpu, r->data[0], now); - break; + case TRC_SCHED_SLEEP: + qos_state_sleeping(cpu, extra_u32[0], now); + break; - case TRC_SCHED_WAKE: - qos_state_runnable(cpu, r->data[0], now); - break; + case TRC_SCHED_WAKE: + qos_state_runnable(cpu, extra_u32[0], now); + break; - case TRC_SCHED_BLOCK: - qos_state_sleeping(cpu, r->data[0], now); - break; + case TRC_SCHED_BLOCK: + qos_state_sleeping(cpu, extra_u32[0], now); + break; - case TRC_MEM_PAGE_GRANT_TRANSFER: - qos_count_packets(r->data[0], now); - break; + case TRC_MEM_PAGE_GRANT_TRANSFER: + qos_count_packets(extra_u32[0], now); + break; - default: - break; - } - new_qos = NULL; -} - + default: + break; + } + new_qos = NULL; + return 4 + (r->cycles_included ? 8 : 0) + (r->extra_u32 * 4); +} -- cgit v1.2.3