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...

10 files changed, 111 insertions, 31 deletions

diff --git a/btt/bt_timeline.c b/btt/bt_timeline.c
index f3483f0..7c52ab7 100644
--- 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 4adcbba..6460585 100644
--- 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 887353d..1f9571e 100644
--- 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 3e7a17e..2af70fb 100644
--- 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 3de9cce..5526029 100644
--- 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 39faf76..1d9a1c0 100644
--- 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 50f3cfa..41bcb7d 100644
--- 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 b1d1560..49c876c 100644
--- 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 56e5629..a18d44d 100644
--- 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 1237f34..82c5760 100644
--- 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