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>

diff --git a/iowatcher/blkparse.c b/iowatcher/blkparse.c
index d254811f4264452c7c7fae3595ba2b56260f43d1..abdacb5a7c16284d20f12f86f12eb73648633b9c 100644 (file)
--- 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 ff1419138d31956a389f071be509000851fb1be8..a78a8b746ce683474f722297bd595ea38c8269e3 100644 (file)
--- 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 9eb7f3b44c171e3ffb462e8e73f954af974ad08b..22c0bb6086f7eeef351b67158b6e2bb05dcd2744 100644 (file)
--- 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 7f30f77ec1f57d73f0584532b425252881006e22..fac59bd02ec0d3eb8f0f4fd92ce55d81817929a2 100644 (file)
--- 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 1d534dd6cf70ad5f6bd779bbc14ef535a4fc983b..11434c46983c9a56f8a6b1edfec76820821ecf84 100644 (file)
--- 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 acced94e4b4e0b241b848662ae0df78254b58067..362fb0f13832b40ed0c22721494de63023c4ef26 100644 (file)
--- a/iowatcher/tracers.c
+++ b/iowatcher/tracers.c
@@ -51,6 +51,7 @@ char *blktrace_args[] = {
        "-a", "queue",
        "-a", "complete",
        "-a", "issue",
+       "-a", "notify",
        NULL,
 };