[PATCH] Add in measuring of Plug and Unplug traces.

Added in the display of plug information on a per-device basis.

% Time Q Plugged: Percent of the total time during which the queue
                  was plugged

==================== Plug Information ====================

       DEV |    # Plugs # Timer Us  | % Time Q Plugged
---------- | ---------- ----------  | ----------------
 ( 68, 64) |        833(         0) |   0.36%

Signed-off-by: Alan D. Brunelle <Alan.Brunelle@hp.com>
Signed-off-by: Jens Axboe <jens.axboe@oracle.com>

diff --git a/btt/Makefile b/btt/Makefile
index e1696518a0a8385d5da6a4878a299d0b0b5ce82d..98ce1b472aa34a1d9e66c15dd7551b98a618ad54 100644 (file)
--- a/btt/Makefile
+++ b/btt/Makefile
@@ -9,7 +9,7 @@ LIBS    = $(PLIBS) $(ELIBS)
 OBJS   = args.o bt_timeline.o devmap.o devs.o dip_rb.o iostat.o latency.o \
          misc.o output.o proc.o seek.o trace.o trace_complete.o trace_im.o \
          trace_issue.o trace_queue.o trace_remap.o trace_requeue.o rbtree.o \
-         mmap.o
+         mmap.o trace_plug.o
 
 all: depend $(PROGS)
 

diff --git a/btt/devs.c b/btt/devs.c
index 465f44dfb7c1248db803de57e791ccb90b4cb9c5..f2b09d2083cca5d173bab69c900c641b688f0eff 100644 (file)
--- a/btt/devs.c
+++ b/btt/devs.c
@@ -111,6 +111,7 @@ struct d_info *dip_add(__u32 device, struct io *iop)
                latency_init(dip);
                list_add_tail(&dip->hash_head, &dev_heads[DEV_HASH(device)]);
                list_add_tail(&dip->all_head, &all_devs);
+               dip->start_time = BIT_TIME(iop->t.time);
                n_devs++;
        }
 
@@ -119,6 +120,8 @@ struct d_info *dip_add(__u32 device, struct io *iop)
        if (iop->linked) 
                rb_tree_size++;
 #endif
+
+       dip->end_time = BIT_TIME(iop->t.time);
        return dip;
 }
 
@@ -183,3 +186,26 @@ void dip_foreach_out(void (*func)(struct d_info *, void *), void *arg)
                }
        }
 }
+
+void dip_plug(__u32 dev, double cur_time)
+{
+       struct d_info *dip = __dip_find(dev);
+
+       if (!dip || dip->is_plugged) return;
+
+       dip->is_plugged = 1;
+       dip->last_plug = cur_time;
+}
+
+void dip_unplug(__u32 dev, double cur_time, int is_timer)
+{
+       struct d_info *dip = __dip_find(dev);
+
+       if (!dip || !dip->is_plugged) return;
+
+       dip->nplugs++;
+       if (is_timer) dip->n_timer_unplugs++;
+
+       dip->plugged_time += (cur_time - dip->last_plug);
+       dip->is_plugged = 0;
+}

diff --git a/btt/globals.h b/btt/globals.h
index 2aea4dac1299223a87a102b903e0b4451dae612a..b47e9f52fdd9f210b70365a289159da8c16b01ed 100644 (file)
--- a/btt/globals.h
+++ b/btt/globals.h
@@ -155,6 +155,9 @@ struct d_info {
        struct stats stats, all_stats;
        __u64 last_q, n_ds;
        __u32 device;
+
+       int is_plugged, nplugs, n_timer_unplugs;
+       double start_time, last_plug, plugged_time, end_time;
 };
 
 struct io {
@@ -216,6 +219,8 @@ void dip_foreach(struct io *iop, enum iop_type type,
                 void (*fnc)(struct io *iop, struct io *this), int rm_after);
 struct io *dip_find_sec(struct d_info *dip, enum iop_type type, __u64 sec);
 void dip_foreach_out(void (*func)(struct d_info *, void *), void *arg);
+void dip_plug(__u32 dev, double cur_time);
+void dip_unplug(__u32 dev, double cur_time, int is_timer);
 
 /* dip_rb.c */
 int rb_insert(struct rb_root *root, struct io *iop);
@@ -295,6 +300,11 @@ void run_unissue(struct io *d_iop, struct list_head *rmhd);
 int ready_issue(struct io *d_iop, struct io *c_iop);
 void trace_issue(struct io *d_iop);
 
+/* trace_plug.c */
+void trace_plug(struct io *p_iop);
+void trace_unplug_io(struct io *u_iop);
+void trace_unplug_timer(struct io *u_iop);
+
 /* trace_queue.c */
 void run_queue(struct io *q_iop, struct io *c_iop, struct list_head *rmhd);
 int ready_queue(struct io *q_iop, struct io *c_iop);

diff --git a/btt/output.c b/btt/output.c
index 528e3e26dd5c8690a4bc8ab9114495c229136fb5..d85937cf1abda3c5afb7da2f551327a396ec83b0 100644 (file)
--- a/btt/output.c
+++ b/btt/output.c
@@ -433,6 +433,30 @@ void output_pip_avgs(FILE *ofp)
        fprintf(ofp, "\n");
 }
 
