Put message notes from kernel into a separate file for easy tracking

Also made made_dev_hdr standard for all usages.

diff --git a/btt/args.c b/btt/args.c
index 2d0dfdf2ad578578d9be00d27c70acb5b97f6a3b..9c5c4d500acc0a78752faa9885206e06c688b9d3 100644 (file)
--- a/btt/args.c
+++ b/btt/args.c
@@ -335,7 +335,7 @@ void handle_args(int argc, char *argv[])
        setup_ifile(input_name);
 
        if (output_name == NULL) {
-               ranges_ofp = avgs_ofp = stdout;
+               ranges_ofp = avgs_ofp = msgs_ofp = stdout;
                easy_parse_avgs = 0;
        }
        else {
@@ -359,6 +359,15 @@ void handle_args(int argc, char *argv[])
                if (verbose)
                        printf("Sending stats data to %s\n", fname);
 
+               sprintf(fname, "%s.msg", output_name);
+               msgs_ofp = fopen(fname, "w");
+               if (msgs_ofp == NULL) {
+                       perror(fname);
+                       exit(1);
+               }
+               if (verbose)
+                       printf("Sending K messages to %s\n", fname);
+
                if (easy_parse_avgs) {
                        sprintf(fname, "%s.xvg", output_name);
                        xavgs_ofp = fopen(fname, "w");

diff --git a/btt/bt_timeline.c b/btt/bt_timeline.c
index bb32e44b10469fec9fbd8433394ec55213d4db72..2eed08715620cf76c4ad29693a65a8a10bf3c273 100644 (file)
--- a/btt/bt_timeline.c
+++ b/btt/bt_timeline.c
@@ -30,7 +30,7 @@ char bt_timeline_version[] = "2.05";
 char *devices, *exes, *input_name, *output_name, *seek_name, *bno_dump_name;
 char *d2c_name, *q2c_name, *per_io_name, *unplug_hist_name;
 char *sps_name;
-FILE *ranges_ofp, *avgs_ofp, *xavgs_ofp, *per_io_ofp;
+FILE *ranges_ofp, *avgs_ofp, *xavgs_ofp, *per_io_ofp, *msgs_ofp;
 int verbose, done, time_bounded, output_all_data, seek_absolute;
 int easy_parse_avgs;
 double t_astart, t_aend;
@@ -69,6 +69,8 @@ int main(int argc, char *argv[])
                iostat_dump_stats(iostat_last_stamp, 1);
        }
 
+       if (msgs_ofp != stdout)
+               fclose(msgs_ofp);
        if (ranges_ofp != stdout)
                fclose(ranges_ofp);
        if (avgs_ofp != stdout)

diff --git a/btt/globals.h b/btt/globals.h
index 299a02e7e7cdf11e0c87901450fe1d15adb5662a..c4b76744172f8c45b8314fc62c52f1c86f7d7a75 100644 (file)
--- a/btt/globals.h
+++ b/btt/globals.h
@@ -183,6 +183,7 @@ extern char *seek_name, *iostat_name, *d2c_name, *q2c_name, *per_io_name;
 extern char *bno_dump_name, *unplug_hist_name, *sps_name;
 extern double range_delta;
 extern FILE *ranges_ofp, *avgs_ofp, *xavgs_ofp, *iostat_ofp, *per_io_ofp;
+extern FILE *msgs_ofp;
 extern int verbose, done, time_bounded, output_all_data, seek_absolute;
 extern int easy_parse_avgs;
 extern unsigned int n_devs;
@@ -250,6 +251,7 @@ void add_file(struct file_info **fipp, FILE *fp, char *oname);
 void clean_files(struct file_info **fipp);
 void add_buf(void *buf);
 void clean_bufs(void);
+char *make_dev_hdr(char *pad, size_t len, struct d_info *dip, int add_parens);
 void dbg_ping(void);
 
 /* mmap.c */
@@ -260,7 +262,6 @@ int next_trace(struct blk_io_trace *t, void **pdu);
 /* output.c */
 int output_avgs(FILE *ofp);
 int output_ranges(FILE *ofp);
-char *make_dev_hdr(char *pad, size_t len, struct d_info *dip);
 
 /* proc.c */
 void add_process(__u32 pid, char *name);

diff --git a/btt/iostat.c b/btt/iostat.c
index c4ddcb47700a76a684c3922d2c54767d983bcc64..d701e2fa71e9c42a32d2ae181ef4b3a9ca5342cb 100644 (file)
--- a/btt/iostat.c
+++ b/btt/iostat.c
@@ -124,7 +124,7 @@ void __dump_stats(__u64 stamp, int all, struct d_info *dip, struct stats_t *asp)
         * and we add in nrqm (number of merges), which should give
         * us the total number of IOs sent to the block IO layer.
         */
-       fprintf(iostat_ofp, "%-11s ", make_dev_hdr(hdr, 11, dip));
+       fprintf(iostat_ofp, "%-11s ", make_dev_hdr(hdr, 11, dip, 1));
        fprintf(iostat_ofp, "%8.2lf ", (double)sp->rqm[1] / dt);
        fprintf(iostat_ofp, "%8.2lf ", (double)sp->rqm[0] / dt);
        fprintf(iostat_ofp, "%7.2lf ", (double)sp->ios[1] / dt);

diff --git a/btt/misc.c b/btt/misc.c
index 4e721fc2691c026070152c411dfabd4fec0db17e..0ddd26003c82ff64dcca2161e15849870842a8b4 100644 (file)
--- a/btt/misc.c
+++ b/btt/misc.c
@@ -100,4 +100,20 @@ void clean_bufs(void)
        }
 }
 
