X-Git-Url: https://git.kernel.dk/?a=blobdiff_plain;f=blkparse.c;h=ca2f28f296985cb1001ab8bc80664998c4596048;hb=3c667f3c92f0daa58d7d77cb52de3a1b5f283bc6;hp=b9f490832ffddae6c2eba1c30edc5466aa0cd231;hpb=0583b6a25eaa259bf9ade5746452473464814f6e;p=blktrace.git diff --git a/blkparse.c b/blkparse.c index b9f4908..0054d4f 100644 --- a/blkparse.c +++ b/blkparse.c @@ -2,6 +2,7 @@ * block queue tracing parse application * * Copyright (C) 2005 Jens Axboe + * Copyright (C) 2006 Jens Axboe * * This program is free software; you can redistribute it and/or modify * it under the terms of the GNU General Public License as published by @@ -29,35 +30,64 @@ #include #include #include -#include +#include #include "blktrace.h" #include "rbtree.h" +#include "jhash.h" -static char blkparse_version[] = "0.90"; +static char blkparse_version[] = "1.2.0"; + +struct skip_info { + unsigned long start, end; + struct skip_info *prev, *next; +}; struct per_dev_info { - dev_t id; + dev_t dev; char *name; int backwards; unsigned long long events; + unsigned long long first_reported_time; unsigned long long last_reported_time; unsigned long long last_read_time; struct io_stats io_stats; - unsigned long last_sequence; unsigned long skips; + unsigned long long seq_skips; + unsigned int max_depth[2]; + unsigned int cur_depth[2]; + + struct rb_root rb_track; int nfiles; int ncpus; + + unsigned long *cpu_map; + unsigned int cpu_map_max; + struct per_cpu_info *cpus; }; +/* + * some duplicated effort here, we can unify this hash and the ppi hash later + */ +struct process_pid_map { + pid_t pid; + char comm[16]; + struct process_pid_map *hash_next, *list_next; +}; + +#define PPM_HASH_SHIFT (8) +#define PPM_HASH_SIZE (1 << PPM_HASH_SHIFT) +#define PPM_HASH_MASK (PPM_HASH_SIZE - 1) +static struct process_pid_map *ppm_hash_table[PPM_HASH_SIZE]; + struct per_process_info { - char name[16]; - __u32 pid; + struct process_pid_map *ppm; struct io_stats io_stats; struct per_process_info *hash_next, *list_next; + int more_than_one; /* * individual io stats @@ -68,23 +98,37 @@ struct per_process_info { }; #define PPI_HASH_SHIFT (8) -static struct per_process_info *ppi_hash[1 << PPI_HASH_SHIFT]; +#define PPI_HASH_SIZE (1 << PPI_HASH_SHIFT) +#define PPI_HASH_MASK (PPI_HASH_SIZE - 1) + +enum { + SORT_PROG_EVENT_N, /* Program Name */ + SORT_PROG_EVENT_QKB, /* KB: Queued read and write */ + SORT_PROG_EVENT_RKB, /* KB: Queued Read */ + SORT_PROG_EVENT_WKB, /* KB: Queued Write */ + SORT_PROG_EVENT_CKB, /* KB: Complete */ + SORT_PROG_EVENT_QIO, /* IO: Queued read and write */ + SORT_PROG_EVENT_RIO, /* IO: Queued Read */ + SORT_PROG_EVENT_WIO, /* IO: Queued Write */ + SORT_PROG_EVENT_CIO, /* IO: Complete */ +}; + +static struct per_process_info *ppi_hash_table[PPI_HASH_SIZE]; static struct per_process_info *ppi_list; static int ppi_list_entries; -#define S_OPTS "i:o:b:stqw:f:F:v" static struct option l_opts[] = { - { - .name = "input", + { + .name = "act-mask", .has_arg = required_argument, .flag = NULL, - .val = 'i' + .val = 'a' }, { - .name = "output", + .name = "set-mask", .has_arg = required_argument, .flag = NULL, - .val = 'o' + .val = 'A' }, { .name = "batch", @@ -93,16 +137,58 @@ static struct option l_opts[] = { .val = 'b' }, { - .name = "per program stats", + .name = "input-directory", + .has_arg = required_argument, + .flag = NULL, + .val = 'D' + }, + { + .name = "dump-binary", + .has_arg = required_argument, + .flag = NULL, + .val = 'd' + }, + { + .name = "format", + .has_arg = required_argument, + .flag = NULL, + .val = 'f' + }, + { + .name = "format-spec", + .has_arg = required_argument, + .flag = NULL, + .val = 'F' + }, + { + .name = "hash-by-name", .has_arg = no_argument, .flag = NULL, - .val = 's' + .val = 'h' + }, + { + .name = "input", + .has_arg = required_argument, + .flag = NULL, + .val = 'i' }, { - .name = "track ios", + .name = "no-msgs", .has_arg = no_argument, .flag = NULL, - .val = 't' + .val = 'M' + }, + { + .name = "output", + .has_arg = required_argument, + .flag = NULL, + .val = 'o' + }, + { + .name = "no-text-output", + .has_arg = no_argument, + .flag = NULL, + .val = 'O' }, { .name = "quiet", @@ -111,29 +197,44 @@ static struct option l_opts[] = { .val = 'q' }, { - .name = "stopwatch", - .has_arg = required_argument, + .name = "per-program-stats", + .has_arg = no_argument, .flag = NULL, - .val = 'w' + .val = 's' }, { - .name = "format", + .name = "sort-program-stats", .has_arg = required_argument, .flag = NULL, - .val = 'f' + .val = 'S' }, { - .name = "format-spec", + .name = "track-ios", + .has_arg = no_argument, + .flag = NULL, + .val = 't' + }, + { + .name = "stopwatch", .has_arg = required_argument, .flag = NULL, - .val = 'F' + .val = 'w' }, { - .name = "version", + .name = "verbose", .has_arg = no_argument, .flag = NULL, .val = 'v' }, + { + .name = "version", + .has_arg = no_argument, + .flag = NULL, + .val = 'V' + }, + { + .name = NULL, + } }; /* @@ -143,14 +244,12 @@ struct trace { struct blk_io_trace *bit; struct rb_node rb_node; struct trace *next; - int skipped; + unsigned long read_sequence; }; static struct rb_root rb_sort_root; static unsigned long rb_sort_entries; -static struct rb_root rb_track_root; - static struct trace *trace_list; /* @@ -165,9 +264,8 @@ static struct trace *t_alloc_list; struct io_track { struct rb_node rb_node; - dev_t device; + struct process_pid_map *ppm; __u64 sector; - __u32 pid; unsigned long long allocation_time; unsigned long long queue_time; unsigned long long dispatch_time; @@ -177,241 +275,787 @@ struct io_track { static int ndevices; static struct per_dev_info *devices; static char *get_dev_name(struct per_dev_info *, char *, int); +static int trace_rb_insert_last(struct per_dev_info *, struct trace *); FILE *ofp = NULL; static char *output_name; +static char *input_dir; static unsigned long long genesis_time; static unsigned long long last_allowed_time; static unsigned long long stopwatch_start; /* start from zero by default */ -static unsigned long long stopwatch_end = ULONG_LONG_MAX; /* "infinity" */ +static unsigned long long stopwatch_end = -1ULL; /* "infinity" */ +static unsigned long read_sequence; static int per_process_stats; +static int per_process_stats_event = SORT_PROG_EVENT_N; +static int per_device_and_cpu_stats = 1; static int track_ios; +static int ppi_hash_by_pid = 1; +static int verbose; +static unsigned int act_mask = -1U; +static int stats_printed; +static int bin_output_msgs = 1; +int data_is_native = -1; + +static FILE *dump_fp; +static char *dump_binary; + +static unsigned int t_alloc_cache; +static unsigned int bit_alloc_cache; #define RB_BATCH_DEFAULT (512) -static int rb_batch = RB_BATCH_DEFAULT; +static unsigned int rb_batch = RB_BATCH_DEFAULT; static int pipeline; +static char *pipename; + +static int text_output = 1; #define is_done() (*(volatile int *)(&done)) static volatile int done; -static inline unsigned long hash_long(unsigned long val) -{ -#if __WORDSIZE == 32 - val *= 0x9e370001UL; -#elif __WORDSIZE == 64 - val *= 0x9e37fffffffc0001UL; -#else -#error unknown word size -#endif +struct timespec abs_start_time; +static unsigned long long start_timestamp; - return val >> (__WORDSIZE - PPI_HASH_SHIFT); -} +static int have_drv_data = 0; -static inline void add_process_to_hash(struct per_process_info *ppi) -{ - const int hash_idx = hash_long(ppi->pid); +#define JHASH_RANDOM (0x3af5f2ee) - ppi->hash_next = ppi_hash[hash_idx]; - ppi_hash[hash_idx] = ppi; -} +#define CPUS_PER_LONG (8 * sizeof(unsigned long)) +#define CPU_IDX(cpu) ((cpu) / CPUS_PER_LONG) +#define CPU_BIT(cpu) ((cpu) & (CPUS_PER_LONG - 1)) -static inline void add_process_to_list(struct per_process_info *ppi) +static void output_binary(void *buf, int len) { - ppi->list_next = ppi_list; - ppi_list = ppi; - ppi_list_entries++; + if (dump_binary) { + size_t n = fwrite(buf, len, 1, dump_fp); + if (n != 1) { + perror(dump_binary); + fclose(dump_fp); + dump_binary = NULL; + } + } } -static struct per_process_info *find_process_by_pid(__u32 pid) +static void resize_cpu_info(struct per_dev_info *pdi, int cpu) { - const int hash_idx = hash_long(pid); - struct per_process_info *ppi; - - ppi = ppi_hash[hash_idx]; - while (ppi) { - if (ppi->pid == pid) - return ppi; + struct per_cpu_info *cpus = pdi->cpus; + int ncpus = pdi->ncpus; + int new_count = cpu + 1; + int new_space, size; + char *new_start; - ppi = ppi->hash_next; + size = new_count * sizeof(struct per_cpu_info); + cpus = realloc(cpus, size); + if (!cpus) { + char name[20]; + fprintf(stderr, "Out of memory, CPU info for device %s (%d)\n", + get_dev_name(pdi, name, sizeof(name)), size); + exit(1); } - return NULL; -} + new_start = (char *)cpus + (ncpus * sizeof(struct per_cpu_info)); + new_space = (new_count - ncpus) * sizeof(struct per_cpu_info); + memset(new_start, 0, new_space); -static inline int trace_rb_insert(struct trace *t) -{ - struct rb_node **p = &rb_sort_root.rb_node; - struct rb_node *parent = NULL; - struct trace *__t; + pdi->ncpus = new_count; + pdi->cpus = cpus; - while (*p) { - parent = *p; - __t = rb_entry(parent, struct trace, rb_node); + for (new_count = 0; new_count < pdi->ncpus; new_count++) { + struct per_cpu_info *pci = &pdi->cpus[new_count]; - if (t->bit->time < __t->bit->time) - p = &(*p)->rb_left; - else if (t->bit->time > __t->bit->time) - p = &(*p)->rb_right; - else if (t->bit->device < __t->bit->device) - p = &(*p)->rb_left; - else if (t->bit->device > __t->bit->device) - p = &(*p)->rb_right; - else if (t->bit->sequence < __t->bit->sequence) - p = &(*p)->rb_left; - else if (t->bit->sequence > __t->bit->sequence) - p = &(*p)->rb_right; - else if (t->bit->device == __t->bit->device) { - fprintf(stderr, - "sequence alias (%d) on device %d,%d!\n", - t->bit->sequence, - MAJOR(t->bit->device), MINOR(t->bit->device)); - return 1; + if (!pci->fd) { + pci->fd = -1; + memset(&pci->rb_last, 0, sizeof(pci->rb_last)); + pci->rb_last_entries = 0; + pci->last_sequence = -1; } } +} - rb_sort_entries++; - rb_link_node(&t->rb_node, parent, p); - rb_insert_color(&t->rb_node, &rb_sort_root); - return 0; +static struct per_cpu_info *get_cpu_info(struct per_dev_info *pdi, int cpu) +{ + struct per_cpu_info *pci; + + if (cpu >= pdi->ncpus) + resize_cpu_info(pdi, cpu); + + pci = &pdi->cpus[cpu]; + pci->cpu = cpu; + return pci; } -static struct trace *trace_rb_find(dev_t device, unsigned long sequence) + +static int resize_devices(char *name) { - struct rb_node **p = &rb_sort_root.rb_node; - struct rb_node *parent = NULL; - struct trace *__t; + int size = (ndevices + 1) * sizeof(struct per_dev_info); - while (*p) { - parent = *p; - __t = rb_entry(parent, struct trace, rb_node); + devices = realloc(devices, size); + if (!devices) { + fprintf(stderr, "Out of memory, device %s (%d)\n", name, size); + return 1; + } + memset(&devices[ndevices], 0, sizeof(struct per_dev_info)); + devices[ndevices].name = name; + ndevices++; + return 0; +} - if (device < __t->bit->device) - p = &(*p)->rb_left; - else if (device > __t->bit->device) - p = &(*p)->rb_right; - else if (sequence < __t->bit->sequence) - p = &(*p)->rb_left; - else if (sequence > __t->bit->sequence) - p = &(*p)->rb_right; - else - return __t; +static struct per_dev_info *get_dev_info(dev_t dev) +{ + struct per_dev_info *pdi; + int i; + + for (i = 0; i < ndevices; i++) { + if (!devices[i].dev) + devices[i].dev = dev; + if (devices[i].dev == dev) + return &devices[i]; } - return NULL; + if (resize_devices(NULL)) + return NULL; + + pdi = &devices[ndevices - 1]; + pdi->dev = dev; + pdi->first_reported_time = 0; + pdi->last_read_time = 0; + + return pdi; } -static inline int track_rb_insert(struct io_track *iot) +static void insert_skip(struct per_cpu_info *pci, unsigned long start, + unsigned long end) { - struct rb_node **p = &rb_track_root.rb_node; - struct rb_node *parent = NULL; - struct io_track *__iot; + struct skip_info *sip; - while (*p) { - parent = *p; + for (sip = pci->skips_tail; sip != NULL; sip = sip->prev) { + if (end == (sip->start - 1)) { + sip->start = start; + return; + } else if (start == (sip->end + 1)) { + sip->end = end; + return; + } + } - __iot = rb_entry(parent, struct io_track, rb_node); + sip = malloc(sizeof(struct skip_info)); + sip->start = start; + sip->end = end; + sip->prev = sip->next = NULL; + if (pci->skips_tail == NULL) + pci->skips_head = pci->skips_tail = sip; + else { + sip->prev = pci->skips_tail; + pci->skips_tail->next = sip; + pci->skips_tail = sip; + } +} - if (iot->device < __iot->device) - p = &(*p)->rb_left; - else if (iot->device > __iot->device) - p = &(*p)->rb_right; - else if (iot->sector < __iot->sector) - p = &(*p)->rb_left; - else if (iot->sector > __iot->sector) - p = &(*p)->rb_right; +static void remove_sip(struct per_cpu_info *pci, struct skip_info *sip) +{ + if (sip->prev == NULL) { + if (sip->next == NULL) + pci->skips_head = pci->skips_tail = NULL; else { - fprintf(stderr, - "sector alias (%Lu) on device %d,%d!\n", - (unsigned long long) iot->sector, - MAJOR(iot->device), MINOR(iot->device)); - return 1; + pci->skips_head = sip->next; + sip->next->prev = NULL; } + } else if (sip->next == NULL) { + pci->skips_tail = sip->prev; + sip->prev->next = NULL; + } else { + sip->prev->next = sip->next; + sip->next->prev = sip->prev; } - rb_link_node(&iot->rb_node, parent, p); - rb_insert_color(&iot->rb_node, &rb_track_root); - return 0; + sip->prev = sip->next = NULL; + free(sip); } -static struct io_track *__find_track(dev_t device, __u64 sector) +#define IN_SKIP(sip,seq) (((sip)->start <= (seq)) && ((seq) <= sip->end)) +static int check_current_skips(struct per_cpu_info *pci, unsigned long seq) { - struct rb_node **p = &rb_track_root.rb_node; - struct rb_node *parent = NULL; - struct io_track *__iot; + struct skip_info *sip; - while (*p) { - parent = *p; - - __iot = rb_entry(parent, struct io_track, rb_node); - - if (device < __iot->device) - p = &(*p)->rb_left; - else if (device > __iot->device) - p = &(*p)->rb_right; - else if (sector < __iot->sector) - p = &(*p)->rb_left; - else if (sector > __iot->sector) - p = &(*p)->rb_right; - else - return __iot; + for (sip = pci->skips_tail; sip != NULL; sip = sip->prev) { + if (IN_SKIP(sip, seq)) { + if (sip->start == seq) { + if (sip->end == seq) + remove_sip(pci, sip); + else + sip->start += 1; + } else if (sip->end == seq) + sip->end -= 1; + else { + sip->end = seq - 1; + insert_skip(pci, seq + 1, sip->end); + } + return 1; + } } - return NULL; + return 0; } -static struct io_track *find_track(__u32 pid, dev_t device, __u64 sector) +static void collect_pdi_skips(struct per_dev_info *pdi) { - struct io_track *iot; + struct skip_info *sip; + int cpu; - iot = __find_track(device, sector); - if (!iot) { - iot = malloc(sizeof(*iot)); - iot->pid = pid; - iot->device = device; - iot->sector = sector; - track_rb_insert(iot); - } + pdi->skips = 0; + pdi->seq_skips = 0; - return iot; + for (cpu = 0; cpu < pdi->ncpus; cpu++) { + struct per_cpu_info *pci = &pdi->cpus[cpu]; + + for (sip = pci->skips_head; sip != NULL; sip = sip->next) { + pdi->skips++; + pdi->seq_skips += (sip->end - sip->start + 1); + if (verbose) + fprintf(stderr,"(%d,%d): skipping %lu -> %lu\n", + MAJOR(pdi->dev), MINOR(pdi->dev), + sip->start, sip->end); + } + } } -static void log_track_frontmerge(struct blk_io_trace *t) +static void cpu_mark_online(struct per_dev_info *pdi, unsigned int cpu) { - struct io_track *iot; + if (cpu >= pdi->cpu_map_max || !pdi->cpu_map) { + int new_max = (cpu + CPUS_PER_LONG) & ~(CPUS_PER_LONG - 1); + unsigned long *map = malloc(new_max / sizeof(long)); - if (!track_ios) - return; + memset(map, 0, new_max / sizeof(long)); - iot = __find_track(t->device, t->sector + (t->bytes >> 9)); - if (!iot) { - fprintf(stderr, "failed to find mergeable event\n"); - return; + if (pdi->cpu_map) { + memcpy(map, pdi->cpu_map, pdi->cpu_map_max / sizeof(long)); + free(pdi->cpu_map); + } + + pdi->cpu_map = map; + pdi->cpu_map_max = new_max; } - rb_erase(&iot->rb_node, &rb_track_root); - iot->sector -= t->bytes >> 9; - track_rb_insert(iot); + pdi->cpu_map[CPU_IDX(cpu)] |= (1UL << CPU_BIT(cpu)); } -static void log_track_getrq(struct blk_io_trace *t) +static inline void cpu_mark_offline(struct per_dev_info *pdi, int cpu) { - struct io_track *iot; + pdi->cpu_map[CPU_IDX(cpu)] &= ~(1UL << CPU_BIT(cpu)); +} - if (!track_ios) - return; +static inline int cpu_is_online(struct per_dev_info *pdi, int cpu) +{ + return (pdi->cpu_map[CPU_IDX(cpu)] & (1UL << CPU_BIT(cpu))) != 0; +} - iot = find_track(t->pid, t->device, t->sector); - iot->allocation_time = t->time; +static inline int ppm_hash_pid(pid_t pid) +{ + return jhash_1word(pid, JHASH_RANDOM) & PPM_HASH_MASK; } +static struct process_pid_map *find_ppm(pid_t pid) +{ + const int hash_idx = ppm_hash_pid(pid); + struct process_pid_map *ppm; + + ppm = ppm_hash_table[hash_idx]; + while (ppm) { + if (ppm->pid == pid) + return ppm; + + ppm = ppm->hash_next; + } + + return NULL; +} + +static struct process_pid_map *add_ppm_hash(pid_t pid, const char *name) +{ + const int hash_idx = ppm_hash_pid(pid); + struct process_pid_map *ppm; + + ppm = find_ppm(pid); + if (!ppm) { + ppm = malloc(sizeof(*ppm)); + memset(ppm, 0, sizeof(*ppm)); + ppm->pid = pid; + memset(ppm->comm, 0, sizeof(ppm->comm)); + strncpy(ppm->comm, name, sizeof(ppm->comm)); + ppm->comm[sizeof(ppm->comm) - 1] = '\0'; + ppm->hash_next = ppm_hash_table[hash_idx]; + ppm_hash_table[hash_idx] = ppm; + } + + return ppm; +} + +static void handle_notify(struct blk_io_trace *bit) +{ + void *payload = (caddr_t) bit + sizeof(*bit); + __u32 two32[2]; + + switch (bit->action) { + case BLK_TN_PROCESS: + add_ppm_hash(bit->pid, payload); + break; + + case BLK_TN_TIMESTAMP: + if (bit->pdu_len != sizeof(two32)) + return; + memcpy(two32, payload, sizeof(two32)); + if (!data_is_native) { + two32[0] = be32_to_cpu(two32[0]); + two32[1] = be32_to_cpu(two32[1]); + } + start_timestamp = bit->time; + abs_start_time.tv_sec = two32[0]; + abs_start_time.tv_nsec = two32[1]; + if (abs_start_time.tv_nsec < 0) { + abs_start_time.tv_sec--; + abs_start_time.tv_nsec += 1000000000; + } + + break; + + case BLK_TN_MESSAGE: + if (bit->pdu_len > 0) { + char msg[bit->pdu_len+1]; + + memcpy(msg, (char *)payload, bit->pdu_len); + msg[bit->pdu_len] = '\0'; + + fprintf(ofp, + "%3d,%-3d %2d %8s %5d.%09lu %5u %2s %3s %s\n", + MAJOR(bit->device), MINOR(bit->device), + bit->cpu, "0", (int) SECONDS(bit->time), + (unsigned long) NANO_SECONDS(bit->time), + 0, "m", "N", msg); + } + break; + + default: + /* Ignore unknown notify events */ + ; + } +} + +char *find_process_name(pid_t pid) +{ + struct process_pid_map *ppm = find_ppm(pid); + + if (ppm) + return ppm->comm; + + return NULL; +} + +static inline int ppi_hash_pid(pid_t pid) +{ + return jhash_1word(pid, JHASH_RANDOM) & PPI_HASH_MASK; +} + +static inline int ppi_hash_name(const char *name) +{ + return jhash(name, 16, JHASH_RANDOM) & PPI_HASH_MASK; +} + +static inline int ppi_hash(struct per_process_info *ppi) +{ + struct process_pid_map *ppm = ppi->ppm; + + if (ppi_hash_by_pid) + return ppi_hash_pid(ppm->pid); + + return ppi_hash_name(ppm->comm); +} + +static inline void add_ppi_to_hash(struct per_process_info *ppi) +{ + const int hash_idx = ppi_hash(ppi); + + ppi->hash_next = ppi_hash_table[hash_idx]; + ppi_hash_table[hash_idx] = ppi; +} + +static inline void add_ppi_to_list(struct per_process_info *ppi) +{ + ppi->list_next = ppi_list; + ppi_list = ppi; + ppi_list_entries++; +} + +static struct per_process_info *find_ppi_by_name(char *name) +{ + const int hash_idx = ppi_hash_name(name); + struct per_process_info *ppi; + + ppi = ppi_hash_table[hash_idx]; + while (ppi) { + struct process_pid_map *ppm = ppi->ppm; + + if (!strcmp(ppm->comm, name)) + return ppi; + + ppi = ppi->hash_next; + } + + return NULL; +} + +static struct per_process_info *find_ppi_by_pid(pid_t pid) +{ + const int hash_idx = ppi_hash_pid(pid); + struct per_process_info *ppi; + + ppi = ppi_hash_table[hash_idx]; + while (ppi) { + struct process_pid_map *ppm = ppi->ppm; + + if (ppm->pid == pid) + return ppi; + + ppi = ppi->hash_next; + } + + return NULL; +} + +static struct per_process_info *find_ppi(pid_t pid) +{ + struct per_process_info *ppi; + char *name; + + if (ppi_hash_by_pid) + return find_ppi_by_pid(pid); + + name = find_process_name(pid); + if (!name) + return NULL; + + ppi = find_ppi_by_name(name); + if (ppi && ppi->ppm->pid != pid) + ppi->more_than_one = 1; + + return ppi; +} + +/* + * struct trace and blktrace allocation cache, we do potentially + * millions of mallocs for these structures while only using at most + * a few thousand at the time + */ +static inline void t_free(struct trace *t) +{ + if (t_alloc_cache < 1024) { + t->next = t_alloc_list; + t_alloc_list = t; + t_alloc_cache++; + } else + free(t); +} + +static inline struct trace *t_alloc(void) +{ + struct trace *t = t_alloc_list; + + if (t) { + t_alloc_list = t->next; + t_alloc_cache--; + return t; + } + + return malloc(sizeof(*t)); +} + +static inline void bit_free(struct blk_io_trace *bit) +{ + if (bit_alloc_cache < 1024 && !bit->pdu_len) { + /* + * abuse a 64-bit field for a next pointer for the free item + */ + bit->time = (__u64) (unsigned long) bit_alloc_list; + bit_alloc_list = (struct blk_io_trace *) bit; + bit_alloc_cache++; + } else + free(bit); +} + +static inline struct blk_io_trace *bit_alloc(void) +{ + struct blk_io_trace *bit = bit_alloc_list; + + if (bit) { + bit_alloc_list = (struct blk_io_trace *) (unsigned long) \ + bit->time; + bit_alloc_cache--; + return bit; + } + + return malloc(sizeof(*bit)); +} + +static inline void __put_trace_last(struct per_dev_info *pdi, struct trace *t) +{ + struct per_cpu_info *pci = get_cpu_info(pdi, t->bit->cpu); + + rb_erase(&t->rb_node, &pci->rb_last); + pci->rb_last_entries--; + + bit_free(t->bit); + t_free(t); +} + +static void put_trace(struct per_dev_info *pdi, struct trace *t) +{ + rb_erase(&t->rb_node, &rb_sort_root); + rb_sort_entries--; + + trace_rb_insert_last(pdi, t); +} + +static inline int trace_rb_insert(struct trace *t, struct rb_root *root) +{ + struct rb_node **p = &root->rb_node; + struct rb_node *parent = NULL; + struct trace *__t; + + while (*p) { + parent = *p; + + __t = rb_entry(parent, struct trace, rb_node); + + if (t->bit->time < __t->bit->time) + p = &(*p)->rb_left; + else if (t->bit->time > __t->bit->time) + p = &(*p)->rb_right; + else if (t->bit->device < __t->bit->device) + p = &(*p)->rb_left; + else if (t->bit->device > __t->bit->device) + p = &(*p)->rb_right; + else if (t->bit->sequence < __t->bit->sequence) + p = &(*p)->rb_left; + else /* >= sequence */ + p = &(*p)->rb_right; + } + + rb_link_node(&t->rb_node, parent, p); + rb_insert_color(&t->rb_node, root); + return 0; +} + +static inline int trace_rb_insert_sort(struct trace *t) +{ + if (!trace_rb_insert(t, &rb_sort_root)) { + rb_sort_entries++; + return 0; + } + + return 1; +} + +static int trace_rb_insert_last(struct per_dev_info *pdi, struct trace *t) +{ + struct per_cpu_info *pci = get_cpu_info(pdi, t->bit->cpu); + + if (trace_rb_insert(t, &pci->rb_last)) + return 1; + + pci->rb_last_entries++; + + if (pci->rb_last_entries > rb_batch * pdi->nfiles) { + struct rb_node *n = rb_first(&pci->rb_last); + + t = rb_entry(n, struct trace, rb_node); + __put_trace_last(pdi, t); + } + + return 0; +} + +static struct trace *trace_rb_find(dev_t device, unsigned long sequence, + struct rb_root *root, int order) +{ + struct rb_node *n = root->rb_node; + struct rb_node *prev = NULL; + struct trace *__t; + + while (n) { + __t = rb_entry(n, struct trace, rb_node); + prev = n; + + if (device < __t->bit->device) + n = n->rb_left; + else if (device > __t->bit->device) + n = n->rb_right; + else if (sequence < __t->bit->sequence) + n = n->rb_left; + else if (sequence > __t->bit->sequence) + n = n->rb_right; + else + return __t; + } + + /* + * hack - the list may not be sequence ordered because some + * events don't have sequence and time matched. so we end up + * being a little off in the rb lookup here, because we don't + * know the time we are looking for. compensate by browsing + * a little ahead from the last entry to find the match + */ + if (order && prev) { + int max = 5; + + while (((n = rb_next(prev)) != NULL) && max--) { + __t = rb_entry(n, struct trace, rb_node); + + if (__t->bit->device == device && + __t->bit->sequence == sequence) + return __t; + + prev = n; + } + } + + return NULL; +} + +static inline struct trace *trace_rb_find_last(struct per_dev_info *pdi, + struct per_cpu_info *pci, + unsigned long seq) +{ + return trace_rb_find(pdi->dev, seq, &pci->rb_last, 0); +} + +static inline int track_rb_insert(struct per_dev_info *pdi,struct io_track *iot) +{ + struct rb_node **p = &pdi->rb_track.rb_node; + struct rb_node *parent = NULL; + struct io_track *__iot; + + while (*p) { + parent = *p; + __iot = rb_entry(parent, struct io_track, rb_node); + + if (iot->sector < __iot->sector) + p = &(*p)->rb_left; + else if (iot->sector > __iot->sector) + p = &(*p)->rb_right; + else { + fprintf(stderr, + "sector alias (%Lu) on device %d,%d!\n", + (unsigned long long) iot->sector, + MAJOR(pdi->dev), MINOR(pdi->dev)); + return 1; + } + } + + rb_link_node(&iot->rb_node, parent, p); + rb_insert_color(&iot->rb_node, &pdi->rb_track); + return 0; +} + +static struct io_track *__find_track(struct per_dev_info *pdi, __u64 sector) +{ + struct rb_node *n = pdi->rb_track.rb_node; + struct io_track *__iot; + + while (n) { + __iot = rb_entry(n, struct io_track, rb_node); + + if (sector < __iot->sector) + n = n->rb_left; + else if (sector > __iot->sector) + n = n->rb_right; + else + return __iot; + } + + return NULL; +} + +static struct io_track *find_track(struct per_dev_info *pdi, pid_t pid, + __u64 sector) +{ + struct io_track *iot; + + iot = __find_track(pdi, sector); + if (!iot) { + iot = malloc(sizeof(*iot)); + iot->ppm = find_ppm(pid); + if (!iot->ppm) + iot->ppm = add_ppm_hash(pid, "unknown"); + iot->sector = sector; + track_rb_insert(pdi, iot); + } + + return iot; +} + +static void log_track_frontmerge(struct per_dev_info *pdi, + struct blk_io_trace *t) +{ + struct io_track *iot; + + if (!track_ios) + return; + + iot = __find_track(pdi, t->sector + t_sec(t)); + if (!iot) { + if (verbose) + fprintf(stderr, "merge not found for (%d,%d): %llu\n", + MAJOR(t->device), MINOR(t->device), + (unsigned long long) t->sector + t_sec(t)); + return; + } + + rb_erase(&iot->rb_node, &pdi->rb_track); + iot->sector -= t_sec(t); + track_rb_insert(pdi, iot); +} + +static void log_track_getrq(struct per_dev_info *pdi, struct blk_io_trace *t) +{ + struct io_track *iot; + + if (!track_ios) + return; + + iot = find_track(pdi, t->pid, t->sector); + iot->allocation_time = t->time; +} + +static inline int is_remapper(struct per_dev_info *pdi) +{ + int major = MAJOR(pdi->dev); + + return (major == 253 || major == 9); +} + +/* + * for md/dm setups, the interesting cycle is Q -> C. So track queueing + * time here, as dispatch time + */ +static void log_track_queue(struct per_dev_info *pdi, struct blk_io_trace *t) +{ + struct io_track *iot; + + if (!track_ios) + return; + if (!is_remapper(pdi)) + return; + + iot = find_track(pdi, t->pid, t->sector); + iot->dispatch_time = t->time; +} /* * return time between rq allocation and insertion */ -static unsigned long long log_track_insert(struct blk_io_trace *t) +static unsigned long long log_track_insert(struct per_dev_info *pdi, + struct blk_io_trace *t) { unsigned long long elapsed; struct io_track *iot; @@ -419,12 +1063,16 @@ static unsigned long long log_track_insert(struct blk_io_trace *t) if (!track_ios) return -1; - iot = find_track(t->pid, t->device, t->sector); + iot = find_track(pdi, t->pid, t->sector); iot->queue_time = t->time; + + if (!iot->allocation_time) + return -1; + elapsed = iot->queue_time - iot->allocation_time; if (per_process_stats) { - struct per_process_info *ppi = find_process_by_pid(iot->pid); + struct per_process_info *ppi = find_ppi(iot->ppm->pid); int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; if (ppi && elapsed > ppi->longest_allocation_wait[w]) @@ -437,7 +1085,8 @@ static unsigned long long log_track_insert(struct blk_io_trace *t) /* * return time between queue and issue */ -static unsigned long long log_track_issue(struct blk_io_trace *t) +static unsigned long long log_track_issue(struct per_dev_info *pdi, + struct blk_io_trace *t) { unsigned long long elapsed; struct io_track *iot; @@ -447,9 +1096,12 @@ static unsigned long long log_track_issue(struct blk_io_trace *t) if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0) return -1; - iot = __find_track(t->device, t->sector); + iot = __find_track(pdi, t->sector); if (!iot) { - fprintf(stderr, "failed to find issue event\n"); + if (verbose) + fprintf(stderr, "issue not found for (%d,%d): %llu\n", + MAJOR(t->device), MINOR(t->device), + (unsigned long long) t->sector); return -1; } @@ -457,7 +1109,7 @@ static unsigned long long log_track_issue(struct blk_io_trace *t) elapsed = iot->dispatch_time - iot->queue_time; if (per_process_stats) { - struct per_process_info *ppi = find_process_by_pid(iot->pid); + struct per_process_info *ppi = find_ppi(iot->ppm->pid); int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; if (ppi && elapsed > ppi->longest_dispatch_wait[w]) @@ -470,19 +1122,21 @@ static unsigned long long log_track_issue(struct blk_io_trace *t) /* * return time between dispatch and complete */ -static unsigned long long log_track_complete(struct blk_io_trace *t) +static unsigned long long log_track_complete(struct per_dev_info *pdi, + struct blk_io_trace *t) { unsigned long long elapsed; struct io_track *iot; if (!track_ios) return -1; - if ((t->action & BLK_TC_ACT(BLK_TC_FS)) == 0) - return -1; - iot = __find_track(t->device, t->sector); + iot = __find_track(pdi, t->sector); if (!iot) { - fprintf(stderr, "failed to find complete event\n"); + if (verbose) + fprintf(stderr,"complete not found for (%d,%d): %llu\n", + MAJOR(t->device), MINOR(t->device), + (unsigned long long) t->sector); return -1; } @@ -490,7 +1144,7 @@ static unsigned long long log_track_complete(struct blk_io_trace *t) elapsed = iot->completion_time - iot->dispatch_time; if (per_process_stats) { - struct per_process_info *ppi = find_process_by_pid(iot->pid); + struct per_process_info *ppi = find_ppi(iot->ppm->pid); int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; if (ppi && elapsed > ppi->longest_completion_wait[w]) @@ -500,144 +1154,169 @@ static unsigned long long log_track_complete(struct blk_io_trace *t) /* * kill the trace, we don't need it after completion */ - rb_erase(&iot->rb_node, &rb_track_root); + rb_erase(&iot->rb_node, &pdi->rb_track); free(iot); return elapsed; } -static struct io_stats *find_process_io_stats(__u32 pid, char *name) +static struct io_stats *find_process_io_stats(pid_t pid) { - struct per_process_info *ppi = find_process_by_pid(pid); + struct per_process_info *ppi = find_ppi(pid); if (!ppi) { ppi = malloc(sizeof(*ppi)); memset(ppi, 0, sizeof(*ppi)); - strncpy(ppi->name, name, sizeof(ppi->name)); - ppi->pid = pid; - add_process_to_hash(ppi); - add_process_to_list(ppi); + ppi->ppm = find_ppm(pid); + if (!ppi->ppm) + ppi->ppm = add_ppm_hash(pid, "unknown"); + add_ppi_to_hash(ppi); + add_ppi_to_list(ppi); } return &ppi->io_stats; } - -static void resize_cpu_info(struct per_dev_info *pdi, int cpu) +static char *get_dev_name(struct per_dev_info *pdi, char *buffer, int size) { - struct per_cpu_info *cpus = pdi->cpus; - int ncpus = pdi->ncpus; - int new_count = cpu + 1; - int new_space, size; - char *new_start; + if (pdi->name) + snprintf(buffer, size, "%s", pdi->name); + else + snprintf(buffer, size, "%d,%d",MAJOR(pdi->dev),MINOR(pdi->dev)); + return buffer; +} - size = new_count * sizeof(struct per_cpu_info); - cpus = realloc(cpus, size); - if (!cpus) { - char name[20]; - fprintf(stderr, "Out of memory, CPU info for device %s (%d)\n", - get_dev_name(pdi, name, sizeof(name)), size); - exit(1); - } +static void check_time(struct per_dev_info *pdi, struct blk_io_trace *bit) +{ + unsigned long long this = bit->time; + unsigned long long last = pdi->last_reported_time; - new_start = (char *)cpus + (ncpus * sizeof(struct per_cpu_info)); - new_space = (new_count - ncpus) * sizeof(struct per_cpu_info); - memset(new_start, 0, new_space); + pdi->backwards = (this < last) ? 'B' : ' '; + pdi->last_reported_time = this; +} - pdi->ncpus = new_count; - pdi->cpus = cpus; +static inline void __account_m(struct io_stats *ios, struct blk_io_trace *t, + int rw) +{ + if (rw) { + ios->mwrites++; + ios->mwrite_kb += t_kb(t); + ios->mwrite_b += t_b(t); + } else { + ios->mreads++; + ios->mread_kb += t_kb(t); + ios->mread_b += t_b(t); + } } -static struct per_cpu_info *get_cpu_info(struct per_dev_info *pdi, int cpu) +static inline void account_m(struct blk_io_trace *t, struct per_cpu_info *pci, + int rw) { - struct per_cpu_info *pci; + __account_m(&pci->io_stats, t, rw); - if (cpu >= pdi->ncpus) - resize_cpu_info(pdi, cpu); + if (per_process_stats) { + struct io_stats *ios = find_process_io_stats(t->pid); - pci = &pdi->cpus[cpu]; - pci->cpu = cpu; - return pci; + __account_m(ios, t, rw); + } } - -static int resize_devices(char *name) +static inline void __account_pc_queue(struct io_stats *ios, + struct blk_io_trace *t, int rw) { - int size = (ndevices + 1) * sizeof(struct per_dev_info); - - devices = realloc(devices, size); - if (!devices) { - fprintf(stderr, "Out of memory, device %s (%d)\n", name, size); - return 1; + if (rw) { + ios->qwrites_pc++; + ios->qwrite_kb_pc += t_kb(t); + ios->qwrite_b_pc += t_b(t); + } else { + ios->qreads_pc++; + ios->qread_kb += t_kb(t); + ios->qread_b_pc += t_b(t); } - memset(&devices[ndevices], 0, sizeof(struct per_dev_info)); - devices[ndevices].name = name; - ndevices++; - return 0; } -static struct per_dev_info *get_dev_info(dev_t id) +static inline void account_pc_queue(struct blk_io_trace *t, + struct per_cpu_info *pci, int rw) { - struct per_dev_info *pdi; - int i; - - for (i = 0; i < ndevices; i++) { - if (!devices[i].id) - devices[i].id = id; - if (devices[i].id == id) - return &devices[i]; - } + __account_pc_queue(&pci->io_stats, t, rw); - if (resize_devices(NULL) != 0) - return NULL; + if (per_process_stats) { + struct io_stats *ios = find_process_io_stats(t->pid); - pdi = &devices[ndevices - 1]; - pdi->id = id; - pdi->last_sequence = 0; - pdi->last_read_time = 0; - return pdi; + __account_pc_queue(ios, t, rw); + } } -static char *get_dev_name(struct per_dev_info *pdi, char *buffer, int size) +static inline void __account_pc_issue(struct io_stats *ios, int rw, + unsigned int bytes) { - if (pdi->name) - snprintf(buffer, size, "%s", pdi->name); - else - snprintf(buffer, size, "%d,%d", MAJOR(pdi->id), MINOR(pdi->id)); - return buffer; + if (rw) { + ios->iwrites_pc++; + ios->iwrite_kb_pc += bytes >> 10; + ios->iwrite_b_pc += bytes & 1023; + } else { + ios->ireads_pc++; + ios->iread_kb_pc += bytes >> 10; + ios->iread_b_pc += bytes & 1023; + } } -static void check_time(struct per_dev_info *pdi, struct blk_io_trace *bit) +static inline void account_pc_issue(struct blk_io_trace *t, + struct per_cpu_info *pci, int rw) { - unsigned long long this = bit->time; - unsigned long long last = pdi->last_reported_time; + __account_pc_issue(&pci->io_stats, rw, t->bytes); - pdi->backwards = (this < last) ? 'B' : ' '; - pdi->last_reported_time = this; + if (per_process_stats) { + struct io_stats *ios = find_process_io_stats(t->pid); + + __account_pc_issue(ios, rw, t->bytes); + } } -static inline void __account_m(struct io_stats *ios, struct blk_io_trace *t, - int rw) +static inline void __account_pc_requeue(struct io_stats *ios, + struct blk_io_trace *t, int rw) { if (rw) { - ios->mwrites++; - ios->qwrite_kb += t->bytes >> 10; + ios->wrqueue_pc++; + ios->iwrite_kb_pc -= t_kb(t); + ios->iwrite_b_pc -= t_b(t); } else { - ios->mreads++; - ios->qread_kb += t->bytes >> 10; + ios->rrqueue_pc++; + ios->iread_kb_pc -= t_kb(t); + ios->iread_b_pc -= t_b(t); } } -static inline void account_m(struct blk_io_trace *t, struct per_cpu_info *pci, - int rw) +static inline void account_pc_requeue(struct blk_io_trace *t, + struct per_cpu_info *pci, int rw) { - __account_m(&pci->io_stats, t, rw); + __account_pc_requeue(&pci->io_stats, t, rw); if (per_process_stats) { - struct io_stats *ios = find_process_io_stats(t->pid, t->comm); + struct io_stats *ios = find_process_io_stats(t->pid); - __account_m(ios, t, rw); + __account_pc_requeue(ios, t, rw); + } +} + +static inline void __account_pc_c(struct io_stats *ios, int rw) +{ + if (rw) + ios->cwrites_pc++; + else + ios->creads_pc++; +} + +static inline void account_pc_c(struct blk_io_trace *t, + struct per_cpu_info *pci, int rw) +{ + __account_pc_c(&pci->io_stats, rw); + + if (per_process_stats) { + struct io_stats *ios = find_process_io_stats(t->pid); + + __account_pc_c(ios, rw); } } @@ -646,10 +1325,12 @@ static inline void __account_queue(struct io_stats *ios, struct blk_io_trace *t, { if (rw) { ios->qwrites++; - ios->qwrite_kb += t->bytes >> 10; + ios->qwrite_kb += t_kb(t); + ios->qwrite_b += t_b(t); } else { ios->qreads++; - ios->qread_kb += t->bytes >> 10; + ios->qread_kb += t_kb(t); + ios->qread_b += t_b(t); } } @@ -659,20 +1340,22 @@ static inline void account_queue(struct blk_io_trace *t, __account_queue(&pci->io_stats, t, rw); if (per_process_stats) { - struct io_stats *ios = find_process_io_stats(t->pid, t->comm); + struct io_stats *ios = find_process_io_stats(t->pid); __account_queue(ios, t, rw); } } -static inline void __account_c(struct io_stats *ios, int rw, unsigned int bytes) +static inline void __account_c(struct io_stats *ios, int rw, int bytes) { if (rw) { ios->cwrites++; ios->cwrite_kb += bytes >> 10; + ios->cwrite_b += bytes & 1023; } else { ios->creads++; ios->cread_kb += bytes >> 10; + ios->cread_b += bytes & 1023; } } @@ -682,7 +1365,7 @@ static inline void account_c(struct blk_io_trace *t, struct per_cpu_info *pci, __account_c(&pci->io_stats, rw, bytes); if (per_process_stats) { - struct io_stats *ios = find_process_io_stats(t->pid, t->comm); + struct io_stats *ios = find_process_io_stats(t->pid); __account_c(ios, rw, bytes); } @@ -694,9 +1377,11 @@ static inline void __account_issue(struct io_stats *ios, int rw, if (rw) { ios->iwrites++; ios->iwrite_kb += bytes >> 10; + ios->iwrite_b += bytes & 1023; } else { ios->ireads++; ios->iread_kb += bytes >> 10; + ios->iread_b += bytes & 1023; } } @@ -706,7 +1391,7 @@ static inline void account_issue(struct blk_io_trace *t, __account_issue(&pci->io_stats, rw, t->bytes); if (per_process_stats) { - struct io_stats *ios = find_process_io_stats(t->pid, t->comm); + struct io_stats *ios = find_process_io_stats(t->pid); __account_issue(ios, rw, t->bytes); } @@ -726,22 +1411,48 @@ static inline void account_unplug(struct blk_io_trace *t, __account_unplug(&pci->io_stats, timer); if (per_process_stats) { - struct io_stats *ios = find_process_io_stats(t->pid, t->comm); + struct io_stats *ios = find_process_io_stats(t->pid); __account_unplug(ios, timer); } } -static void log_complete(struct per_cpu_info *pci, struct blk_io_trace *t, - char *act) +static inline void __account_requeue(struct io_stats *ios, + struct blk_io_trace *t, int rw) { - process_fmt(act, pci, t, log_track_complete(t), 0, NULL); + if (rw) { + ios->wrqueue++; + ios->iwrite_kb -= t_kb(t); + ios->iwrite_b -= t_b(t); + } else { + ios->rrqueue++; + ios->iread_kb -= t_kb(t); + ios->iread_b -= t_b(t); + } } -static void log_insert(struct per_cpu_info *pci, struct blk_io_trace *t, - char *act) +static inline void account_requeue(struct blk_io_trace *t, + struct per_cpu_info *pci, int rw) { - process_fmt(act, pci, t, log_track_insert(t), 0, NULL); + __account_requeue(&pci->io_stats, t, rw); + + if (per_process_stats) { + struct io_stats *ios = find_process_io_stats(t->pid); + + __account_requeue(ios, t, rw); + } +} + +static void log_complete(struct per_dev_info *pdi, struct per_cpu_info *pci, + struct blk_io_trace *t, char *act) +{ + process_fmt(act, pci, t, log_track_complete(pdi, t), 0, NULL); +} + +static void log_insert(struct per_dev_info *pdi, struct per_cpu_info *pci, + struct blk_io_trace *t, char *act) +{ + process_fmt(act, pci, t, log_track_insert(pdi, t), 0, NULL); } static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t, @@ -750,17 +1461,17 @@ static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t, process_fmt(act, pci, t, -1, 0, NULL); } -static void log_issue(struct per_cpu_info *pci, struct blk_io_trace *t, - char *act) +static void log_issue(struct per_dev_info *pdi, struct per_cpu_info *pci, + struct blk_io_trace *t, char *act) { - process_fmt(act, pci, t, log_track_issue(t), 0, NULL); + process_fmt(act, pci, t, log_track_issue(pdi, t), 0, NULL); } -static void log_merge(struct per_cpu_info *pci, struct blk_io_trace *t, - char *act) +static void log_merge(struct per_dev_info *pdi, struct per_cpu_info *pci, + struct blk_io_trace *t, char *act) { if (act[0] == 'F') - log_track_frontmerge(t); + log_track_frontmerge(pdi, t); process_fmt(act, pci, t, -1ULL, 0, NULL); } @@ -796,13 +1507,16 @@ static void log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char *act) process_fmt(act, pci, t, -1ULL, t->pdu_len, buf); } -static void dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci) +static void dump_trace_pc(struct blk_io_trace *t, struct per_dev_info *pdi, + struct per_cpu_info *pci) { + int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; int act = t->action & 0xffff; switch (act) { case __BLK_TA_QUEUE: log_generic(pci, t, "Q"); + account_pc_queue(t, pci, w); break; case __BLK_TA_GETRQ: log_generic(pci, t, "G"); @@ -811,13 +1525,27 @@ static void dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci) log_generic(pci, t, "S"); break; case __BLK_TA_REQUEUE: + /* + * can happen if we miss traces, don't let it go + * below zero + */ + if (pdi->cur_depth[w]) + pdi->cur_depth[w]--; + account_pc_requeue(t, pci, w); log_generic(pci, t, "R"); break; case __BLK_TA_ISSUE: + account_pc_issue(t, pci, w); + pdi->cur_depth[w]++; + if (pdi->cur_depth[w] > pdi->max_depth[w]) + pdi->max_depth[w] = pdi->cur_depth[w]; log_pc(pci, t, "D"); break; case __BLK_TA_COMPLETE: + if (pdi->cur_depth[w]) + pdi->cur_depth[w]--; log_pc(pci, t, "C"); + account_pc_c(t, pci, w); break; case __BLK_TA_INSERT: log_pc(pci, t, "I"); @@ -828,45 +1556,58 @@ static void dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci) } } -static void dump_trace_fs(struct blk_io_trace *t, struct per_cpu_info *pci) +static void dump_trace_fs(struct blk_io_trace *t, struct per_dev_info *pdi, + struct per_cpu_info *pci) { - int w = t->action & BLK_TC_ACT(BLK_TC_WRITE); + int w = (t->action & BLK_TC_ACT(BLK_TC_WRITE)) != 0; int act = t->action & 0xffff; switch (act) { case __BLK_TA_QUEUE: + log_track_queue(pdi, t); account_queue(t, pci, w); log_queue(pci, t, "Q"); break; case __BLK_TA_INSERT: - log_insert(pci, t, "I"); + log_insert(pdi, pci, t, "I"); break; case __BLK_TA_BACKMERGE: account_m(t, pci, w); - log_merge(pci, t, "M"); + log_merge(pdi, pci, t, "M"); break; case __BLK_TA_FRONTMERGE: account_m(t, pci, w); - log_merge(pci, t, "F"); + log_merge(pdi, pci, t, "F"); break; case __BLK_TA_GETRQ: - log_track_getrq(t); + log_track_getrq(pdi, t); log_generic(pci, t, "G"); break; case __BLK_TA_SLEEPRQ: log_generic(pci, t, "S"); break; case __BLK_TA_REQUEUE: - account_c(t, pci, w, -t->bytes); + /* + * can happen if we miss traces, don't let it go + * below zero + */ + if (pdi->cur_depth[w]) + pdi->cur_depth[w]--; + account_requeue(t, pci, w); log_queue(pci, t, "R"); break; case __BLK_TA_ISSUE: account_issue(t, pci, w); - log_issue(pci, t, "D"); + pdi->cur_depth[w]++; + if (pdi->cur_depth[w] > pdi->max_depth[w]) + pdi->max_depth[w] = pdi->cur_depth[w]; + log_issue(pdi, pci, t, "D"); break; case __BLK_TA_COMPLETE: + if (pdi->cur_depth[w]) + pdi->cur_depth[w]--; account_c(t, pci, w, t->bytes); - log_complete(pci, t, "C"); + log_complete(pdi, pci, t, "C"); break; case __BLK_TA_PLUG: log_action(pci, t, "P"); @@ -885,36 +1626,124 @@ static void dump_trace_fs(struct blk_io_trace *t, struct per_cpu_info *pci) case __BLK_TA_BOUNCE: log_generic(pci, t, "B"); break; + case __BLK_TA_REMAP: + log_generic(pci, t, "A"); + break; + case __BLK_TA_DRV_DATA: + have_drv_data = 1; + /* dump to binary file only */ + break; default: fprintf(stderr, "Bad fs action %x\n", t->action); break; } } -static void dump_trace(struct blk_io_trace *t, struct per_cpu_info *pci, - struct per_dev_info *pdi) +static void dump_trace(struct blk_io_trace *t, struct per_cpu_info *pci, + struct per_dev_info *pdi) +{ + if (text_output) { + if (t->action == BLK_TN_MESSAGE) + handle_notify(t); + else if (t->action & BLK_TC_ACT(BLK_TC_PC)) + dump_trace_pc(t, pdi, pci); + else + dump_trace_fs(t, pdi, pci); + } + + if (!pdi->events) + pdi->first_reported_time = t->time; + + pdi->events++; + + if (bin_output_msgs || + !(t->action & BLK_TC_ACT(BLK_TC_NOTIFY) && + t->action == BLK_TN_MESSAGE)) + output_binary(t, sizeof(*t) + t->pdu_len); +} + +/* + * print in a proper way, not too small and not too big. if more than + * 1000,000K, turn into M and so on + */ +static char *size_cnv(char *dst, unsigned long long num, int in_kb) { - if (t->action & BLK_TC_ACT(BLK_TC_PC)) - dump_trace_pc(t, pci); - else - dump_trace_fs(t, pci); + char suff[] = { '\0', 'K', 'M', 'G', 'P' }; + unsigned int i = 0; - pdi->events++; + if (in_kb) + i++; + + while (num > 1000 * 1000ULL && (i < sizeof(suff) - 1)) { + i++; + num /= 1000; + } + + sprintf(dst, "%'8Lu%c", num, suff[i]); + return dst; } -static void dump_io_stats(struct io_stats *ios, char *msg) +static void dump_io_stats(struct per_dev_info *pdi, struct io_stats *ios, + char *msg) { - fprintf(ofp, "%s\n", msg); + static char x[256], y[256]; - fprintf(ofp, " Reads Queued: %'8lu, %'8LuKiB\t", ios->qreads, ios->qread_kb); - fprintf(ofp, " Writes Queued: %'8lu, %'8LuKiB\n", ios->qwrites,ios->qwrite_kb); + fprintf(ofp, "%s\n", msg); - fprintf(ofp, " Read Dispatches: %'8lu, %'8LuKiB\t", ios->ireads, ios->iread_kb); - fprintf(ofp, " Write Dispatches: %'8lu, %'8LuKiB\n", ios->iwrites,ios->iwrite_kb); - fprintf(ofp, " Reads Completed: %'8lu, %'8LuKiB\t", ios->creads, ios->cread_kb); - fprintf(ofp, " Writes Completed: %'8lu, %'8LuKiB\n", ios->cwrites,ios->cwrite_kb); - fprintf(ofp, " Read Merges: %'8lu%8c\t", ios->mreads, ' '); - fprintf(ofp, " Write Merges: %'8lu\n", ios->mwrites); + fprintf(ofp, " Reads Queued: %s, %siB\t", + size_cnv(x, ios->qreads, 0), + size_cnv(y, ios->qread_kb + (ios->qread_b>>10), 1)); + fprintf(ofp, " Writes Queued: %s, %siB\n", + size_cnv(x, ios->qwrites, 0), + size_cnv(y, ios->qwrite_kb + (ios->qwrite_b>>10), 1)); + fprintf(ofp, " Read Dispatches: %s, %siB\t", + size_cnv(x, ios->ireads, 0), + size_cnv(y, ios->iread_kb + (ios->iread_b>>10), 1)); + fprintf(ofp, " Write Dispatches: %s, %siB\n", + size_cnv(x, ios->iwrites, 0), + size_cnv(y, ios->iwrite_kb + (ios->iwrite_b>>10), 1)); + fprintf(ofp, " Reads Requeued: %s\t\t", size_cnv(x, ios->rrqueue, 0)); + fprintf(ofp, " Writes Requeued: %s\n", size_cnv(x, ios->wrqueue, 0)); + fprintf(ofp, " Reads Completed: %s, %siB\t", + size_cnv(x, ios->creads, 0), + size_cnv(y, ios->cread_kb + (ios->cread_b>>10), 1)); + fprintf(ofp, " Writes Completed: %s, %siB\n", + size_cnv(x, ios->cwrites, 0), + size_cnv(y, ios->cwrite_kb + (ios->cwrite_b>>10), 1)); + fprintf(ofp, " Read Merges: %s, %siB\t", + size_cnv(x, ios->mreads, 0), + size_cnv(y, ios->mread_kb + (ios->mread_b>>10), 1)); + fprintf(ofp, " Write Merges: %s, %siB\n", + size_cnv(x, ios->mwrites, 0), + size_cnv(y, ios->mwrite_kb + (ios->mwrite_b>>10), 1)); + if (pdi) { + fprintf(ofp, " Read depth: %'8u%8c\t", pdi->max_depth[0], ' '); + fprintf(ofp, " Write depth: %'8u\n", pdi->max_depth[1]); + } + if (ios->qreads_pc || ios->qwrites_pc || ios->ireads_pc || ios->iwrites_pc || + ios->rrqueue_pc || ios->wrqueue_pc || ios->creads_pc || ios->cwrites_pc) { + fprintf(ofp, " PC Reads Queued: %s, %siB\t", + size_cnv(x, ios->qreads_pc, 0), + size_cnv(y, + ios->qread_kb_pc + (ios->qread_b_pc>>10), 1)); + fprintf(ofp, " PC Writes Queued: %s, %siB\n", + size_cnv(x, ios->qwrites_pc, 0), + size_cnv(y, + ios->qwrite_kb_pc + (ios->qwrite_b_pc>>10), 1)); + fprintf(ofp, " PC Read Disp.: %s, %siB\t", + size_cnv(x, ios->ireads_pc, 0), + size_cnv(y, + ios->iread_kb_pc + (ios->iread_b_pc>>10), 1)); + fprintf(ofp, " PC Write Disp.: %s, %siB\n", + size_cnv(x, ios->iwrites_pc, 0), + size_cnv(y, + ios->iwrite_kb_pc + (ios->iwrite_b_pc>>10), + 1)); + fprintf(ofp, " PC Reads Req.: %s\t\t", size_cnv(x, ios->rrqueue_pc, 0)); + fprintf(ofp, " PC Writes Req.: %s\n", size_cnv(x, ios->wrqueue_pc, 0)); + fprintf(ofp, " PC Reads Compl.: %s\t\t", size_cnv(x, ios->creads_pc, 0)); + fprintf(ofp, " PC Writes Compl.: %s\n", size_cnv(x, ios->cwrites_pc, 0)); + } fprintf(ofp, " IO unplugs: %'8lu%8c\t", ios->io_unplugs, ' '); fprintf(ofp, " Timer unplugs: %'8lu\n", ios->timer_unplugs); } @@ -942,13 +1771,95 @@ static int ppi_name_compare(const void *p1, const void *p2) struct per_process_info *ppi2 = *((struct per_process_info **) p2); int res; - res = strverscmp(ppi1->name, ppi2->name); + res = strverscmp(ppi1->ppm->comm, ppi2->ppm->comm); if (!res) - res = ppi1->pid > ppi2->pid; + res = ppi1->ppm->pid > ppi2->ppm->pid; return res; } +static int ppi_event_compare(const void *p1, const void *p2) +{ + struct per_process_info *ppi1 = *((struct per_process_info **) p1); + struct per_process_info *ppi2 = *((struct per_process_info **) p2); + struct io_stats *ios1 = &ppi1->io_stats; + struct io_stats *ios2 = &ppi2->io_stats; + unsigned long io1, io2; + unsigned long long kb1,kb2; + int sort_by_kb = 1; + + io1 = io2 = 0; + kb1 = kb2 = 0; + + switch (per_process_stats_event) { + case SORT_PROG_EVENT_QKB: /* KB: Queued read and write */ + kb1 = ios1->qwrite_kb + (ios1->qwrite_b>>10) + + ios1->qread_kb + (ios1->qread_b>>10); + kb2 = ios2->qwrite_kb + (ios2->qwrite_b>>10) + + ios2->qread_kb + (ios2->qread_b>>10); + break; + case SORT_PROG_EVENT_RKB: /* KB: Queued Read */ + kb1 = ios1->qread_kb + (ios1->qread_b>>10); + kb2 = ios2->qread_kb + (ios2->qread_b>>10); + break; + case SORT_PROG_EVENT_WKB: /* KB: Queued Write */ + kb1 = ios1->qwrite_kb + (ios1->qwrite_b>>10); + kb2 = ios2->qwrite_kb + (ios2->qwrite_b>>10); + break; + case SORT_PROG_EVENT_CKB: /* KB: Complete */ + kb1 = ios1->cwrite_kb + (ios1->cwrite_b>>10) + + ios1->cread_kb + (ios1->cread_b>>10); + kb2 = ios2->cwrite_kb + (ios2->cwrite_b>>10) + + ios2->cread_kb + (ios2->cread_b>>10); + break; + case SORT_PROG_EVENT_QIO: /* IO: Queued read and write */ + sort_by_kb = 0; + io1 = ios1->qreads + ios1->qwrites; + io2 = ios2->qreads + ios2->qwrites; + break; + case SORT_PROG_EVENT_RIO: /* IO: Queued Read */ + sort_by_kb = 0; + io1 = ios1->qreads; + io2 = ios2->qreads; + break; + case SORT_PROG_EVENT_WIO: /* IO: Queued Write */ + sort_by_kb = 0; + io1 = ios1->qwrites; + io2 = ios2->qwrites; + break; + case SORT_PROG_EVENT_CIO: /* IO: Complete */ + sort_by_kb = 0; + io1 = ios1->creads + ios1->cwrites; + io2 = ios2->creads + ios2->cwrites; + break; + } + + + /* compare kb */ + if (sort_by_kb) { + if (kb1 > kb2) + return 1; + else if (kb1 == kb2) + return 0; + return -1; + } + + /* compare io */ + if (io1 > io2) + return 1; + else if (io1 == io2) + return 0; + return -1; +} + +static int ppi_compare(const void *p1, const void *p2) +{ + if (per_process_stats_event == SORT_PROG_EVENT_N) + return ppi_name_compare(p1, p2); + + return ppi_event_compare(p1, p2); +} + static void sort_process_list(void) { struct per_process_info **ppis; @@ -963,7 +1874,7 @@ static void sort_process_list(void) ppi = ppi->list_next; } - qsort(ppis, ppi_list_entries, sizeof(ppi), ppi_name_compare); + qsort(ppis, ppi_list_entries, sizeof(ppi), ppi_compare); i = ppi_list_entries - 1; ppi_list = NULL; @@ -986,10 +1897,15 @@ static void show_process_stats(void) ppi = ppi_list; while (ppi) { + struct process_pid_map *ppm = ppi->ppm; char name[64]; - snprintf(name, sizeof(name)-1, "%s (%u)", ppi->name, ppi->pid); - dump_io_stats(&ppi->io_stats, name); + if (ppi->more_than_one) + sprintf(name, "%s (%u, ...)", ppm->comm, ppm->pid); + else + sprintf(name, "%s (%u)", ppm->comm, ppm->pid); + + dump_io_stats(NULL, &ppi->io_stats, name); dump_wait_stats(ppi); ppi = ppi->list_next; } @@ -1002,9 +1918,11 @@ static void show_device_and_cpu_stats(void) struct per_dev_info *pdi; struct per_cpu_info *pci; struct io_stats total, *ios; + unsigned long long rrate, wrate, msec; int i, j, pci_events; char line[3 + 8/*cpu*/ + 2 + 32/*dev*/ + 3]; char name[32]; + double ratio; for (pdi = devices, i = 0; i < ndevices; i++, pdi++) { @@ -1027,18 +1945,48 @@ static void show_device_and_cpu_stats(void) total.mwrites += ios->mwrites; total.ireads += ios->ireads; total.iwrites += ios->iwrites; + total.rrqueue += ios->rrqueue; + total.wrqueue += ios->wrqueue; total.qread_kb += ios->qread_kb; total.qwrite_kb += ios->qwrite_kb; total.cread_kb += ios->cread_kb; total.cwrite_kb += ios->cwrite_kb; total.iread_kb += ios->iread_kb; total.iwrite_kb += ios->iwrite_kb; + total.mread_kb += ios->mread_kb; + total.mwrite_kb += ios->mwrite_kb; + total.qread_b += ios->qread_b; + total.qwrite_b += ios->qwrite_b; + total.cread_b += ios->cread_b; + total.cwrite_b += ios->cwrite_b; + total.iread_b += ios->iread_b; + total.iwrite_b += ios->iwrite_b; + total.mread_b += ios->mread_b; + total.mwrite_b += ios->mwrite_b; + + total.qreads_pc += ios->qreads_pc; + total.qwrites_pc += ios->qwrites_pc; + total.creads_pc += ios->creads_pc; + total.cwrites_pc += ios->cwrites_pc; + total.ireads_pc += ios->ireads_pc; + total.iwrites_pc += ios->iwrites_pc; + total.rrqueue_pc += ios->rrqueue_pc; + total.wrqueue_pc += ios->wrqueue_pc; + total.qread_kb_pc += ios->qread_kb_pc; + total.qwrite_kb_pc += ios->qwrite_kb_pc; + total.iread_kb_pc += ios->iread_kb_pc; + total.iwrite_kb_pc += ios->iwrite_kb_pc; + total.qread_b_pc += ios->qread_b_pc; + total.qwrite_b_pc += ios->qwrite_b_pc; + total.iread_b_pc += ios->iread_b_pc; + total.iwrite_b_pc += ios->iwrite_b_pc; + total.timer_unplugs += ios->timer_unplugs; total.io_unplugs += ios->io_unplugs; snprintf(line, sizeof(line) - 1, "CPU%d (%s):", j, get_dev_name(pdi, name, sizeof(name))); - dump_io_stats(ios, line); + dump_io_stats(pdi, ios, line); pci_events++; } @@ -1046,12 +1994,47 @@ static void show_device_and_cpu_stats(void) fprintf(ofp, "\n"); snprintf(line, sizeof(line) - 1, "Total (%s):", get_dev_name(pdi, name, sizeof(name))); - dump_io_stats(&total, line); + dump_io_stats(NULL, &total, line); } - fprintf(ofp, "\nEvents (%s): %'Lu entries, %'lu skips\n", - get_dev_name(pdi, line, sizeof(line)), pdi->events, - pdi->skips); + wrate = rrate = 0; + msec = (pdi->last_reported_time - pdi->first_reported_time) / 1000000; + if (msec) { + rrate = ((1000 * total.cread_kb) + total.cread_b) / + msec; + wrate = ((1000 * total.cwrite_kb) + total.cwrite_b) / + msec; + } + + fprintf(ofp, "\nThroughput (R/W): %'LuKiB/s / %'LuKiB/s\n", + rrate, wrate); + fprintf(ofp, "Events (%s): %'Lu entries\n", + get_dev_name(pdi, line, sizeof(line)), pdi->events); + + collect_pdi_skips(pdi); + if (!pdi->skips && !pdi->events) + ratio = 0.0; + else + ratio = 100.0 * ((double)pdi->seq_skips / + (double)(pdi->events + pdi->seq_skips)); + fprintf(ofp, "Skips: %'lu forward (%'llu - %5.1lf%%)\n", + pdi->skips, pdi->seq_skips, ratio); + } +} + +static void correct_abs_start_time(void) +{ + long delta = genesis_time - start_timestamp; + + abs_start_time.tv_sec += SECONDS(delta); + abs_start_time.tv_nsec += NANO_SECONDS(delta); + if (abs_start_time.tv_nsec < 0) { + abs_start_time.tv_nsec += 1000000000; + abs_start_time.tv_sec -= 1; + } else + if (abs_start_time.tv_nsec > 1000000000) { + abs_start_time.tv_nsec -= 1000000000; + abs_start_time.tv_sec += 1; } } @@ -1066,359 +2049,750 @@ static void find_genesis(void) t = t->next; } + + /* The time stamp record will usually be the first + * record in the trace, but not always. + */ + if (start_timestamp + && start_timestamp != genesis_time) { + correct_abs_start_time(); + } } -static int sort_entries(void) +static inline int check_stopwatch(struct blk_io_trace *bit) { + if (bit->time < stopwatch_end && + bit->time >= stopwatch_start) + return 0; + + return 1; +} + +/* + * return youngest entry read + */ +static int sort_entries(unsigned long long *youngest) +{ + struct per_dev_info *pdi = NULL; + struct per_cpu_info *pci = NULL; struct trace *t; - int nr = 0; if (!genesis_time) find_genesis(); + *youngest = 0; while ((t = trace_list) != NULL) { + struct blk_io_trace *bit = t->bit; + trace_list = t->next; - if (verify_trace(t->bit)) + bit->time -= genesis_time; + + if (bit->time < *youngest || !*youngest) + *youngest = bit->time; + + if (!pdi || pdi->dev != bit->device) { + pdi = get_dev_info(bit->device); + pci = NULL; + } + + if (!pci || pci->cpu != bit->cpu) + pci = get_cpu_info(pdi, bit->cpu); + + if (bit->sequence < pci->smallest_seq_read) + pci->smallest_seq_read = bit->sequence; + + if (check_stopwatch(bit)) { + bit_free(bit); + t_free(t); + continue; + } + + if (trace_rb_insert_sort(t)) + return -1; + } + + return 0; +} + +/* + * to continue, we must have traces from all online cpus in the tree + */ +static int check_cpu_map(struct per_dev_info *pdi) +{ + unsigned long *cpu_map; + struct rb_node *n; + struct trace *__t; + unsigned int i; + int ret, cpu; + + /* + * create a map of the cpus we have traces for + */ + cpu_map = malloc(pdi->cpu_map_max / sizeof(long)); + memset(cpu_map, 0, sizeof(*cpu_map)); + n = rb_first(&rb_sort_root); + while (n) { + __t = rb_entry(n, struct trace, rb_node); + cpu = __t->bit->cpu; + + cpu_map[CPU_IDX(cpu)] |= (1UL << CPU_BIT(cpu)); + n = rb_next(n); + } + + /* + * we can't continue if pdi->cpu_map has entries set that we don't + * have in the sort rbtree. the opposite is not a problem, though + */ + ret = 0; + for (i = 0; i < pdi->cpu_map_max / CPUS_PER_LONG; i++) { + if (pdi->cpu_map[i] & ~(cpu_map[i])) { + ret = 1; + break; + } + } + + free(cpu_map); + return ret; +} + +static int check_sequence(struct per_dev_info *pdi, struct trace *t, int force) +{ + struct blk_io_trace *bit = t->bit; + unsigned long expected_sequence; + struct per_cpu_info *pci; + struct trace *__t; + + pci = get_cpu_info(pdi, bit->cpu); + expected_sequence = pci->last_sequence + 1; + + if (!expected_sequence) { + /* + * 1 should be the first entry, just allow it + */ + if (bit->sequence == 1) + return 0; + if (bit->sequence == pci->smallest_seq_read) + return 0; + + return check_cpu_map(pdi); + } + + if (bit->sequence == expected_sequence) + return 0; + + /* + * we may not have seen that sequence yet. if we are not doing + * the final run, break and wait for more entries. + */ + if (expected_sequence < pci->smallest_seq_read) { + __t = trace_rb_find_last(pdi, pci, expected_sequence); + if (!__t) + goto skip; + + __put_trace_last(pdi, __t); + return 0; + } else if (!force) { + return 1; + } else { +skip: + if (check_current_skips(pci, bit->sequence)) + return 0; + + if (expected_sequence < bit->sequence) + insert_skip(pci, expected_sequence, bit->sequence - 1); + return 0; + } +} + +static void show_entries_rb(int force) +{ + struct per_dev_info *pdi = NULL; + struct per_cpu_info *pci = NULL; + struct blk_io_trace *bit; + struct rb_node *n; + struct trace *t; + + while ((n = rb_first(&rb_sort_root)) != NULL) { + if (is_done() && !force && !pipeline) + break; + + t = rb_entry(n, struct trace, rb_node); + bit = t->bit; + + if (read_sequence - t->read_sequence < 1 && !force) + break; + + if (!pdi || pdi->dev != bit->device) { + pdi = get_dev_info(bit->device); + pci = NULL; + } + + if (!pdi) { + fprintf(stderr, "Unknown device ID? (%d,%d)\n", + MAJOR(bit->device), MINOR(bit->device)); + break; + } + + if (!(bit->action == BLK_TN_MESSAGE) && + check_sequence(pdi, t, force)) + break; + + if (!force && bit->time > last_allowed_time) + break; + + check_time(pdi, bit); + + if (!pci || pci->cpu != bit->cpu) + pci = get_cpu_info(pdi, bit->cpu); + + if (!(bit->action == BLK_TN_MESSAGE)) + pci->last_sequence = bit->sequence; + + pci->nelems++; + + if (bit->action & (act_mask << BLK_TC_SHIFT)) + dump_trace(bit, pci, pdi); + + put_trace(pdi, t); + } +} + +static int read_data(int fd, void *buffer, int bytes, int block, int *fdblock) +{ + int ret, bytes_left, fl; + void *p; + + if (block != *fdblock) { + fl = fcntl(fd, F_GETFL); + + if (!block) { + *fdblock = 0; + fcntl(fd, F_SETFL, fl | O_NONBLOCK); + } else { + *fdblock = 1; + fcntl(fd, F_SETFL, fl & ~O_NONBLOCK); + } + } + + bytes_left = bytes; + p = buffer; + while (bytes_left > 0) { + ret = read(fd, p, bytes_left); + if (!ret) + return 1; + else if (ret < 0) { + if (errno != EAGAIN) { + perror("read"); + return -1; + } + + /* + * never do partial reads. we can return if we + * didn't read anything and we should not block, + * otherwise wait for data + */ + if ((bytes_left == bytes) && !block) + return 1; + + usleep(10); continue; + } else { + p += ret; + bytes_left -= ret; + } + } + + return 0; +} + +static inline __u16 get_pdulen(struct blk_io_trace *bit) +{ + if (data_is_native) + return bit->pdu_len; + + return __bswap_16(bit->pdu_len); +} + +static inline __u32 get_magic(struct blk_io_trace *bit) +{ + if (data_is_native) + return bit->magic; + + return __bswap_32(bit->magic); +} - t->bit->time -= genesis_time; +static int read_events(int fd, int always_block, int *fdblock) +{ + struct per_dev_info *pdi = NULL; + unsigned int events = 0; + + while (!is_done() && events < rb_batch) { + struct blk_io_trace *bit; + struct trace *t; + int pdu_len, should_block, ret; + __u32 magic; + + bit = bit_alloc(); + + should_block = !events || always_block; + + ret = read_data(fd, bit, sizeof(*bit), should_block, fdblock); + if (ret) { + bit_free(bit); + if (!events && ret < 0) + events = ret; + break; + } + + /* + * look at first trace to check whether we need to convert + * data in the future + */ + if (data_is_native == -1 && check_data_endianness(bit->magic)) + break; - if (trace_rb_insert(t)) + magic = get_magic(bit); + if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) { + fprintf(stderr, "Bad magic %x\n", magic); break; - nr++; + } + + pdu_len = get_pdulen(bit); + if (pdu_len) { + void *ptr = realloc(bit, sizeof(*bit) + pdu_len); + + if (read_data(fd, ptr + sizeof(*bit), pdu_len, 1, fdblock)) { + bit_free(ptr); + break; + } + + bit = ptr; + } + + trace_to_cpu(bit); + + if (verify_trace(bit)) { + bit_free(bit); + continue; + } + + /* + * not a real trace, so grab and handle it here + */ + if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) { + handle_notify(bit); + output_binary(bit, sizeof(*bit) + bit->pdu_len); + continue; + } + + t = t_alloc(); + memset(t, 0, sizeof(*t)); + t->bit = bit; + t->read_sequence = read_sequence; + + t->next = trace_list; + trace_list = t; + + if (!pdi || pdi->dev != bit->device) + pdi = get_dev_info(bit->device); + + if (bit->time > pdi->last_read_time) + pdi->last_read_time = bit->time; + + events++; } - return nr; -} + return events; +} + +/* + * Managing input streams + */ + +struct ms_stream { + struct ms_stream *next; + struct trace *first, *last; + struct per_dev_info *pdi; + unsigned int cpu; +}; + +#define MS_HASH(d, c) ((MAJOR(d) & 0xff) ^ (MINOR(d) & 0xff) ^ (cpu & 0xff)) + +struct ms_stream *ms_head; +struct ms_stream *ms_hash[256]; + +static void ms_sort(struct ms_stream *msp); +static int ms_prime(struct ms_stream *msp); -/* - * struct trace and blktrace allocation cache, we do potentially - * millions of mallocs for these structures while only using at most - * a few thousand at the time - */ -static inline void t_free(struct trace *t) +static inline struct trace *ms_peek(struct ms_stream *msp) { - t->next = t_alloc_list; - t_alloc_list = t; + return (msp == NULL) ? NULL : msp->first; } -static inline struct trace *t_alloc(void) +static inline __u64 ms_peek_time(struct ms_stream *msp) { - struct trace *t = t_alloc_list; + return ms_peek(msp)->bit->time; +} - if (t) { - t_alloc_list = t->next; - return t; +static inline void ms_resort(struct ms_stream *msp) +{ + if (msp->next && ms_peek_time(msp) > ms_peek_time(msp->next)) { + ms_head = msp->next; + msp->next = NULL; + ms_sort(msp); } - - return malloc(sizeof(*t)); } -static inline void bit_free(struct blk_io_trace *bit) +static inline void ms_deq(struct ms_stream *msp) { - /* - * abuse a 64-bit field for a next pointer for the free item - */ - bit->time = (__u64) (unsigned long) bit_alloc_list; - bit_alloc_list = (struct blk_io_trace *) bit; + msp->first = msp->first->next; + if (!msp->first) { + msp->last = NULL; + if (!ms_prime(msp)) { + ms_head = msp->next; + msp->next = NULL; + return; + } + } + + ms_resort(msp); } -static inline struct blk_io_trace *bit_alloc(void) +static void ms_sort(struct ms_stream *msp) { - struct blk_io_trace *bit = bit_alloc_list; + __u64 msp_t = ms_peek_time(msp); + struct ms_stream *this_msp = ms_head; - if (bit) { - bit_alloc_list = (struct blk_io_trace *) (unsigned long) \ - bit->time; - return bit; + if (this_msp == NULL) + ms_head = msp; + else if (msp_t < ms_peek_time(this_msp)) { + msp->next = this_msp; + ms_head = msp; } + else { + while (this_msp->next && ms_peek_time(this_msp->next) < msp_t) + this_msp = this_msp->next; - return malloc(sizeof(*bit)); + msp->next = this_msp->next; + this_msp->next = msp; + } } -static void show_entries_rb(int force) +static int ms_prime(struct ms_stream *msp) { - struct per_dev_info *pdi = NULL; - struct per_cpu_info *pci = NULL; - struct blk_io_trace *bit; - struct rb_node *n; + __u32 magic; + unsigned int i; struct trace *t; + struct per_dev_info *pdi = msp->pdi; + struct per_cpu_info *pci = get_cpu_info(pdi, msp->cpu); + struct blk_io_trace *bit = NULL; + int ret, pdu_len, ndone = 0; - while ((n = rb_first(&rb_sort_root)) != NULL) { + for (i = 0; !is_done() && pci->fd >= 0 && i < rb_batch; i++) { + bit = bit_alloc(); + ret = read_data(pci->fd, bit, sizeof(*bit), 1, &pci->fdblock); + if (ret) + goto err; - if (done) - break; + if (data_is_native == -1 && check_data_endianness(bit->magic)) + goto err; - t = rb_entry(n, struct trace, rb_node); - bit = t->bit; + magic = get_magic(bit); + if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) { + fprintf(stderr, "Bad magic %x\n", magic); + goto err; - if (!pdi || pdi->id != bit->device) - pdi = get_dev_info(bit->device); + } - if (!pdi) { - fprintf(stderr, "Unknown device ID? (%d,%d)\n", - MAJOR(bit->device), MINOR(bit->device)); - break; + pdu_len = get_pdulen(bit); + if (pdu_len) { + void *ptr = realloc(bit, sizeof(*bit) + pdu_len); + ret = read_data(pci->fd, ptr + sizeof(*bit), pdu_len, + 1, &pci->fdblock); + if (ret) { + free(ptr); + bit = NULL; + goto err; + } + + bit = ptr; } - if (bit->cpu > pdi->ncpus) { - fprintf(stderr, "Unknown CPU ID? (%d, device %d,%d)\n", - bit->cpu, MAJOR(bit->device), - MINOR(bit->device)); - break; + trace_to_cpu(bit); + if (verify_trace(bit)) + goto err; + + if (bit->cpu != pci->cpu) { + fprintf(stderr, "cpu %d trace info has error cpu %d\n", + pci->cpu, bit->cpu); + continue; } - /* - * back off displaying more info if we are out of sync - * on SMP systems. to prevent stalling on lost events, - * only allow an event to skip us a few times - */ - if (bit->sequence > (pdi->last_sequence + 1) && !force) { - struct trace *__t; + if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY) && bit->action != BLK_TN_MESSAGE) { + handle_notify(bit); + output_binary(bit, sizeof(*bit) + bit->pdu_len); + bit_free(bit); - /* - * the wanted sequence is really there, continue - * because this means that the log time is earlier - * on the trace we have now - */ - __t = trace_rb_find(pdi->id, pdi->last_sequence + 1); - if (__t) - goto ok; + i -= 1; + continue; + } - if (t->skipped < 5) { - t->skipped++; - break; - } else - pdi->skips++; + if (bit->time > pdi->last_read_time) + pdi->last_read_time = bit->time; + + t = t_alloc(); + memset(t, 0, sizeof(*t)); + t->bit = bit; + + if (msp->first == NULL) + msp->first = msp->last = t; + else { + msp->last->next = t; + msp->last = t; } -ok: - if (bit->time >= stopwatch_end) - break; + ndone++; + } - if (!force && bit->time > last_allowed_time) - break; + return ndone; - pdi->last_sequence = bit->sequence; +err: + if (bit) bit_free(bit); - if (bit->time >= stopwatch_start) { - check_time(pdi, bit); + cpu_mark_offline(pdi, pci->cpu); + close(pci->fd); + pci->fd = -1; - if (!pci || pci->cpu != bit->cpu) - pci = get_cpu_info(pdi, bit->cpu); + return ndone; +} - dump_trace(bit, pci, pdi); - } +static struct ms_stream *ms_alloc(struct per_dev_info *pdi, int cpu) +{ + struct ms_stream *msp = malloc(sizeof(*msp)); - rb_erase(&t->rb_node, &rb_sort_root); - rb_sort_entries--; - bit_free(bit); - t_free(t); - } + msp->next = NULL; + msp->first = msp->last = NULL; + msp->pdi = pdi; + msp->cpu = cpu; + + if (ms_prime(msp)) + ms_sort(msp); + + return msp; } -static int read_data(int fd, void *buffer, int bytes, int block) +static int setup_file(struct per_dev_info *pdi, int cpu) { - int ret, bytes_left, fl; - void *p; + int len = 0; + struct stat st; + char *p, *dname; + struct per_cpu_info *pci = get_cpu_info(pdi, cpu); - fl = fcntl(fd, F_GETFL); + pci->cpu = cpu; + pci->fdblock = -1; + + p = strdup(pdi->name); + dname = dirname(p); + if (strcmp(dname, ".")) { + input_dir = dname; + p = strdup(pdi->name); + strcpy(pdi->name, basename(p)); + } + free(p); - if (!block) - fcntl(fd, F_SETFL, fl | O_NONBLOCK); - else - fcntl(fd, F_SETFL, fl & ~O_NONBLOCK); + if (input_dir) + len = sprintf(pci->fname, "%s/", input_dir); - bytes_left = bytes; - p = buffer; - while (bytes_left > 0) { - ret = read(fd, p, bytes_left); - if (!ret) - return 1; - else if (ret < 0) { - if (errno != EAGAIN) - perror("read"); + snprintf(pci->fname + len, sizeof(pci->fname)-1-len, + "%s.blktrace.%d", pdi->name, pci->cpu); + if (stat(pci->fname, &st) < 0) + return 0; + if (!st.st_size) + return 1; - return -1; - } else { - p += ret; - bytes_left -= ret; - } + pci->fd = open(pci->fname, O_RDONLY); + if (pci->fd < 0) { + perror(pci->fname); + return 0; } - return 0; -} + printf("Input file %s added\n", pci->fname); + cpu_mark_online(pdi, pci->cpu); -static int read_events(int fd, int always_block) -{ - struct per_dev_info *pdi = NULL; - int events = 0; + pdi->nfiles++; + ms_alloc(pdi, pci->cpu); - while (!is_done() && events < rb_batch) { - struct blk_io_trace *bit; - struct trace *t; - int pdu_len; - __u32 magic; + return 1; +} - bit = bit_alloc(); +static int handle(struct ms_stream *msp) +{ + struct trace *t; + struct per_dev_info *pdi; + struct per_cpu_info *pci; + struct blk_io_trace *bit; - if (read_data(fd, bit, sizeof(*bit), !events || always_block)) - break; + t = ms_peek(msp); - magic = be32_to_cpu(bit->magic); - if ((magic & 0xffffff00) != BLK_IO_TRACE_MAGIC) { - fprintf(stderr, "Bad magic %x\n", magic); - break; - } + bit = t->bit; + pdi = msp->pdi; + pci = get_cpu_info(pdi, msp->cpu); + pci->nelems++; + bit->time -= genesis_time; - pdu_len = be16_to_cpu(bit->pdu_len); - if (pdu_len) { - void *ptr = realloc(bit, sizeof(*bit) + pdu_len); + if (t->bit->time > stopwatch_end) + return 0; - if (read_data(fd, ptr + sizeof(*bit), pdu_len, 1)) - break; + pdi->last_reported_time = bit->time; + if ((bit->action & (act_mask << BLK_TC_SHIFT))&& + t->bit->time >= stopwatch_start) + dump_trace(bit, pci, pdi); - bit = ptr; - } + ms_deq(msp); - t = t_alloc(); - memset(t, 0, sizeof(*t)); - t->bit = bit; + if (text_output) + trace_rb_insert_last(pdi, t); + else { + bit_free(t->bit); + t_free(t); + } - trace_to_cpu(bit); - t->next = trace_list; - trace_list = t; + return 1; +} - if (!pdi || pdi->id != bit->device) - pdi = get_dev_info(bit->device); +/* + * Check if we need to sanitize the name. We allow 'foo', or if foo.blktrace.X + * is given, then strip back down to 'foo' to avoid missing files. + */ +static int name_fixup(char *name) +{ + char *b; - if (bit->time > pdi->last_read_time) - pdi->last_read_time = bit->time; + if (!name) + return 1; - events++; - } + b = strstr(name, ".blktrace."); + if (b) + *b = '\0'; - return events; + return 0; } static int do_file(void) { - struct per_cpu_info *pci; + int i, cpu, ret; struct per_dev_info *pdi; - int i, j, events, events_added; /* * first prepare all files for reading */ for (i = 0; i < ndevices; i++) { pdi = &devices[i]; - pdi->nfiles = 0; - pdi->last_sequence = 0; - - for (j = 0;; j++) { - struct stat st; - - pci = get_cpu_info(pdi, j); - pci->cpu = j; - pci->fd = -1; + ret = name_fixup(pdi->name); + if (ret) + return ret; - snprintf(pci->fname, sizeof(pci->fname)-1, - "%s.blktrace.%d", pdi->name, pci->cpu); - if (stat(pci->fname, &st) < 0) - break; - if (st.st_size) { - pci->fd = open(pci->fname, O_RDONLY); - if (pci->fd < 0) { - perror(pci->fname); - continue; - } - } + for (cpu = 0; setup_file(pdi, cpu); cpu++) + ; - printf("Input file %s added\n", pci->fname); - pdi->nfiles++; + if (!cpu) { + fprintf(stderr,"No input files found for %s\n", + pdi->name); + return 1; } } /* - * now loop over the files reading in the data + * Get the initial time stamp */ - do { - events_added = 0; - last_allowed_time = -1ULL; - - for (i = 0; i < ndevices; i++) { - pdi = &devices[i]; + if (ms_head) + genesis_time = ms_peek_time(ms_head); - for (j = 0; j < pdi->nfiles; j++) { + /* + * Correct abs_start_time if necessary + */ + if (start_timestamp + && start_timestamp != genesis_time) { + correct_abs_start_time(); + } - pci = get_cpu_info(pdi, j); + /* + * Keep processing traces while any are left + */ + while (!is_done() && ms_head && handle(ms_head)) + ; - if (pci->fd == -1) - continue; + return 0; +} - events = read_events(pci->fd, 1); - if (!events) { - close(pci->fd); - pci->fd = -1; - continue; - } +static void do_pipe(int fd) +{ + unsigned long long youngest; + int events, fdblock; - if (pdi->last_read_time < last_allowed_time) - last_allowed_time = pdi->last_read_time; + last_allowed_time = -1ULL; + fdblock = -1; + while ((events = read_events(fd, 0, &fdblock)) > 0) { + read_sequence++; + +#if 0 + smallest_seq_read = -1U; +#endif - events_added += events; - } - } + if (sort_entries(&youngest)) + break; - if (sort_entries() == -1) + if (youngest > stopwatch_end) break; show_entries_rb(0); - - } while (events_added); + } if (rb_sort_entries) show_entries_rb(1); - - return 0; } -static int do_stdin(void) +static int do_fifo(void) { int fd; - last_allowed_time = -1ULL; - fd = dup(STDIN_FILENO); - do { - int events; - - events = read_events(fd, 0); - if (!events) - break; - - if (sort_entries() == -1) - break; - - show_entries_rb(0); - } while (1); + if (!strcmp(pipename, "-")) + fd = dup(STDIN_FILENO); + else + fd = open(pipename, O_RDONLY); - if (rb_sort_entries) - show_entries_rb(1); + if (fd == -1) { + perror("dup stdin"); + return -1; + } + do_pipe(fd); close(fd); return 0; } -static void flush_output(void) +static void show_stats(void) { + if (!ofp) + return; + if (stats_printed) + return; + + stats_printed = 1; + + if (per_process_stats) + show_process_stats(); + + if (per_device_and_cpu_stats) + show_device_and_cpu_stats(); + fflush(ofp); } -static void handle_sigint(int sig) +static void handle_sigint(__attribute__((__unused__)) int sig) { done = 1; - flush_output(); } /* @@ -1459,45 +2833,155 @@ static int find_stopwatch_interval(char *string) return 0; } -static char usage_str[] = \ - "[ -i ] [-o [ -s ] [ -t ] [ -q ]\n" \ - "[ -w start:stop ] [ -f output format ] [ -F format spec ] [ -v] \n\n" \ +static int is_pipe(const char *str) +{ + struct stat st; + + if (!strcmp(str, "-")) + return 1; + if (!stat(str, &st) && S_ISFIFO(st.st_mode)) + return 1; + + return 0; +} + +static int get_program_sort_event(const char *str) +{ + char evt = str[0]; + + switch (evt) { + case 'N': + per_process_stats_event = SORT_PROG_EVENT_N; + break; + case 'Q': + per_process_stats_event = SORT_PROG_EVENT_QKB; + break; + case 'q': + per_process_stats_event = SORT_PROG_EVENT_QIO; + break; + case 'R': + per_process_stats_event = SORT_PROG_EVENT_RKB; + break; + case 'r': + per_process_stats_event = SORT_PROG_EVENT_RIO; + break; + case 'W': + per_process_stats_event = SORT_PROG_EVENT_WKB; + break; + case 'w': + per_process_stats_event = SORT_PROG_EVENT_WIO; + break; + case 'C': + per_process_stats_event = SORT_PROG_EVENT_CKB; + break; + case 'c': + per_process_stats_event = SORT_PROG_EVENT_CIO; + break; + default: + return 1; + } + + return 0; +} + +#define S_OPTS "a:A:b:D:d:f:F:hi:o:OqsS:tw:vVM" +static char usage_str[] = "\n\n" \ + "-i | --input=\n" \ + "[ -a | --act-mask= ]\n" \ + "[ -A | --set-mask= ]\n" \ + "[ -b | --batch= ]\n" \ + "[ -d | --dump-binary= ]\n" \ + "[ -D | --input-directory= ]\n" \ + "[ -f | --format= ]\n" \ + "[ -F | --format-spec= ]\n" \ + "[ -h | --hash-by-name ]\n" \ + "[ -o | --output= ]\n" \ + "[ -O | --no-text-output ]\n" \ + "[ -q | --quiet ]\n" \ + "[ -s | --per-program-stats ]\n" \ + "[ -S | --sort-program-stats= ]\n" \ + "[ -t | --track-ios ]\n" \ + "[ -w