Added S2G times + fixed up -X output to include X2X

Including Q2Q, Q2G, S2G, G2I, Q2M, I2D, M2D, D2C, Q2C.

S2G is part of Q2G, and shows the number of times we had to sleep to
get a request.

Ignored 0-byte I/Os - coming from barrier I/Os...

diff --git a/btt/bt_timeline.c b/btt/bt_timeline.c
index f3483f0c52ffc14248d18d5221e57fac8ab1a81a..7c52ab761471c754dc0ff0c007caf01fb30d3c81 100644 (file)
--- a/btt/bt_timeline.c
+++ b/btt/bt_timeline.c
@@ -25,7 +25,7 @@
 #include <time.h>
 #include "globals.h"
 
-char bt_timeline_version[] = "2.03";
+char bt_timeline_version[] = "2.04";
 
 char *devices, *exes, *input_name, *output_name, *seek_name, *bno_dump_name;
 char *d2c_name, *q2c_name, *per_io_name, *unplug_hist_name;

diff --git a/btt/doc/btt.tex b/btt/doc/btt.tex
index 4adcbbafe7d3115ac55a24f392fb99570c00ea07..646058574fda1c867bda9c82bf77d200ec359335 100644 (file)
--- a/btt/doc/btt.tex
+++ b/btt/doc/btt.tex
@@ -22,7 +22,7 @@
 
 \title{\texttt{btt} User Guide}
 \author{Alan D. Brunelle (Alan.Brunelle@hp.com)}
-\date{12 February 2008}
+\date{9 May 2008}
 
 \begin{document}
 \maketitle
@@ -115,7 +115,10 @@ easier.
 
       This is denoted as \emph{Q2I} time.
 