+char *make_dev_hdr(char *pad, size_t len, struct d_info *dip, int add_parens)
+{
+       if (dip->map == NULL) {
+               if (add_parens)
+                       snprintf(pad, len, "(%3d,%3d)",
+                                MAJOR(dip->device), MINOR(dip->device));
+               else
+                       snprintf(pad, len, "%d,%d",
+                                MAJOR(dip->device), MINOR(dip->device));
+       }
+       else
+               snprintf(pad, len, "%s", dip->map->device);
+
+       return pad;
+}
+
 void dbg_ping(void) {}

diff --git a/btt/output.c b/btt/output.c
index ab1566b371bebf6a2b4f05374b3674b33d13bd6e..307641206c558aac0a1a5e0fb15f5da25121be04 100644 (file)
--- a/btt/output.c
+++ b/btt/output.c
@@ -90,28 +90,6 @@ static inline char *avg2string(struct avg_info *ap, char *string)
        return string;
 }
 
-char *make_dev_hdr(char *pad, size_t len, struct d_info *dip)
-{
-       if (dip->map == NULL)
-               snprintf(pad, len, "(%3d,%3d)",
-                        MAJOR(dip->device), MINOR(dip->device));
-       else
-               snprintf(pad, len, "%s", dip->map->device);
-
-       return pad;
-}
-
-char *make_dev_hdrX(char *pad, size_t len, struct d_info *dip)
-{
-       if (dip->map == NULL)
-               snprintf(pad, len, "%d,%d",
-                        MAJOR(dip->device), MINOR(dip->device));
-       else
-               snprintf(pad, len, "%s", dip->map->device);
-
-       return pad;
-}
-
 struct __oda {
        FILE *ofp;
        ai_dip_t (*func)(struct d_info *);
@@ -123,7 +101,8 @@ 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, 0);
+               __output_avg(odap->ofp, make_dev_hdr(dev_info, 15, dip, 1),
+                               ap, 0);
        }
 }
 
@@ -148,7 +127,8 @@ void __output_q2d_histo(struct d_info *dip, void *arg)
                char dev_info[15];
                FILE *ofp = q2dp->ofp;
 
-               fprintf(q2dp->ofp, "%10s | ", make_dev_hdr(dev_info, 15, dip));
+               fprintf(q2dp->ofp, "%10s | ",
+                                       make_dev_hdr(dev_info, 15, dip, 1));
                q2d_display(ofp, dip->q2d_priv);
                q2d_acc(q2dp->q2d_all, dip->q2d_priv);
                q2dp->n++;
