From 21e47d90eb3160c797a9d5ef5032cd371eacedc5 Mon Sep 17 00:00:00 2001 From: Alan David Brunelle Date: Thu, 21 Sep 2006 09:16:27 +0200 Subject: [PATCH] [PATCH] Added iostat-style statistics to btt Added iostat-style statistics: rrqm/s, wrqm/s, r/s, w/s, rsec/s, wsec/s, rkB/s, wkB/s, avgrq-sz, avgqu-sz, await, svctm, %util. Signed-off-by: Alan D. Brunelle Signed-off-by: Jens Axboe --- btt/Makefile | 2 +- btt/args.c | 46 +++++++-- btt/bt_timeline.c | 6 ++ btt/devs.c | 2 + btt/globals.h | 27 ++++- btt/iostat.c | 247 ++++++++++++++++++++++++++++++++++++++++++++++ btt/trace.c | 9 +- 7 files changed, 328 insertions(+), 11 deletions(-) create mode 100644 btt/iostat.c diff --git a/btt/Makefile b/btt/Makefile index 86d70f0..b86e828 100644 --- a/btt/Makefile +++ b/btt/Makefile @@ -8,7 +8,7 @@ PROGS = btt #PLIBS = -lpthread LIBS = $(PLIBS) $(ELIBS) OBJS = bt_timeline.o args.o output.o proc.o trace.o misc.o devs.o \ - traverse.o iofree.o devmap.o cylist.o seek.o + traverse.o iofree.o devmap.o cylist.o seek.o iostat.o all: depend $(PROGS) diff --git a/btt/args.c b/btt/args.c index bed39c8..a198da2 100644 --- a/btt/args.c +++ b/btt/args.c @@ -28,7 +28,7 @@ #include "globals.h" -#define S_OPTS "d:D:e:hlmM:i:o:s:Vv" +#define S_OPTS "d:D:e:hi:I:lmM:o:s:S:Vv" static struct option l_opts[] = { { .name = "range-delta", @@ -54,6 +54,18 @@ static struct option l_opts[] = { .flag = NULL, .val = 'h' }, + { + .name = "input-file", + .has_arg = required_argument, + .flag = NULL, + .val = 'i' + }, + { + .name = "iostat", + .has_arg = required_argument, + .flag = NULL, + .val = 'I' + }, { .name = "lvm", .has_arg = no_argument, @@ -72,12 +84,6 @@ static struct option l_opts[] = { .flag = NULL, .val = 'M' }, - { - .name = "input-file", - .has_arg = required_argument, - .flag = NULL, - .val = 'i' - }, { .name = "output-file", .has_arg = required_argument, @@ -90,6 +96,12 @@ static struct option l_opts[] = { .flag = NULL, .val = 's' }, + { + .name = "iostat-interval", + .has_arg = required_argument, + .flag = NULL, + .val = 'S' + }, { .name = "version", .has_arg = no_argument, @@ -112,9 +124,12 @@ static char usage_str[] = \ "[ -e | --exes= ]\n" \ "[ -h | --help ]\n" \ "[ -i | --input-file= ]\n" \ + "[ -I | --iostat= ]\n" \ "(-l | -m) | (--lvm | -md)\n" \ + "[ -M | --dev-maps=\n" \ "[ -o | --output-file= ]\n" \ "[ -s | --seeks= ]\n" \ + "[ -S | --iostat-interval= ]\n" \ "[ -V | --version ]\n" \ "[ -v | --verbose ]\n\n"; @@ -146,6 +161,9 @@ void handle_args(int argc, char *argv[]) case 'i': input_name = optarg; break; + case 'I': + iostat_name = optarg; + break; case 'l': is_lvm = 1; break; @@ -161,6 +179,12 @@ void handle_args(int argc, char *argv[]) case 's': seek_name = optarg; break; + case 'S': { + unsigned int interval; + sscanf(optarg, "%u", &interval); + iostat_interval = (__u64)interval * (1000 * 1000 * 1000); + break; + } case 'v': verbose = 1; break; @@ -212,4 +236,12 @@ void handle_args(int argc, char *argv[]) free(fname); } + + if (iostat_name != NULL) { + iostat_ofp = fopen(iostat_name, "w"); + if (iostat_ofp == NULL) { + perror(iostat_name); + exit(1); + } + } } diff --git a/btt/bt_timeline.c b/btt/bt_timeline.c index 1c3216d..ce5662e 100644 --- a/btt/bt_timeline.c +++ b/btt/bt_timeline.c @@ -65,6 +65,7 @@ int main(int argc, char *argv[]) handle_args(argc, argv); cy_init(); + iostat_init(); if (process() || output_avgs(avgs_ofp) || output_ranges(ranges_ofp)) return 1; @@ -92,6 +93,11 @@ int process(void) } IO_FREE(iop); + if (iostat_ofp) { + fprintf(iostat_ofp, "\n"); + iostat_dump_stats(iostat_last_stamp, 1); + } + if (verbose) printf("\n%10lu traces, %10lu mallocs %1lu frees\n", n_traces, n_io_allocs, n_io_frees); diff --git a/btt/devs.c b/btt/devs.c index 90d44fa..2801804 100644 --- a/btt/devs.c +++ b/btt/devs.c @@ -69,6 +69,8 @@ struct d_info *dip_add(__u32 device, struct io *iop) init_region(&dip->regions); dip->map = dev_map_find(device); dip->seek_handle = seeki_init(device); + memset(&dip->stats, 0, sizeof(dip->stats)); + memset(&dip->all_stats, 0, sizeof(dip->all_stats)); if (dev_heads == NULL) init_dev_heads(); list_add_tail(&dip->hash_head, &dev_heads[DEV_HASH(device)]); diff --git a/btt/globals.h b/btt/globals.h index 7bc89ef..dcb25a6 100644 --- a/btt/globals.h +++ b/btt/globals.h @@ -32,6 +32,7 @@ #define BIT_START(iop) ((iop)->t.sector) #define BIT_END(iop) ((iop)->t.sector + ((iop)->t.bytes >> 9)) #define IOP_READ(iop) ((iop)->t.action & BLK_TC_ACT(BLK_TC_READ)) +#define IOP_RW(iop) (IOP_READ(iop) ? 1 : 0) #if defined(DEBUG) #define ASSERT(truth) do { \ @@ -135,6 +136,17 @@ struct devmap { char devno[32]; }; +struct stats { + __u64 rqm[2]; + __u64 ios[2]; + __u64 sec[2]; + __u64 wait; + __u64 svctm; + + int cur_qusz, cur_dev; + double last_qu_change, last_dev_change, tot_qusz, idle_time; +}; + struct d_info { struct list_head head, hash_head; struct list_head iop_heads[N_IOP_TYPES]; @@ -145,6 +157,7 @@ struct d_info { __u64 n_ds; struct devmap *map; void *seek_handle; + struct stats stats, all_stats; }; struct io { @@ -191,9 +204,9 @@ struct io { }; extern char bt_timeline_version[], *devices, *exes, *input_name, *output_name; -extern char *seek_name; +extern char *seek_name, *iostat_name; extern double range_delta; -extern FILE *ranges_ofp, *avgs_ofp; +extern FILE *ranges_ofp, *avgs_ofp, *iostat_ofp; extern int is_lvm, verbose, ifd; extern unsigned int n_devs; extern unsigned long n_traces, n_io_allocs, n_io_frees; @@ -204,9 +217,11 @@ extern struct region_info all_regions; extern struct my_mem *free_ios, *free_bits; extern char iop_map[]; extern unsigned int pending_xs; +extern __u64 iostat_interval, iostat_last_stamp; void add_trace(struct io *iop); int in_devices(struct blk_io_trace *t); +char *make_dev_hdr(char *pad, size_t len, struct d_info *dip); int output_avgs(FILE *ofp); int output_ranges(FILE *ofp); unsigned int do_read(int ifd, void *buf, int len); @@ -231,4 +246,12 @@ long long seeki_nseeks(void *handle); long long seeki_median(void *handle); int seeki_mode(void *handle, long long **modes_p, int *nseeks_p); +void iostat_init(void); +void iostat_insert(struct io *iop); +void iostat_merge(struct io *iop); +void iostat_issue(struct io *iop); +void iostat_complete(struct io *iop); +void iostat_check_time(__u64 stamp); +void iostat_dump_stats(__u64 stamp, int all); + #include "inlines.h" diff --git a/btt/iostat.c b/btt/iostat.c new file mode 100644 index 0000000..4f375dc --- /dev/null +++ b/btt/iostat.c @@ -0,0 +1,247 @@ +/* + * blktrace output analysis: generate a timeline & gather statistics + * + * Copyright (C) 2006 Alan D. Brunelle + * + * 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 + * the Free Software Foundation; either version 2 of the License, or + * (at your option) any later version. + * + * This program is distributed in the hope that it will be useful, + * but WITHOUT ANY WARRANTY; without even the implied warranty of + * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the + * GNU General Public License for more details. + * + * You should have received a copy of the GNU General Public License + * along with this program; if not, write to the Free Software + * Foundation, Inc., 59 Temple Place, Suite 330, Boston, MA 02111-1307 USA + * + */ +#include +#include +#include "globals.h" + +#define TO_SEC(nanosec) ((double)(nanosec) / 1.0e9) +#define TO_MSEC(nanosec) (1000.0 * TO_SEC(nanosec)) + +#define INC_STAT(dip, fld) \ + do { \ + (dip)->stats. fld ++; \ + (dip)->all_stats. fld ++; \ + } while (0) + +#define DEC_STAT(dip, fld) \ + do { \ + (dip)->stats. fld --; \ + (dip)->all_stats. fld --; \ + } while (0) + +#define ADD_STAT(dip, fld, val) \ + do { \ + __u64 __v = (val); \ + (dip)->stats. fld += __v; \ + (dip)->all_stats. fld += __v; \ + } while (0) + +#define SUB_STAT(dip, fld, val) \ + do { \ + __u64 __v = (val); \ + (dip)->stats. fld -= __v; \ + (dip)->all_stats. fld -= __v; \ + } while (0) + +__u64 last_start, iostat_last_stamp; +__u64 iostat_interval = 1; +char *iostat_name = NULL; +FILE *iostat_ofp = NULL; + +void calc_waits(struct io *d_iop, __u64 c_time) +{ + __u64 waits = 0; + struct list_head *p; + struct io_list *iolp; + + __list_for_each(p, &d_iop->u.d.d_im_head) { + iolp = list_entry(p, struct io_list, head); + waits += (c_time - iolp->iop->t.time); + } + ADD_STAT(d_iop->dip, wait, waits); +} + +void dump_hdr(void) +{ + fprintf(iostat_ofp, "Device: rrqm/s wrqm/s r/s w/s " + "rsec/s wsec/s rkB/s wkB/s " + "avgrq-sz avgqu-sz await svctm %%util Stamp\n"); +} + +void iostat_init(void) +{ + last_start = (__u64)-1; + if (iostat_ofp) + dump_hdr(); +} + +void update_tot_qusz(struct d_info *dip, double now) +{ + dip->stats.tot_qusz += ((now - dip->stats.last_qu_change) * + dip->stats.cur_qusz); + dip->all_stats.tot_qusz += ((now - dip->all_stats.last_qu_change) * + dip->all_stats.cur_qusz); + + dip->stats.last_qu_change = dip->all_stats.last_qu_change = now; +} + +void update_idle_time(struct d_info *dip, double now) +{ + if (dip->stats.cur_dev == 0) { + dip->stats.idle_time += (now - dip->stats.last_dev_change); + dip->all_stats.idle_time += + (now - dip->all_stats.last_dev_change); + } + dip->stats.last_dev_change = dip->all_stats.last_dev_change = now; +} + +void __dump_stats(__u64 stamp, int all, struct d_info *dip) +{ + char hdr[16]; + struct stats *sp; + double dt, nios, avgrq_sz, p_util, nrqm; + double now = TO_SEC(stamp); + + if (all) { + dt = (double)stamp / 1.0e9; + sp = &dip->all_stats; + } + else { + dt = (double)(stamp-last_start) / 1.0e9; + sp = &dip->stats; + } + + nios = (double)(sp->ios[0] + sp->ios[1]); + nrqm = (double)(sp->rqm[0] + sp->rqm[1]); + if (nios > 0.0) { + update_idle_time(dip, now); + update_tot_qusz(dip, now); + avgrq_sz = (double)(sp->sec[0] + sp->sec[1]) / nios; + p_util = 100.0 * (1.0 - (sp->idle_time / dt)); + + /* + * For AWAIT: nios should be the same as number of inserts + * and we add in nrqm (number of merges), which should give + * us the total number of IOs sent to the block IO layer. + */ + fprintf(iostat_ofp, "%-11s ", make_dev_hdr(hdr, 11, dip)); + fprintf(iostat_ofp, "%8.2lf ", (double)sp->rqm[1] / dt); + fprintf(iostat_ofp, "%8.2lf ", (double)sp->rqm[0] / dt); + fprintf(iostat_ofp, "%7.2lf ", (double)sp->ios[1] / dt); + fprintf(iostat_ofp, "%7.2lf ", (double)sp->ios[0] / dt); + fprintf(iostat_ofp, "%9.2lf ", (double)sp->sec[1] / dt); + fprintf(iostat_ofp, "%9.2lf ", (double)sp->sec[0] / dt); + fprintf(iostat_ofp, "%9.2lf ", (double)(sp->sec[1] / 2) / dt); + fprintf(iostat_ofp, "%9.2lf ", (double)(sp->sec[0] / 2) / dt); + fprintf(iostat_ofp, "%8.2lf ", avgrq_sz); + fprintf(iostat_ofp, "%8.2lf ", (double)sp->tot_qusz / dt); + fprintf(iostat_ofp, "%7.2lf ", TO_MSEC(sp->wait) / (nios+nrqm)); + fprintf(iostat_ofp, "%7.2lf ", TO_MSEC(sp->svctm) / nios); + fprintf(iostat_ofp, "%6.2lf", p_util); + if (all) + fprintf(iostat_ofp, "%8s\n", "TOTAL"); + else { + fprintf(iostat_ofp, "%8.2lf\n", TO_SEC(stamp)); + sp->rqm[0] = sp->rqm[1] = 0; + sp->ios[0] = sp->ios[1] = 0; + sp->sec[0] = sp->sec[1] = 0; + sp->wait = sp->svctm = 0; + + sp->tot_qusz = sp->idle_time = 0.0; + } + } +} + +void iostat_dump_stats(__u64 stamp, int all) +{ + struct d_info *dip; + + if (all) + dump_hdr(); + if (devices == NULL) { + struct list_head *p; + + __list_for_each(p, &all_devs) { + dip = list_entry(p, struct d_info, head); + __dump_stats(stamp, all, dip); + } + } + else { + int i; + unsigned int mjr, mnr; + char *p = devices; + + while (p && ((i = sscanf(p, "%u,%u", &mjr, &mnr)) == 2)) { + dip = __dip_find((__u32)((mjr << MINORBITS) | mnr)); + __dump_stats(stamp, all, dip); + + p = strchr(p, ';'); + if (p) p++; + } + } +} + +void iostat_check_time(__u64 stamp) +{ + if (iostat_ofp) { + if (last_start == (__u64)-1) + last_start = stamp; + else if ((stamp - last_start) >= iostat_interval) { + iostat_dump_stats(stamp, 0); + last_start = stamp; + } + + iostat_last_stamp = stamp; + } +} + +void iostat_insert(struct io *iop) +{ + update_tot_qusz(iop->dip, TO_SEC(iop->t.time)); + INC_STAT(iop->dip, cur_qusz); +} + +void iostat_merge(struct io *iop) +{ + INC_STAT(iop->dip, rqm[IOP_RW(iop)]); +} + +void iostat_issue(struct io *iop) +{ + int rw = IOP_RW(iop); + struct d_info *dip = iop->dip; + double now = TO_SEC(iop->t.time); + + INC_STAT(dip, ios[rw]); + ADD_STAT(dip, sec[rw], iop->t.bytes >> 9); + + update_idle_time(dip, now); + INC_STAT(dip, cur_dev); +} + +void iostat_complete(struct io *iop) +{ + struct io *d_iop; + struct d_info *dip = iop->dip; + + if ((d_iop = iop->u.c.c_d) != NULL) { + double now = TO_SEC(iop->t.time); + calc_waits(d_iop, iop->t.time); + + update_tot_qusz(dip, now); + DEC_STAT(dip, cur_qusz); + + update_idle_time(dip, now); + DEC_STAT(dip, cur_dev); + + ADD_STAT(dip, svctm, iop->t.time - d_iop->t.time); + } +} diff --git a/btt/trace.c b/btt/trace.c index 076100c..5250232 100644 --- a/btt/trace.c +++ b/btt/trace.c @@ -165,6 +165,8 @@ void handle_merge(struct io *iop) q_iop = dip_find_exact(dip_get_head(iop->dip, IOP_Q), iop); if (q_iop) io_link(&iop->u.m.m_q, q_iop); + + iostat_merge(iop); } void handle_insert(struct io *iop) @@ -174,6 +176,8 @@ void handle_insert(struct io *iop) io_setup(iop, IOP_I); INIT_LIST_HEAD(&iop->u.i.i_qs_head); dip_add_qs(dip_get_head(iop->dip, IOP_Q), iop); + + iostat_insert(iop); } void handle_complete(struct io *iop) @@ -190,7 +194,7 @@ void handle_complete(struct io *iop) d_iop = dip_find_exact(dip_get_head(iop->dip, IOP_D), iop); if (d_iop) { io_link(&iop->u.c.c_d, d_iop); - + iostat_complete(iop); add_cy(iop); } else @@ -214,6 +218,8 @@ void handle_issue(struct io *iop) dip_add_ms(dip_get_head(iop->dip, IOP_M), iop); seeki_add(iop->dip->seek_handle, iop); + + iostat_issue(iop); } void handle_split(struct io *iop) @@ -310,6 +316,7 @@ void __add_trace(struct io *iop) { n_traces++; + iostat_check_time(iop->t.time); if (verbose && (n_traces % 10000) == 0) { printf("%10lu t, %10lu m %1lu f\r", n_traces, n_io_allocs, n_io_frees); -- 2.25.1