-      This is also broken down into two component times:
+      This is also broken down into two component times\footnote{On
+      occasion there are also some time spent \emph{sleeping} waiting
+      for a request. That occurs between the Q and G operations. You
+      will see these listed as \texttt{S2G} times.}:
 
         \begin{description}
          \item[Q2G] Time needed to \emph{get} a request (get request
@@ -760,7 +763,7 @@ Device:       rrqm/s   wrqm/s     r/s     w/s    rsec/s    wsec/s
 \newpage\section{\label{sec:cmd-line}Command Line}
 
 \begin{verbatim}
-Usage: btt 2.03
+Usage: btt 2.04
 [ -a               | --seek-absolute ]
 [ -A               | --all-data ]
 [ -B <output name> | --dump-blocknos=<output name> ]
@@ -993,19 +996,38 @@ Sending stats data to bttX.avg
   \texttt{UPG} & Unplug Information:\\
                & IOsPerUnplug IOsPerUnplugTimeout\\\hline
   \texttt{ARQ} & Active Requests at Q Information:\\
-               & AvgReqs@Q\\\hline
+               & AvgReqs@Q\\\hline\hline
+  \texttt{Q2Q}  & Queue-to-Queue times:\\
+  \texttt{Q2G}  & Queue-to-GetRequest times:\\
+  \texttt{S2G}  & Sleep-to-GetRequest times:\\
+  \texttt{G2I}  & GetRequest-to-Insert times:\\
+  \texttt{Q2M}  & Queue-to-Merge times:\\
+  \texttt{I2D}  & Insert-to-Issue times:\\
+  \texttt{M2D}  & Merge-to-Issue times:\\
+  \texttt{D2C}  & Issue-to-Complete times:\\
+  \texttt{Q2C}  & Queue-to-Complete times:\\
+                & MIN AVG MAX N\\\hline
   \end{tabular}
 
   \bigskip
   A sample output file would look like:
 
   \begin{verbatim}
-DMI 8,16 310407 106729 2.908366049 0 182 1024 19504768
-QSK 8,16 310407 167141.958551192 0 0 235753
+Q2Q 0.000000001 0.003511356 9.700000000 309906
+Q2G 0.000000001 0.774586535 805.300000000 106732
+S2G 0.000000001 0.072525952 0.370000000 578
+G2I 0.000000001 0.000001125 0.010000000 106732
+Q2M 0.000000001 0.730763626 751.820000000 204040
+I2D 0.000000001 1.270720538 612.880000000 106948
+M2D 0.000000001 0.992355230 428.930000000 203114
+D2C 0.000000001 0.008681311 137.020000000 307343
+Q2C 0.000000001 1.304370794 805.660000000 308921
+DMI 8,16 309907 106729 2.903681286 8 182 1024 19504768
+QSK 8,16 309907 167200.935561314 0 0 235708
 DSK 8,16 106729 433247.436563633 0 0 33974
-PLG 8,16 40824 382 0.008882101
+PLG 8,16 40824 382 0.008881420
 UPG 8,16 1.993361748 1.866492147
-ARQ 8,16 22.863331046
+ARQ 8,16 12.938165321
   \end{verbatim}
 
 \newpage\section{\label{sec:bno_plot}bno\_plot.py}

diff --git a/btt/globals.h b/btt/globals.h
index 887353d2216a085fd86d9705060d8c05cbd3ec65..1f9571efbb94d607f96edac484314386074de318 100644 (file)
--- a/btt/globals.h
+++ b/btt/globals.h
@@ -55,9 +55,10 @@ enum iop_type {
        IOP_D = 5,
        IOP_C = 6,
        IOP_R = 7,
-       IOP_I = 8
+       IOP_I = 8,
+       IOP_S = 9
 };
-#define N_IOP_TYPES    (IOP_I + 1)
+#define N_IOP_TYPES    (IOP_S + 1)
 
 struct file_info {
        struct file_info *next;
@@ -91,6 +92,7 @@ struct avgs_info {
         struct avg_info q2q;
        struct avg_info q2a;
        struct avg_info q2g;
+       struct avg_info s2g;
        struct avg_info g2i;
        struct avg_info q2m;
        struct avg_info i2d;
@@ -165,6 +167,7 @@ struct io {
        struct p_info *pip;
        void *pdu;
        __u64 bytes_left, g_time, i_time, m_time, d_time, c_time, d_sec, c_sec;
+       __u64 s_time;
        __u32 d_nsec, c_nsec;
 
        struct blk_io_trace t;
@@ -305,6 +308,7 @@ int ready_im(struct io *im_iop, struct io *c_iop);
 void trace_insert(struct io *i_iop);
 void trace_merge(struct io *m_iop);
 void trace_getrq(struct io *g_iop);
+void trace_sleeprq(struct io *s_iop);
 
 /* trace_issue.c */
 void run_issue(struct io *d_iop, struct io *u_iop, struct io *c_iop);

diff --git a/btt/inlines.h b/btt/inlines.h
index 3e7a17e5cbaa59988f4234bcebc563c50d59d758..2af70fb022338687a88b812a45e1bc9d8cb9a1c2 100644 (file)
--- a/btt/inlines.h
+++ b/btt/inlines.h
@@ -219,6 +219,11 @@ static inline void update_q2g(struct io *iop, __u64 g_time)
        UPDATE_AVGS(q2g, iop, iop->pip, g_time);
 }
 
+static inline void update_s2g(struct io *iop, __u64 g_time)
+{
+       UPDATE_AVGS(s2g, iop, iop->pip, g_time);
+}
+
 static inline void unupdate_q2g(struct io *iop, __u64 g_time)
 {
        UNUPDATE_AVGS(q2g, iop, iop->pip, g_time);

diff --git a/btt/output.c b/btt/output.c
index 3de9cce6ed6c6f957ca0cd4808e48dc3b0d74ae7..5526029ff3d9f308ba36198d03873ebbe7252031 100644 (file)
--- a/btt/output.c
+++ b/btt/output.c
@@ -30,6 +30,7 @@ ai_dip_t dip_q2q_avg(struct d_info *dip) { return &dip->avgs.q2q; }
 ai_dip_t dip_q2c_avg(struct d_info *dip) { return &dip->avgs.q2c; }
 ai_dip_t dip_q2a_avg(struct d_info *dip) { return &dip->avgs.q2a; }
 ai_dip_t dip_q2g_avg(struct d_info *dip) { return &dip->avgs.q2g; }
+ai_dip_t dip_s2g_avg(struct d_info *dip) { return &dip->avgs.s2g; }
 ai_dip_t dip_g2i_avg(struct d_info *dip) { return &dip->avgs.g2i; }
 ai_dip_t dip_q2m_avg(struct d_info *dip) { return &dip->avgs.q2m; }
 ai_dip_t dip_i2d_avg(struct d_info *dip) { return &dip->avgs.i2d; }
@@ -44,6 +45,7 @@ ai_pip_t pip_q2q_avg(struct p_info *pip) { return &pip->avgs.q2q; }
 ai_pip_t pip_q2c_avg(struct p_info *pip) { return &pip->avgs.q2c; }
 ai_pip_t pip_q2a_avg(struct p_info *pip) { return &pip->avgs.q2a; }
 ai_pip_t pip_q2g_avg(struct p_info *pip) { return &pip->avgs.q2g; }
+ai_pip_t pip_s2g_avg(struct p_info *pip) { return &pip->avgs.s2g; }
 ai_pip_t pip_g2i_avg(struct p_info *pip) { return &pip->avgs.g2i; }
 ai_pip_t pip_q2m_avg(struct p_info *pip) { return &pip->avgs.q2m; }
 ai_pip_t pip_i2d_avg(struct p_info *pip) { return &pip->avgs.i2d; }
@@ -63,12 +65,19 @@ void output_hdr(FILE *ofp, char *hdr)
        fprintf(ofp, "--------------- ------------- ------------- ------------- -----------\n");
 }
 
-void __output_avg(FILE *ofp, char *hdr, struct avg_info *ap)
+void __output_avg(FILE *ofp, char *hdr, struct avg_info *ap, int do_easy)
 {
        if (ap->n > 0) {
                ap->avg = BIT_TIME(ap->total) / (double)ap->n;
                fprintf(ofp, "%-15s %13.9f %13.9f %13.9f %11d\n", hdr,
                        BIT_TIME(ap->min), ap->avg, BIT_TIME(ap->max), ap->n);
+
+               if (do_easy && easy_parse_avgs) {
+                       fprintf(xavgs_ofp,
+                               "%s %.9lf %.9lf %.9lf %d\n",
+                               hdr, BIT_TIME(ap->min), ap->avg,
+                                               BIT_TIME(ap->max), ap->n);
+               }
        }
 }
 
@@ -114,7 +123,7 @@ void __output_dip_avg(struct d_info *dip, void *arg)
        if (ap->n > 0) {
                char dev_info[15];
                ap->avg = BIT_TIME(ap->total) / (double)ap->n;
-               __output_avg(odap->ofp, make_dev_hdr(dev_info, 15, dip), ap);
+               __output_avg(odap->ofp, make_dev_hdr(dev_info, 15, dip), ap, 0);
        }
 }
 
@@ -533,7 +542,7 @@ void __output_pip_avg(struct p_info *pip, void *arg)
                snprintf(proc_name, 15, pip->name);
 
                ap->avg = BIT_TIME(ap->total) / (double)ap->n;
-               __output_avg(opap->ofp, proc_name, ap);
+               __output_avg(opap->ofp, proc_name, ap, 0);
        }
 }
 
