From 3639a11e5e8bbe00662076a3d5161c26621b4947 Mon Sep 17 00:00:00 2001 From: Jens Axboe Date: Fri, 16 Sep 2005 10:10:50 +0200 Subject: [PATCH] [PATCH] Improve unplug logging Extend it to capture whether this was an io based unplug (eg someone doing a wait_on_page() or similar), or of it was a timeout based event). The logging code also forget to turn the unplug payload into on-wire big endian and the parsing pdu offset was wrong. --- blkparse.c | 63 ++++++++++--------- blktrace_api.h | 7 ++- ...rc1-git-G1 => blk-trace-2.6.14-rc1-git-G2} | 52 ++++++++------- 3 files changed, 63 insertions(+), 59 deletions(-) rename kernel/{blk-trace-2.6.14-rc1-git-G1 => blk-trace-2.6.14-rc1-git-G2} (92%) diff --git a/blkparse.c b/blkparse.c index 9c2123a..7924b55 100644 --- a/blkparse.c +++ b/blkparse.c @@ -683,7 +683,7 @@ static char hstring[256]; static char tstring[256]; static inline char *setup_header(struct per_cpu_info *pci, - struct blk_io_trace *t, char act) + struct blk_io_trace *t, char *act) { int w = t->action & BLK_TC_ACT(BLK_TC_WRITE); int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER); @@ -702,16 +702,16 @@ static inline char *setup_header(struct per_cpu_info *pci, rwbs[i] = '\0'; - sprintf(hstring, "%3d,%-3d %2d %8ld %5Lu.%09Lu %5u %c %3s", + sprintf(hstring, "%3d,%-3d %2d %8ld %5Lu.%09Lu %5u %2s %3s", MAJOR(t->device), MINOR(t->device), pci->cpu, - (unsigned long)t->sequence, SECONDS(t->time), + (unsigned long)t->sequence, SECONDS(t->time), NANO_SECONDS(t->time), t->pid, act, rwbs); return hstring; } static void log_complete(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { unsigned long long elapsed = log_track_complete(t); @@ -731,7 +731,7 @@ static void log_complete(struct per_cpu_info *pci, struct blk_io_trace *t, } static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { unsigned long long elapsed = log_track_queue(t); @@ -750,7 +750,7 @@ static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t, } static void log_issue(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { unsigned long long elapsed = log_track_issue(t); @@ -770,7 +770,7 @@ static void log_issue(struct per_cpu_info *pci, struct blk_io_trace *t, } static void log_merge(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { log_track_merge(t); @@ -780,14 +780,14 @@ static void log_merge(struct per_cpu_info *pci, struct blk_io_trace *t, } static void log_action(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { sprintf(tstring,"%s [%s]\n", setup_header(pci, t, act), t->comm); output(pci, tstring); } static void log_generic(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act), (unsigned long long)t->sector, t->bytes >> 9, t->comm); @@ -795,20 +795,20 @@ static void log_generic(struct per_cpu_info *pci, struct blk_io_trace *t, } static int log_unplug(struct per_cpu_info *pci, struct blk_io_trace *t, - char act) + char *act) { __u64 *depth; int len; len = sprintf(tstring,"%s ", setup_header(pci, t, act)); - depth = (__u64 *) t + sizeof(*t); + depth = (__u64 *) ((char *) t + sizeof(*t)); sprintf(tstring + len, "%u\n", (unsigned int) be64_to_cpu(*depth)); output(pci, tstring); return 0; } -static int log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char act) +static int log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char *act) { unsigned char *buf; int i; @@ -822,7 +822,7 @@ static int log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char act) output(pci, tstring); } - if (act == 'C') { + if (act[0] == 'C') { sprintf(tstring,"[%d]\n", t->error); output(pci, tstring); } else { @@ -838,22 +838,22 @@ static int dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci) switch (t->action & 0xffff) { case __BLK_TA_QUEUE: - log_generic(pci, t, 'Q'); + log_generic(pci, t, "Q"); break; case __BLK_TA_GETRQ: - log_generic(pci, t, 'G'); + log_generic(pci, t, "G"); break; case __BLK_TA_SLEEPRQ: - log_generic(pci, t, 'S'); + log_generic(pci, t, "S"); break; case __BLK_TA_REQUEUE: - log_generic(pci, t, 'R'); + log_generic(pci, t, "R"); break; case __BLK_TA_ISSUE: - ret = log_pc(pci, t, 'D'); + ret = log_pc(pci, t, "D"); break; case __BLK_TA_COMPLETE: - log_pc(pci, t, 'C'); + log_pc(pci, t, "C"); break; default: fprintf(stderr, "Bad pc action %x\n", t->action); @@ -872,40 +872,43 @@ static void dump_trace_fs(struct blk_io_trace *t, struct per_cpu_info *pci) switch (act) { case __BLK_TA_QUEUE: account_q(t, pci, w); - log_queue(pci, t, 'Q'); + log_queue(pci, t, "Q"); break; case __BLK_TA_BACKMERGE: account_m(t, pci, w); - log_merge(pci, t, 'M'); + log_merge(pci, t, "M"); break; case __BLK_TA_FRONTMERGE: account_m(t, pci, w); - log_merge(pci, t, 'F'); + log_merge(pci, t, "F"); break; case __BLK_TA_GETRQ: log_track_getrq(t); - log_generic(pci, t, 'G'); + log_generic(pci, t, "G"); break; case __BLK_TA_SLEEPRQ: - log_generic(pci, t, 'S'); + log_generic(pci, t, "S"); break; case __BLK_TA_REQUEUE: account_c(t, pci, w, -t->bytes); - log_queue(pci, t, 'R'); + log_queue(pci, t, "R"); break; case __BLK_TA_ISSUE: account_i(t, pci, w); - log_issue(pci, t, 'D'); + log_issue(pci, t, "D"); break; case __BLK_TA_COMPLETE: account_c(t, pci, w, t->bytes); - log_complete(pci, t, 'C'); + log_complete(pci, t, "C"); break; case __BLK_TA_PLUG: - log_action(pci, t, 'P'); + log_action(pci, t, "P"); break; - case __BLK_TA_UNPLUG: - log_unplug(pci, t, 'U'); + case __BLK_TA_UNPLUG_IO: + log_unplug(pci, t, "U"); + break; + case __BLK_TA_UNPLUG_TIMER: + log_unplug(pci, t, "UT"); break; default: fprintf(stderr, "Bad fs action %x\n", t->action); diff --git a/blktrace_api.h b/blktrace_api.h index c716d66..a1eb4c8 100644 --- a/blktrace_api.h +++ b/blktrace_api.h @@ -37,7 +37,9 @@ enum { __BLK_TA_ISSUE, /* sent to driver */ __BLK_TA_COMPLETE, /* completed by driver */ __BLK_TA_PLUG, /* queue was plugged */ - __BLK_TA_UNPLUG, /* queue was unplugged */ + __BLK_TA_UNPLUG_IO, /* queue was unplugged by io */ + __BLK_TA_UNPLUG_TIMER, /* queue was unplugged by timer */ + __BLK_TA_IOSCHED, /* some io scheduler defined action */ }; /* @@ -52,7 +54,8 @@ enum { #define BLK_TA_ISSUE (__BLK_TA_ISSUE | BLK_TC_ACT(BLK_TC_ISSUE)) #define BLK_TA_COMPLETE (__BLK_TA_COMPLETE| BLK_TC_ACT(BLK_TC_COMPLETE)) #define BLK_TA_PLUG (__BLK_TA_PLUG | BLK_TC_ACT(BLK_TC_QUEUE)) -#define BLK_TA_UNPLUG (__BLK_TA_UNPLUG | BLK_TC_ACT(BLK_TC_QUEUE)) +#define BLK_TA_UNPLUG_IO (__BLK_TA_UNPLUG_IO | BLK_TC_ACT(BLK_TC_QUEUE)) +#define BLK_TA_UNPLUG_TIMER (__BLK_TA_UNPLUG_TIMER | BLK_TC_ACT(BLK_TC_QUEUE)) #define BLK_IO_TRACE_MAGIC 0x65617400 #define BLK_IO_TRACE_VERSION 0x05 diff --git a/kernel/blk-trace-2.6.14-rc1-git-G1 b/kernel/blk-trace-2.6.14-rc1-git-G2 similarity index 92% rename from kernel/blk-trace-2.6.14-rc1-git-G1 rename to kernel/blk-trace-2.6.14-rc1-git-G2 index c76c64b..f7cfc79 100644 --- a/kernel/blk-trace-2.6.14-rc1-git-G1 +++ b/kernel/blk-trace-2.6.14-rc1-git-G2 @@ -100,36 +100,31 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c } EXPORT_SYMBOL(blk_plug_device); -@@ -1487,14 +1490,27 @@ static void blk_backing_dev_unplug(struc +@@ -1487,8 +1490,12 @@ static void blk_backing_dev_unplug(struc /* * devices don't necessarily have an ->unplug_fn defined */ - if (q->unplug_fn) + if (q->unplug_fn) { -+ if (test_bit(QUEUE_FLAG_PLUGGED, &q->queue_flags)) { -+ int nrq = q->rq.count[READ] + q->rq.count[WRITE]; -+ -+ blk_add_trace_pdu_int(q, BLK_TA_UNPLUG, nrq); -+ } ++ int nrq = q->rq.count[READ] + q->rq.count[WRITE]; + ++ blk_add_trace_pdu_int(q, BLK_TA_UNPLUG_IO, nrq); q->unplug_fn(q); + } } static void blk_unplug_work(void *data) +@@ -1501,7 +1508,9 @@ static void blk_unplug_work(void *data) + static void blk_unplug_timeout(unsigned long data) { - request_queue_t *q = data; + request_queue_t *q = (request_queue_t *)data; ++ int nrq = q->rq.count[READ] + q->rq.count[WRITE]; -+ if (test_bit(QUEUE_FLAG_PLUGGED, &q->queue_flags)) { -+ int nrq = q->rq.count[READ] + q->rq.count[WRITE]; -+ -+ blk_add_trace_pdu_int(q, BLK_TA_UNPLUG, nrq); -+ } -+ - q->unplug_fn(q); ++ blk_add_trace_pdu_int(q, BLK_TA_UNPLUG_TIMER, nrq); + kblockd_schedule_work(&q->unplug_work); } -@@ -1624,6 +1640,11 @@ void blk_cleanup_queue(request_queue_t * +@@ -1624,6 +1633,11 @@ void blk_cleanup_queue(request_queue_t * if (q->queue_tags) __blk_queue_free_tags(q); @@ -141,7 +136,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c blk_queue_ordered(q, QUEUE_ORDERED_NONE); kmem_cache_free(requestq_cachep, q); -@@ -1970,6 +1991,8 @@ rq_starved: +@@ -1970,6 +1984,8 @@ rq_starved: rq_init(q, rq); rq->rl = rl; @@ -150,7 +145,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c out: return rq; } -@@ -1998,6 +2021,8 @@ static struct request *get_request_wait( +@@ -1998,6 +2014,8 @@ static struct request *get_request_wait( if (!rq) { struct io_context *ioc; @@ -159,7 +154,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c __generic_unplug_device(q); spin_unlock_irq(q->queue_lock); io_schedule(); -@@ -2051,6 +2076,8 @@ EXPORT_SYMBOL(blk_get_request); +@@ -2051,6 +2069,8 @@ EXPORT_SYMBOL(blk_get_request); */ void blk_requeue_request(request_queue_t *q, struct request *rq) { @@ -168,7 +163,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c if (blk_rq_tagged(rq)) blk_queue_end_tag(q, rq); -@@ -2714,6 +2741,8 @@ static int __make_request(request_queue_ +@@ -2714,6 +2734,8 @@ static int __make_request(request_queue_ if (!q->back_merge_fn(q, req, bio)) break; @@ -177,7 +172,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c req->biotail->bi_next = bio; req->biotail = bio; req->nr_sectors = req->hard_nr_sectors += nr_sectors; -@@ -2729,6 +2758,8 @@ static int __make_request(request_queue_ +@@ -2729,6 +2751,8 @@ static int __make_request(request_queue_ if (!q->front_merge_fn(q, req, bio)) break; @@ -186,7 +181,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c bio->bi_next = req->bio; req->bio = bio; -@@ -3030,6 +3061,10 @@ end_io: +@@ -3030,6 +3054,10 @@ end_io: blk_partition_remap(bio); ret = q->make_request_fn(q, bio); @@ -197,7 +192,7 @@ diff --git a/drivers/block/ll_rw_blk.c b/drivers/block/ll_rw_blk.c } while (ret); } -@@ -3148,6 +3183,8 @@ static int __end_that_request_first(stru +@@ -3148,6 +3176,8 @@ static int __end_that_request_first(stru int total_bytes, bio_nbytes, error, next_idx = 0; struct bio *bio; @@ -466,8 +461,8 @@ diff --git a/include/linux/fs.h b/include/linux/fs.h +module_init(blk_trace_init); + --- /dev/null 2005-09-09 21:24:12.000000000 +0200 -+++ linux-2.6/include/linux/blktrace.h 2005-09-15 14:13:12.000000000 +0200 -@@ -0,0 +1,169 @@ ++++ linux-2.6/include/linux/blktrace.h 2005-09-16 09:32:03.000000000 +0200 +@@ -0,0 +1,172 @@ +#ifndef BLKTRACE_H +#define BLKTRACE_H + @@ -509,7 +504,9 @@ diff --git a/include/linux/fs.h b/include/linux/fs.h + __BLK_TA_ISSUE, /* sent to driver */ + __BLK_TA_COMPLETE, /* completed by driver */ + __BLK_TA_PLUG, /* queue was plugged */ -+ __BLK_TA_UNPLUG, /* queue was unplugged */ ++ __BLK_TA_UNPLUG_IO, /* queue was unplugged by io */ ++ __BLK_TA_UNPLUG_TIMER, /* queue was unplugged by timer */ ++ __BLK_TA_IOSCHED, /* some io scheduler defined action */ +}; + +/* @@ -524,7 +521,8 @@ diff --git a/include/linux/fs.h b/include/linux/fs.h +#define BLK_TA_ISSUE (__BLK_TA_ISSUE | BLK_TC_ACT(BLK_TC_ISSUE)) +#define BLK_TA_COMPLETE (__BLK_TA_COMPLETE| BLK_TC_ACT(BLK_TC_COMPLETE)) +#define BLK_TA_PLUG (__BLK_TA_PLUG | BLK_TC_ACT(BLK_TC_QUEUE)) -+#define BLK_TA_UNPLUG (__BLK_TA_UNPLUG | BLK_TC_ACT(BLK_TC_QUEUE)) ++#define BLK_TA_UNPLUG_IO (__BLK_TA_UNPLUG_IO | BLK_TC_ACT(BLK_TC_QUEUE)) ++#define BLK_TA_UNPLUG_TIMER (__BLK_TA_UNPLUG_TIMER | BLK_TC_ACT(BLK_TC_QUEUE)) + +#define BLK_IO_TRACE_MAGIC 0x65617400 +#define BLK_IO_TRACE_VERSION 0x05 @@ -618,7 +616,7 @@ diff --git a/include/linux/fs.h b/include/linux/fs.h + unsigned int pdu) +{ + struct blk_trace *bt = q->blk_trace; -+ u64 rpdu = pdu; ++ u64 rpdu = cpu_to_be64(pdu); + + if (likely(!bt)) + return; -- 2.25.1