iowatcher: Add initial support for flash tracing

This is incomplete, but it will catch messages from
the flash driver to find the actual chip an IO
was sent to.

Signed-off-by: Chris Mason <chris.mason@fusionio.com>

6 files changed, 180 insertions, 42 deletions

diff --git a/iowatcher/blkparse.c b/iowatcher/blkparse.c
index d254811..abdacb5 100644
--- a/iowatcher/blkparse.c
+++ b/iowatcher/blkparse.c
@@ -300,6 +300,23 @@ void first_record(struct trace *trace)
 	trace->io = (struct blk_io_trace *)trace->cur;
 }
 
+int is_io_event(struct blk_io_trace *test)
+{
+	char *message;
+	if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
+		return 1;
+	if (test->action == BLK_TN_MESSAGE) {
+		int len = test->pdu_len;
+		if (len < 3)
+			return 0;
+		message = (char *)(test + 1);
+		if (strncmp(message, "fio ", 4) == 0) {
+			return 1;
+		}
+	}
+	return 0;
+}
+
 u64 find_last_time(struct trace *trace)
 {
 	char *p = trace->start + trace->len;
@@ -312,8 +329,7 @@ u64 find_last_time(struct trace *trace)
 	p -= sizeof(*trace->io);
 	while (p >= trace->start) {
 		test = (struct blk_io_trace *)p;
-		if (CHECK_MAGIC(test) &&
-		   !(test->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
+		if (CHECK_MAGIC(test) && is_io_event(test)) {
 			u64 offset = p - trace->start;
 			if (offset + sizeof(*test) + test->pdu_len == trace->len) {
 				return test->time;
@@ -329,7 +345,7 @@ u64 find_last_time(struct trace *trace)
 	/* searching backwards didn't work out, we'll have to scan the file */
 	first_record(trace);
 	while (1) {
-		if (!(trace->io->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
+		if (is_io_event(trace->io))
 			found = trace->io->time;
 		if (next_record(trace))
 			break;
@@ -338,10 +354,71 @@ u64 find_last_time(struct trace *trace)
 	return found;
 }
 
-u64 find_highest_offset(struct trace *trace)
+int parse_fio_bank_message(struct trace *trace, u64 *bank_ret, u64 *offset_ret,
+			   u64 *num_banks_ret)
+{
+	char *s;
+	char *next;
+	char *message;
+	struct blk_io_trace *test = trace->io;
+	int len = test->pdu_len;
+	u64 bank;
+	u64 offset;
+	u64 num_banks;
+
+	if (!(test->action & BLK_TC_ACT(BLK_TC_NOTIFY)))
+		return -1;
+	if (test->action != BLK_TN_MESSAGE)
+		return -1;
+
+	/* the message is fio rw bank offset num_banks */
+	if (len < 3)
+		return -1;
+	message = (char *)(test + 1);
+	if (strncmp(message, "fio r ", 6) != 0)
+		return -1;
+
+	message = strndup(message, len);
+	s = strchr(message, ' ');
+	if (!s)
+		goto out;
+	s++;
+	s = strchr(s, ' ');
+	if (!s)
+		goto out;
+
+	bank = strtoll(s, &next, 10);
+	if (s == next)
+		goto out;
+	s = next;
+
+	offset = strtoll(s, &next, 10);
+	if (s == next)
+		goto out;
+	s = next;
+
+	num_banks = strtoll(s, &next, 10);
+	if (s == next)
+		goto out;
+
+	*bank_ret = bank;
+	*offset_ret = offset;
+	*num_banks_ret = num_banks;
+
+	return 0;
+out:
+	free(message);
+	return -1;
+}
+
+void find_highest_offset(struct trace *trace, u64 *max_ret, u64 *max_bank_ret,
+			 u64 *max_offset_ret)
 {
 	u64 found = 0;
 	u64 max = 0;
+	u64 max_bank = 0;
+	u64 max_bank_offset = 0;
+	u64 num_banks = 0;
 	first_record(trace);
 	while (1) {
 		if (!(trace->io->action & BLK_TC_ACT(BLK_TC_NOTIFY))) {
@@ -351,12 +428,24 @@ u64 find_highest_offset(struct trace *trace)
 			if (max < found) {
 				max = found;
 			}
+		} else {
+			u64 bank;
+			u64 offset;
+			if (!parse_fio_bank_message(trace, &bank,
+						    &offset, &num_banks)) {
+				if (bank > max_bank)
+					max_bank = bank;
+				if (offset > max_bank_offset)
+					max_bank_offset = offset;
+			}
 		}
 		if (next_record(trace))
 			break;
 	}
 	first_record(trace);
-	return max;
+	*max_ret = max;
+	*max_bank_ret = max_bank;
+	*max_offset_ret = max_bank_offset;
 }
 
 int filter_outliers(struct trace *trace, u64 max_offset,
diff --git a/iowatcher/blkparse.h b/iowatcher/blkparse.h
index ff14191..a78a8b7 100644
--- a/iowatcher/blkparse.h
+++ b/iowatcher/blkparse.h
@@ -63,10 +63,10 @@ static inline unsigned int MINOR(unsigned int dev)
 void init_io_hash_table(void);
 struct trace *open_trace(char *filename);
 u64 find_last_time(struct trace *trace);
-u64 find_highest_offset(struct trace *trace);
+void find_highest_offset(struct trace *trace, u64 *max_ret, u64 *max_bank_ret,
+			 u64 *max_offset_ret);
 int filter_outliers(struct trace *trace, u64 max_offset,
 		    u64 *yzoom_min, u64 *yzoom_max);
-
 void add_iop(struct trace *trace, struct graph_line_data *gld);
 void check_record(struct trace *trace);
 void add_completed_io(struct trace *trace,
diff --git a/iowatcher/main.c b/iowatcher/main.c
index 9eb7f3b..22c0bb6 100644
--- a/iowatcher/main.c
+++ b/iowatcher/main.c
@@ -285,6 +285,8 @@ static void read_traces(void)
 	u64 last_time;
 	u64 ymin;
 	u64 ymax;
+	u64 max_bank;
+	u64 max_bank_offset;
 
 	list_for_each_entry(tf, &all_traces, list) {
 		trace = open_trace(tf->filename);
@@ -295,8 +297,8 @@ static void read_traces(void)
 		tf->trace = trace;
 		tf->seconds = SECONDS(last_time);
 		tf->stop_seconds = SECONDS(last_time);
-		tf->max_offset = find_highest_offset(trace);
-
+		find_highest_offset(trace, &tf->max_offset, &max_bank,
+				    &max_bank_offset);
 		filter_outliers(trace, tf->max_offset, &ymin, &ymax);
 		tf->max_offset = ymax;
 
@@ -526,9 +528,6 @@ static void __plot_io(struct plot *plot, int seconds, u64 max_offset)
 {
 	struct trace_file *tf;
 
-	if (active_graphs[IO_GRAPH_INDEX] == 0)
-		return;
-
 	setup_axis(plot);
 
 	svg_alloc_legend(plot, num_traces * 2);
@@ -559,8 +558,10 @@ static void __plot_io(struct plot *plot, int seconds, u64 max_offset)
 
 static void plot_io(struct plot *plot, int seconds, u64 max_offset)
 {
-	plot->add_xlabel = last_active_graph == IO_GRAPH_INDEX;
+	if (active_graphs[IO_GRAPH_INDEX] == 0)
+		return;
 
+	plot->add_xlabel = last_active_graph == IO_GRAPH_INDEX;
 	__plot_io(plot, seconds, max_offset);
 	close_plot(plot);
 }
@@ -572,9 +573,6 @@ static void __plot_tput(struct plot *plot, int seconds)
 	char line[128];
 	u64 max = 0;
 
-	if (active_graphs[TPUT_GRAPH_INDEX] == 0)
-		return;
-
 	if (num_traces > 1)
 		svg_alloc_legend(plot, num_traces);
 	list_for_each_entry(tf, &all_traces, list) {
@@ -596,7 +594,7 @@ static void __plot_tput(struct plot *plot, int seconds)
 	set_xticks(plot, 9, 0, seconds);
 
 	list_for_each_entry(tf, &all_traces, list) {
-		svg_line_graph(plot, tf->tput_gld, tf->read_color);
+		svg_line_graph(plot, tf->tput_gld, tf->read_color, 0, 0);
 		if (num_traces > 1)
 			svg_add_legend(plot, tf->label, "", tf->read_color);
 	}
@@ -609,6 +607,9 @@ static void __plot_tput(struct plot *plot, int seconds)
 
 static void plot_tput(struct plot *plot, int seconds)
 {
+	if (active_graphs[TPUT_GRAPH_INDEX] == 0)
+		return;
+
 	plot->add_xlabel = last_active_graph == TPUT_GRAPH_INDEX;
 	__plot_tput(plot, seconds);
 	close_plot(plot);
@@ -728,7 +729,6 @@ static void plot_cpu(struct plot *plot, int seconds, char *label,
 		     int active_index, int gld_index)
 {
 	struct trace_file *tf;
-	char line[128];
 	int max = 0;
 	int i;
 	int gld_i;
@@ -768,11 +768,14 @@ static void plot_cpu(struct plot *plot, int seconds, char *label,
 	cpu_color_index = 0;
 	list_for_each_entry(tf, &all_traces, list) {
 		for (i = 0; i < tf->mpstat_gld[0]->stop_seconds; i++) {
-			avg += tf->mpstat_gld[gld_index]->data[i].sum;
+			if (tf->mpstat_gld[gld_index]->data[i].count) {
+				avg += (tf->mpstat_gld[gld_index]->data[i].sum /
+					tf->mpstat_gld[gld_index]->data[i].count);
+			}
 		}
 		avg /= tf->mpstat_gld[gld_index]->stop_seconds;
 		color = pick_cpu_color();
-		svg_line_graph(plot, tf->mpstat_gld[0], color);
+		svg_line_graph(plot, tf->mpstat_gld[0], color, 0, 0);
 		svg_add_legend(plot, tf->label, " avg", color);
 
 		for (i = 1; i < tf->trace->mpstat_num_cpus + 1; i++) {
@@ -780,16 +783,23 @@ static void plot_cpu(struct plot *plot, int seconds, char *label,
 			double this_avg = 0;
 
 			for (gld_i = 0; gld_i < gld->stop_seconds; gld_i++)
-				this_avg += gld->data[i].sum;
+				this_avg += gld->data[i].sum /
+					gld->data[i].count;;
 
 			this_avg /= gld->stop_seconds;
 
 			for (gld_i = 0; gld_i < gld->stop_seconds; gld_i++) {
-				if (this_avg > avg + 30 ||
-				    gld->data[gld_i].sum > 95) {
+				double val;
+
+				if (gld->data[gld_i].count == 0)
+					continue;
+				val = (double)gld->data[gld_i].sum /
+					gld->data[gld_i].count;
+
+				if (this_avg > avg + 30 || val > 95) {
 					color = pick_cpu_color();
-					svg_line_graph(plot, gld, color);
-					snprintf(line, 128, " CPU %d\n", i - 1);
+					svg_line_graph(plot, gld, color, avg + 30, 95);
+					snprintf(line, line_len, " CPU %d\n", i - 1);
 					svg_add_legend(plot, tf->label, line, color);
 					plotted++;
 					break;
@@ -802,10 +812,8 @@ static void plot_cpu(struct plot *plot, int seconds, char *label,
 	if (plot->add_xlabel)
 		set_xlabel(plot, "Time (seconds)");
 
-	if (plot->legend_index <= 8)
-		svg_write_legend(plot);
-	else
-		svg_free_legend(plot);
+	svg_write_legend(plot);
+	svg_free_legend(plot);
 	close_plot(plot);
 }
 
@@ -841,7 +849,7 @@ static void plot_latency(struct plot *plot, int seconds)
 	set_xticks(plot, 9, 0, seconds);
 
 	list_for_each_entry(tf, &all_traces, list) {
-		svg_line_graph(plot, tf->latency_gld, tf->read_color);
+		svg_line_graph(plot, tf->latency_gld, tf->read_color, 0, 0);
 		if (num_traces > 1)
 			svg_add_legend(plot, tf->label, "", tf->read_color);
 	}
@@ -873,7 +881,7 @@ static void plot_queue_depth(struct plot *plot, int seconds)
 	set_xticks(plot, 9, 0, seconds);
 
 	list_for_each_entry(tf, &all_traces, list) {
-		svg_line_graph(plot, tf->queue_depth_gld, tf->read_color);
+		svg_line_graph(plot, tf->queue_depth_gld, tf->read_color, 0, 0);
 		if (num_traces > 1)
 			svg_add_legend(plot, tf->label, "", tf->read_color);
 	}
@@ -918,7 +926,7 @@ static void plot_iops(struct plot *plot, int seconds)
 	set_xticks(plot, 9, 0, seconds);
 
 	list_for_each_entry(tf, &all_traces, list) {
-		svg_line_graph(plot, tf->iop_gld, tf->read_color);
+		svg_line_graph(plot, tf->iop_gld, tf->read_color, 0, 0);
 		if (num_traces > 1)
 			svg_add_legend(plot, tf->label, "", tf->read_color);
 	}
diff --git a/iowatcher/plot.c b/iowatcher/plot.c
index 7f30f77..fac59bd 100644
--- a/iowatcher/plot.c
+++ b/iowatcher/plot.c
@@ -679,10 +679,11 @@ void scale_line_graph_time(u64 *max, char **units)
 	*max /= div;
 }
 
-int svg_line_graph(struct plot *plot, struct graph_line_data *gld, char *color)
+int svg_line_graph(struct plot *plot, struct graph_line_data *gld, char *color, int thresh1, int thresh2)
 {
 	int i;
 	double val;
+	double avg;
 	int rolling;
 	int fd = plot->fd;
 	char *start = "<path d=\"";
@@ -690,24 +691,58 @@ int svg_line_graph(struct plot *plot, struct graph_line_data *gld, char *color)
 	double xscale = (double)(gld->seconds - 1) / graph_width;
 	char c = 'M';
 	double x;
+	int printed_header = 0;
+	int printed_lines = 0;
 
-	if (rolling_avg_secs)
+	if (0 && thresh1 && thresh2)
+		rolling = 0;
+	else if (rolling_avg_secs)
 		rolling = rolling_avg_secs;
 	else
 		rolling = gld->stop_seconds / 25;
 
-	write(fd, start, strlen(start));
 	for (i = 0; i < gld->stop_seconds; i++) {
-		val = rolling_avg(gld->data, i, rolling);
-		val = val / yscale;
+		avg = rolling_avg(gld->data, i, rolling);
+		val = avg / yscale;
 		x = (double)i / xscale;
-		snprintf(line, line_len, "%c %d %d ", c, axis_x_off(x), axis_y_off(val));
+		if (!thresh1 && !thresh2) {
+
+			if (!printed_header) {
+				write(fd, start, strlen(start));
+				printed_header = 1;
+			}
+
+			/* in full line mode, everything in the graph is connected */
+			snprintf(line, line_len, "%c %d %d ", c, axis_x_off(x), axis_y_off(val));
+			c = 'L';
+			write(fd, line, strlen(line));
+			printed_lines = 1;
+		} else if (avg > thresh1 || avg > thresh2) {
+			int len = 10;
+			if (!printed_header) {
+				write(fd, start, strlen(start));
+				printed_header = 1;
+			}
+
+			/* otherwise, we just print a bar up there to show this one data point */
+			if (i == gld->stop_seconds)
+				len = -10;
+
+			/*
+			 * we don't use the rolling averages here to show high
+			 * points in the data
+			 */
+			snprintf(line, line_len, "M %d %d h %d ", axis_x_off(x),
+				 axis_y_off(val), len);
+			write(fd, line, strlen(line));
+			printed_lines = 1;
+		}
 
-		c = 'L';
+	}
+	if (printed_lines) {
+		snprintf(line, line_len, "\" fill=\"none\" stroke=\"%s\" stroke-width=\"2\"/>\n", color);
 		write(fd, line, strlen(line));
 	}
-	snprintf(line, line_len, "\" fill=\"none\" stroke=\"%s\" stroke-width=\"2\"/>\n", color);
-	write(fd, line, strlen(line));
 
 	return 0;
 }
diff --git a/iowatcher/plot.h b/iowatcher/plot.h
index 1d534dd..11434c4 100644
--- a/iowatcher/plot.h
+++ b/iowatcher/plot.h
@@ -70,7 +70,12 @@ struct graph_line_data {
 
 struct graph_dot_data {
 	u64 max_offset;
+	u64 max_bank;
+	u64 max_bank_offset;
 	u64 total_ios;
+	u64 total_bank_ios;
+
+	int add_bank_ios;
 
 	/* in pixels, number of rows in our bitmap */
 	int rows;
@@ -99,7 +104,7 @@ struct plot_history {
 };
 
 int svg_io_graph(struct plot *plot, struct graph_dot_data *gdd, char *color);
-int svg_line_graph(struct plot *plot, struct graph_line_data *gld, char *color);
+int svg_line_graph(struct plot *plot, struct graph_line_data *gld, char *color, int thresh1, int thresh2);
 struct graph_line_data *alloc_line_data(int seconds, int stop_seconds);
 void free_line_data(struct graph_line_data *gld);
 struct graph_dot_data *alloc_dot_data(int seconds, u64 max_offset, int stop_seconds);
diff --git a/iowatcher/tracers.c b/iowatcher/tracers.c
index acced94..362fb0f 100644
--- a/iowatcher/tracers.c
+++ b/iowatcher/tracers.c
@@ -51,6 +51,7 @@ char *blktrace_args[] = {
 	"-a", "queue",
 	"-a", "complete",
 	"-a", "issue",
+	"-a", "notify",
 	NULL,
 };