@@ -756,6 +765,7 @@ int output_avgs(FILE *ofp)
                        output_pip_avg(ofp, "Q2Q", pip_q2q_avg);
                        output_pip_avg(ofp, "Q2A", pip_q2a_avg);
                        output_pip_avg(ofp, "Q2G", pip_q2g_avg);
+                       output_pip_avg(ofp, "S2G", pip_s2g_avg);
                        output_pip_avg(ofp, "G2I", pip_g2i_avg);
                        output_pip_avg(ofp, "Q2M", pip_q2m_avg);
                        output_pip_avg(ofp, "I2D", pip_i2d_avg);
@@ -772,6 +782,7 @@ int output_avgs(FILE *ofp)
                output_dip_avg(ofp, "Q2Q", dip_q2q_avg);
                output_dip_avg(ofp, "Q2A", dip_q2a_avg);
                output_dip_avg(ofp, "Q2G", dip_q2g_avg);
+               output_dip_avg(ofp, "S2G", dip_s2g_avg);
                output_dip_avg(ofp, "G2I", dip_g2i_avg);
                output_dip_avg(ofp, "Q2M", dip_q2m_avg);
                output_dip_avg(ofp, "I2D", dip_i2d_avg);
@@ -781,20 +792,21 @@ int output_avgs(FILE *ofp)
 
        output_section_hdr(ofp, "All Devices");
        output_hdr(ofp, "ALL");