+void __dip_output_plug(struct d_info *dip, void *arg)
+{
+       char dev_info[15];
+       FILE *ofp = arg;
+       double delta;
+
+       if (dip->is_plugged) dip_unplug(dip->device, dip->end_time, 0);
+
+       fprintf(ofp, "%10s | %10s %10s  | %s\n", 
+               "DEV", "# Plugs", "# Timer Us", "% Time Q Plugged");
+       fprintf(ofp, "---------- | ---------- ----------  | ----------------\n");
+       delta = dip->end_time - dip->start_time;
+       fprintf(ofp, "%10s | %10d(%10d) | %6.2lf%%\n", 
+               make_dev_hdr(dev_info, 15, dip), 
+               dip->nplugs, dip->n_timer_unplugs, 
+               100.0 * ((dip->plugged_time / delta) / delta));
+}
+
+void output_plug_info(FILE *ofp)
+{
+       dip_foreach_out(__dip_output_plug, ofp);
+       fprintf(ofp, "\n");
+}
+
 int output_avgs(FILE *ofp)
 {
        if (exes == NULL || *exes != '\0') {
@@ -461,6 +485,10 @@ int output_avgs(FILE *ofp)
        __output_avg(ofp, "I2D", &all_avgs.i2d);
        __output_avg(ofp, "D2C", &all_avgs.d2c);
        __output_avg(ofp, "Q2C", &all_avgs.q2c);
+       fprintf(ofp, "\n");
+
+       output_section_hdr(ofp, "Device Overhead");
+       output_dip_prep_ohead(ofp);
 
        if (exes == NULL || *exes != '\0') {
                output_section_hdr(ofp, "Per Process (avgs)");
@@ -473,12 +501,12 @@ int output_avgs(FILE *ofp)
        output_section_hdr(ofp, "Device Merge Information");
        output_dip_merge_ratio(ofp);
 
-       output_section_hdr(ofp, "Device Overhead");
-       output_dip_prep_ohead(ofp);
-
        output_section_hdr(ofp, "Device Seek Information");
        output_dip_seek_info(ofp);
 
+       output_section_hdr(ofp, "Plug Information");
+       output_plug_info(ofp);
+
        return 0;
 }
 

diff --git a/btt/trace.c b/btt/trace.c
index 8474d0d7676a1e0c57fdf27d8109671d67879e86..e1925947bd0bf661a2234990139875230f6fdd73 100644 (file)
--- a/btt/trace.c
+++ b/btt/trace.c
@@ -105,6 +105,9 @@ static void __add_trace(struct io *iop)
        case __BLK_TA_REQUEUE:          trace_requeue(iop); break;
        case __BLK_TA_ISSUE:            trace_issue(iop); break;
        case __BLK_TA_COMPLETE:         trace_complete(iop); break;
+       case __BLK_TA_PLUG:             trace_plug(iop); break;
+       case __BLK_TA_UNPLUG_IO:        trace_unplug_io(iop); break;
+       case __BLK_TA_UNPLUG_TIMER:     trace_unplug_timer(iop); break;
        default:                        
                io_release(iop); 
                return;

diff --git a/btt/trace_plug.c b/btt/trace_plug.c
new file mode 100644 (file)
index 0000000..6ce3d56
--- /dev/null
+++ b/btt/trace_plug.c
@@ -0,0 +1,43 @@
+/*
+ * blktrace output analysis: generate a timeline & gather statistics
+ *
+ * Copyright (C) 2007 Alan D. Brunelle <Alan.Brunelle@hp.com>
+ *
+ *  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 "globals.h"
+
+static inline void trace_unplug(struct io *u_iop, int is_timer)
+{
+       dip_unplug(u_iop->t.device, BIT_TIME(u_iop->t.time), is_timer);
+       io_release(u_iop);
+}
+
+void trace_unplug_io(struct io *u_iop)
+{
+       trace_unplug(u_iop, 0);
+}
+
+void trace_unplug_timer(struct io *u_iop)
+{
+       trace_unplug(u_iop, 0);
+}
+
+void trace_plug(struct io *p_iop)
+{
+       dip_plug(p_iop->t.device, BIT_TIME(p_iop->t.time));
+       io_release(p_iop);
+}