@@ -203,7 +183,7 @@ void __output_dip_merge_ratio(struct d_info *dip, void *arg)
                blks_avg = (double)dip->avgs.blks.total / d2c_n;
                fprintf((FILE *)arg,
                        "%10s | %8llu %8llu %7.1lf | %8llu %8llu %8llu %8llu\n",
-                       make_dev_hdr(dev_info, 15, dip),
+                       make_dev_hdr(dev_info, 15, dip, 1),
                        (unsigned long long)dip->n_qs,
                        (unsigned long long)dip->n_ds,
                        ratio,
@@ -215,7 +195,7 @@ void __output_dip_merge_ratio(struct d_info *dip, void *arg)
                if (easy_parse_avgs) {
                        fprintf(xavgs_ofp,
                                "DMI %s %llu %llu %.9lf %llu %llu %llu %llu\n",
-                               make_dev_hdrX(dev_info, 15, dip),
+                               make_dev_hdr(dev_info, 15, dip, 0),
                                (unsigned long long)dip->n_qs,
                                (unsigned long long)dip->n_ds,
                                ratio,
@@ -284,7 +264,7 @@ void __output_dip_prep_ohead(struct d_info *dip, void *arg)
 
                fprintf(odp->ofp,
                        "%10s | %8.4lf%% %8.4lf%% %8.4lf%% %8.4lf%% %8.4lf%%\n",
-                       make_dev_hdr(dev_info, 15, dip),
+                       make_dev_hdr(dev_info, 15, dip, 1),
                        100.0 * (double)(dip->avgs.q2g.total) / q2c_total,
                        100.0 * (double)(dip->avgs.g2i.total) / q2c_total,
                        100.0 * (double)(dip->avgs.q2m.total) / q2c_total,
@@ -419,8 +399,8 @@ static void do_output_dip_seek_info(struct d_info *dip, FILE *ofp, int is_q2q)
                nmodes = seeki_mode(handle, &m);
 
                fprintf(ofp, "%10s | %15lld %15.1lf %15lld | %lld(%d)",
-                       make_dev_hdr(dev_info, 15, dip), nseeks, mean, median,
-                       nmodes > 0 ? m.modes[0] : 0, m.most_seeks);
+                       make_dev_hdr(dev_info, 15, dip, 1), nseeks, mean,
+                       median, nmodes > 0 ? m.modes[0] : 0, m.most_seeks);
                for (i = 1; i < nmodes; i++)
                        fprintf(ofp, " %lld", m.modes[i]);
                fprintf(ofp, "\n");
@@ -429,7 +409,7 @@ static void do_output_dip_seek_info(struct d_info *dip, FILE *ofp, int is_q2q)
                        char *rec = is_q2q ? "QSK" : "DSK";
                        fprintf(xavgs_ofp,
                                "%s %s %lld %.9lf %lld %lld %d",
-                               rec, make_dev_hdrX(dev_info, 15, dip),
+                               rec, make_dev_hdr(dev_info, 15, dip, 0),
                                nseeks, mean, median,
                                nmodes > 0 ? m.modes[0] : 0, m.most_seeks);
                                for (i = 1; i < nmodes; i++)
@@ -539,13 +519,13 @@ void __dip_output_plug(struct d_info *dip, void *arg)
                pct = 100.0 * ((dip->plugged_time / delta) / delta);
 
                fprintf(ofp, "%10s | %10d(%10d) | %13.9lf%%\n",
-                       make_dev_hdr(dev_info, 15, dip),
+                       make_dev_hdr(dev_info, 15, dip, 1),
                        dip->nplugs, dip->n_timer_unplugs, pct);
 
                if (easy_parse_avgs) {
                        fprintf(xavgs_ofp,
                                "PLG %s %d %d %.9lf\n",
-                               make_dev_hdrX(dev_info, 15, dip),
+                               make_dev_hdr(dev_info, 15, dip, 0),
                                dip->nplugs, dip->n_timer_unplugs, pct);
                }
 
@@ -590,13 +570,13 @@ void __dip_output_plug_nios(struct d_info *dip, void *arg)
        }
 
        fprintf(ofp, "%10s | %10.1lf   %10.1lf\n",
-               make_dev_hdr(dev_info, 15, dip),
+               make_dev_hdr(dev_info, 15, dip, 1),
                a_nios_uplug, a_nios_uplug_t);
 
        if (easy_parse_avgs) {
                fprintf(xavgs_ofp,
                        "UPG %s %.9lf %.9lf\n",
-                       make_dev_hdrX(dev_info, 15, dip),
+                       make_dev_hdr(dev_info, 15, dip, 0),
                        a_nios_uplug, a_nios_uplug_t);
        }
 }
@@ -649,12 +629,12 @@ void __dip_output_actQ(struct d_info *dip, void *arg)
                double a_actQs = (double)dip->t_act_q / (double)dip->n_qs;
 
                fprintf((FILE *)arg, "%10s | %13.1lf\n",
-                       make_dev_hdr(dev_info, 15, dip), a_actQs);
+                       make_dev_hdr(dev_info, 15, dip, 1), a_actQs);
 
                if (easy_parse_avgs) {
                        fprintf(xavgs_ofp,
                                "ARQ %s %.9lf\n",
-                               make_dev_hdrX(dev_info, 15, dip), a_actQs);
+                               make_dev_hdr(dev_info, 15, dip, 0), a_actQs);
                }
 
                n_actQs++;

diff --git a/btt/trace.c b/btt/trace.c
index 1d9a1c08d28c4ec914948039ec25ea29e7d6648e..efb9996cdd78f1e9044683a612753bfea13381fa 100644 (file)
--- a/btt/trace.c
+++ b/btt/trace.c
@@ -54,6 +54,23 @@ static void __add_trace(struct io *iop)
        }
 }
 
+static void trace_message(struct io *iop)
+{
+       char scratch[15];
+       char msg[iop->t.pdu_len + 1];
+
+       if (!io_setup(iop, IOP_M))
+               return;
+
+       memcpy(msg, iop->pdu, iop->t.pdu_len);
+       msg[iop->t.pdu_len] = '\0';
+
+       fprintf(msgs_ofp, "%s %5d.%09lu %s\n",
+               make_dev_hdr(scratch, 15, iop->dip, 1),
+               (int)SECONDS(iop->t.time),
+               (unsigned long)NANO_SECONDS(iop->t.time), msg);
+}
+
 void add_trace(struct io *iop)
 {
        if (iop->t.action & BLK_TC_ACT(BLK_TC_NOTIFY)) {
@@ -68,6 +85,8 @@ void add_trace(struct io *iop)
                                add_process(iop->t.pid, iop->pdu);
                        }
                }
+               else if (iop->t.action == BLK_TN_MESSAGE)
+                       trace_message(iop);
                io_release(iop);
        }
        else if (iop->t.action & BLK_TC_ACT(BLK_TC_PC))