-       __output_avg(ofp, "Q2Qdm", &all_avgs.q2q_dm);
-       __output_avg(ofp, "Q2Adm", &all_avgs.q2a_dm);
-       __output_avg(ofp, "Q2Cdm", &all_avgs.q2c_dm);
+       __output_avg(ofp, "Q2Qdm", &all_avgs.q2q_dm, 0);
+       __output_avg(ofp, "Q2Adm", &all_avgs.q2a_dm, 0);
+       __output_avg(ofp, "Q2Cdm", &all_avgs.q2c_dm, 0);
        fprintf(ofp, "\n");
 
-       __output_avg(ofp, "Q2Q", &all_avgs.q2q);
-       __output_avg(ofp, "Q2A", &all_avgs.q2a);
-       __output_avg(ofp, "Q2G", &all_avgs.q2g);
-       __output_avg(ofp, "G2I", &all_avgs.g2i);
-       __output_avg(ofp, "Q2M", &all_avgs.q2m);
-       __output_avg(ofp, "I2D", &all_avgs.i2d);
-       __output_avg(ofp, "M2D", &all_avgs.m2d);
-       __output_avg(ofp, "D2C", &all_avgs.d2c);
-       __output_avg(ofp, "Q2C", &all_avgs.q2c);
+       __output_avg(ofp, "Q2Q", &all_avgs.q2q, 1);
+       __output_avg(ofp, "Q2A", &all_avgs.q2a, 1);
+       __output_avg(ofp, "Q2G", &all_avgs.q2g, 1);
+       __output_avg(ofp, "S2G", &all_avgs.s2g, 1);
+       __output_avg(ofp, "G2I", &all_avgs.g2i, 1);
+       __output_avg(ofp, "Q2M", &all_avgs.q2m, 1);
+       __output_avg(ofp, "I2D", &all_avgs.i2d, 1);
+       __output_avg(ofp, "M2D", &all_avgs.m2d, 1);
+       __output_avg(ofp, "D2C", &all_avgs.d2c, 1);
+       __output_avg(ofp, "Q2C", &all_avgs.q2c, 1);
        fprintf(ofp, "\n");
 
        output_section_hdr(ofp, "Device Overhead");

diff --git a/btt/trace.c b/btt/trace.c
index 39faf76701416c2001d22ec6c3a73749a08598c9..1d9a1c08d28c4ec914948039ec25ea29e7d6648e 100644 (file)
--- a/btt/trace.c
+++ b/btt/trace.c
@@ -47,6 +47,7 @@ static void __add_trace(struct io *iop)
        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;
+       case __BLK_TA_SLEEPRQ:          trace_sleeprq(iop); break;
        default:
                io_release(iop);
                return;

diff --git a/btt/trace_complete.c b/btt/trace_complete.c
index 50f3cfa9410a101eccd25a068b351099ef062088..41bcb7da29ca3c71dcff8656bedecc30721680d6 100644 (file)
--- a/btt/trace_complete.c
+++ b/btt/trace_complete.c
@@ -92,6 +92,9 @@ static void handle_complete(struct io *c_iop)
 
 void trace_complete(struct io *c_iop)
 {
+       if (c_iop->t.bytes == 0)
+               return;
+
        if (io_setup(c_iop, IOP_C))
                handle_complete(c_iop);
 

diff --git a/btt/trace_im.c b/btt/trace_im.c
index b1d1560e8663f197d350f5c6dabef08929241545..49c876ca0250f6bcb1db977c8a46ebeb2f22953c 100644 (file)
--- a/btt/trace_im.c
+++ b/btt/trace_im.c
@@ -22,15 +22,27 @@
 
 static void handle_g(struct io *g_iop)
 {
-       struct io *q_iop = dip_find_sec(g_iop->dip, IOP_Q, g_iop->t.sector);
+       struct io *q_iop;
 
        iostat_getrq(g_iop);
+
+       q_iop = dip_find_sec(g_iop->dip, IOP_Q, g_iop->t.sector);
        if (q_iop) {
                q_iop->g_time = g_iop->t.time;
                update_q2g(q_iop, tdelta(q_iop->t.time, g_iop->t.time));
+               if (q_iop->s_time != 0)
+                       update_s2g(q_iop, tdelta(q_iop->s_time, g_iop->t.time));
        }
 }
 
+static void handle_s(struct io *s_iop)
+{
+       struct io *q_iop = dip_find_sec(s_iop->dip, IOP_Q, s_iop->t.sector);
+
+       if (q_iop)
+               q_iop->s_time = s_iop->t.time;
+}
+
 static void handle_i(struct io *i_iop)
 {
        struct io *q_iop = dip_find_sec(i_iop->dip, IOP_Q, i_iop->t.sector);
@@ -44,9 +56,11 @@ static void handle_i(struct io *i_iop)
 
 static void handle_m(struct io *m_iop)
 {
-       struct io *q_iop = dip_find_sec(m_iop->dip, IOP_Q, m_iop->t.sector);
+       struct io *q_iop;
 
        iostat_merge(m_iop);
+
+       q_iop = dip_find_sec(m_iop->dip, IOP_Q, m_iop->t.sector);
        if (q_iop) {
                q_iop->m_time = m_iop->t.time;
                update_q2m(q_iop, tdelta(q_iop->t.time, m_iop->t.time));
@@ -56,26 +70,38 @@ static void handle_m(struct io *m_iop)
                m_iop->dip->n_act_q--;
 }
 
+void trace_sleeprq(struct io *s_iop)
+{
+       if (s_iop->t.bytes == 0)
+               return;
+       if (io_setup(s_iop, IOP_S))
+               handle_s(s_iop);
+       io_release(s_iop);
+}
+
 void trace_getrq(struct io *g_iop)
 {
+       if (g_iop->t.bytes == 0)
+               return;
        if (io_setup(g_iop, IOP_G))
                handle_g(g_iop);
-
        io_release(g_iop);
 }
 
 void trace_insert(struct io *i_iop)
 {
+       if (i_iop->t.bytes == 0)
+               return;
        if (io_setup(i_iop, IOP_I))
                handle_i(i_iop);
-
        io_release(i_iop);
 }
 
 void trace_merge(struct io *m_iop)
 {
+       if (m_iop->t.bytes == 0)
+               return;
        if (io_setup(m_iop, IOP_M))
                handle_m(m_iop);
-
        io_release(m_iop);
 }

diff --git a/btt/trace_issue.c b/btt/trace_issue.c
index 56e562922db5a865f1e68f7e2d843b7eae0184c3..a18d44d503c6576318711b6f3750b9893a37b366 100644 (file)
--- a/btt/trace_issue.c
+++ b/btt/trace_issue.c
@@ -59,8 +59,12 @@ static void handle_issue(struct io *d_iop)
 
 void trace_issue(struct io *d_iop)
 {
+       if (d_iop->t.bytes == 0)
+               return;
+
        if (io_setup(d_iop, IOP_D))
                handle_issue(d_iop);
+
        io_release(d_iop);
 
 }

diff --git a/btt/trace_queue.c b/btt/trace_queue.c
index 1237f343f0d3c7845412f850d207594577fbfd20..82c5760f536d40f369b0ee19e39827d849b249a1 100644 (file)
--- a/btt/trace_queue.c
+++ b/btt/trace_queue.c
@@ -43,6 +43,9 @@ static void handle_queue(struct io *q_iop)
 
 void trace_queue(struct io *q_iop)
 {
+       if (q_iop->t.bytes == 0)
+               return;
+
        if (io_setup(q_iop, IOP_Q))
                handle_queue(q_iop);
        else