[PATCH] blkparse: Add format specifiers and format field identifiers
authorAlan D. Brunelle <Alan.Brunelle@hp.com>
Tue, 20 Sep 2005 07:34:45 +0000 (09:34 +0200)
committerJens Axboe <axboe@suse.de>
Tue, 20 Sep 2005 07:34:45 +0000 (09:34 +0200)
This allows the user to completely customize the output format.

README
blkparse.c
blktrace.c

diff --git a/README b/README
index f41938162b197012a737bf56db867710b820b9bd..06ee153fc9652ccc36a289dae8fcb7a34815f21a 100644 (file)
--- a/README
+++ b/README
@@ -24,8 +24,17 @@ The snapshots include the full git object database as well.
 Usage
 -----
 
-% blktrace -d <dev> [-o <output> -a <trace> [-a <trace>] -k]
-       -a <trace> is one of: (use multiple -a options to get more)
+$ blktrace -d <dev> [ -r relay_path ] [ -o output ] [ -k ] [ -w time ]
+                   [ -a action ] [ -A action mask ]
+
+       -d Use specified device. May also be given last after options.
+       -r Path to mounted relayfs, defaults to /relay.
+       -o File(s) to send output to.
+       -k Kill running trace.
+       -w Stop after defined time, in seconds.
+       -a Only trace specific actions (use more -a options to add actions).
+          Available actions are:
+
                READ
                WRITE
                BARRIER
@@ -36,20 +45,56 @@ Usage
                COMPLETE
                FS
                PC
-       -k Kill a currently running trace.
-       --- run task to generate load to be traced ---
-       <SIGINT to kill>
-       --- Generates:
-               <output>_out.[0..ncpus] : Contains binary trace data
-
-       % blkparse -i <input> [-o <output> -s -t]
-       --- Generates:
-               <output>.log : Contains formatted trace data, if
-               output logging is added with the -o option. Otherwise, the
-               output is sent to stdout. If the -s option is used, in
-               addition to per-CPU stats, per process stats are shown as well.
-               The -t option will provide individual io statistics, displaying
-               things like completion time, queueing time, etc.
+
+       -A Give the trace mask directly as a number.
+
+$ blkparse -i <input> [ -o <output> ] [ -b rb_batch ] [ -s ] [ -t ] [ -q ]
+                     [ -w start:stop ] [ -f output format ] [ -F format spec ]
+
+       -i Input file containing trace data, or '-' for stdin.
+       -o Output file. If not given, output is stdout.
+       -b stdin read batching.
+       -s Show per-program io statistics.
+       -t Track individual ios. Will tell you the time a request took to
+          get queued, to get dispatched, and to get completed.
+       -q Quiet. Don't display any stats at the end of the trace.
+       -w Only parse data between the given time interval in seconds. If
+          'start' isn't given, blkparse defaults the start time to 0.
+       -f Output format. Customize the output format. The format field
+          identifiers are:
+
+               %a      - Action
+               %c      - CPU ID
+               %C      - Task command name
+               %d      - Direction (r/w)
+               %D      - Device number
+               %e      - Error number
+               %M      - Major
+               %m      - Minor
+               %n      - Nblocks
+               %p      - PID
+               %P      - PDU
+               %s      - Sequence number
+               %S      - Sector number
+               %t      - Time (wallclock - nanoseconds)
+               %T      - Time (wallclock - seconds)
+               %u      - Time (processing - microseconds)
+               %U      - Unplug depth(
+
+       -F Format specification. The individual specifiers are:
+
+               B       - Back merge
+               C       - Complete
+               D       - Issue
+               F       - Front merge
+               G       - Get request
+               M       - Both front and back merge
+               P       - Plug
+               Q       - Queue
+               R       - Requeue
+               S       - Sleep requests
+               T       - Unplug timer
+               U       - Unplug IO
 
 
 If you want to do live tracing, you can pipe the data between blktrace
index b586cb549e4f3c7d2f302e616fee5b04bc4ba74b..6da028842f853d9f2a848b26020de2d0e11d5c1d 100644 (file)
@@ -30,6 +30,7 @@
 #include <signal.h>
 #include <locale.h>
 #include <limits.h>
+#include <ctype.h>
 
 #include "blktrace.h"
 #include "rbtree.h"
@@ -45,6 +46,8 @@
 
 #define min(a, b)      ((a) < (b) ? (a) : (b))
 
+#define HEADER         "%D %2c %8s %5T.%9t %5p %2a %3d "
+
 struct io_stats {
        unsigned long qreads, qwrites, creads, cwrites, mreads, mwrites;
        unsigned long ireads, iwrites;
@@ -96,7 +99,7 @@ struct per_process_info {
 static struct per_process_info *ppi_hash[1 << PPI_HASH_SHIFT];
 static struct per_process_info *ppi_list;
 
-#define S_OPTS "i:o:b:stqw:"
+#define S_OPTS "i:o:b:stqw:f:F:"
 static struct option l_opts[] = {
        {
                .name = "input",
@@ -140,6 +143,18 @@ static struct option l_opts[] = {
                .flag = NULL,
                .val = 'w'
        },
+       {
+               .name = "format",
+               .has_arg = 1,
+               .flag = NULL,
+               .val = 'f'
+       },
+       {
+               .name = "format-spec",
+               .has_arg = 1,
+               .flag = NULL,
+               .val = 'F'
+       },
        {
                .name = NULL,
                .has_arg = 0,
@@ -303,8 +318,8 @@ static inline int track_rb_insert(struct io_track *iot)
                        p = &(*p)->rb_right;
                else {
                        fprintf(stderr,
-                               "sector alias (%llu) on device %d,%d!\n",
-                               iot->sector,
+                               "sector alias (%Lu) on device %d,%d!\n",
+                               (unsigned long long) iot->sector,
                                MAJOR(iot->device), MINOR(iot->device));
                        return 1;
                }
@@ -705,99 +720,310 @@ static inline void account_unplug(struct blk_io_trace *t,
        }
 }
 
-static void output(struct per_cpu_info *pci, char *s)
+#define VALID_SPECS    "BCDFGMPQRSTU"
+static char *override_format[256];
+static inline int valid_spec(int spec)
 {
-       fprintf(ofp, "%s", s);
+       return strchr(VALID_SPECS, spec) != NULL;
 }
 
-static char hstring[256];
-static char tstring[256];
-
-static inline char *setup_header(struct per_cpu_info *pci,
-                                struct blk_io_trace *t, char *act)
+static void set_all_format_specs(char *optarg)
 {
-       int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
-       int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
-       int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
-       char rwbs[4];
-       int i = 0;
+       char *p;
 
-       if (w)
-               rwbs[i++] = 'W';
-       else
-               rwbs[i++] = 'R';
-       if (b)
-               rwbs[i++] = 'B';
-       if (s)
-               rwbs[i++] = 'S';
+       for (p = VALID_SPECS; *p; p++)
+               if (override_format[(int)(*p)] == NULL)
+                       override_format[(int)(*p)] = strdup(optarg);
+}
 
-       rwbs[i] = '\0';
+static int add_format_spec(char *optarg)
+{
+       int spec = optarg[0];
 
-       sprintf(hstring, "%3d,%-3d %2d %8ld %5Lu.%09Lu %5u %2s %3s",
-               MAJOR(t->device), MINOR(t->device), pci->cpu,
-               (unsigned long)t->sequence, SECONDS(t->time),
-               NANO_SECONDS(t->time), t->pid, act, rwbs);
+       if (!valid_spec(spec)) {
+               fprintf(stderr,"Bad format specifier %c\n", spec);
+               return 1;
+       }
+       if (optarg[1] != ',') {
+               fprintf(stderr,"Bad format specifier - need ',' %s\n", optarg);
+               return 1;
+       }
+       optarg += 2;
+       if (*optarg == '\0') {
+               fprintf(stderr,"Bad format specifier - need fmt %s\n", optarg);
+               return 1;
+       }
+
+       /*
+        * Set both merges (front and back)
+        */
+       if (spec == 'M') {
+               override_format['B'] = strdup(optarg);
+               override_format['M'] = strdup(optarg);
+       } else
+               override_format[spec] = strdup(optarg);
 
-       return hstring;
+       return 0;
 }
 
-static void log_complete(struct per_cpu_info *pci, struct blk_io_trace *t,
-                        char *act)
+static void print_field(char *act, struct per_cpu_info *pci,
+                       struct blk_io_trace *t, unsigned long long elapsed,
+                       int pdu_len, unsigned char *pdu_buf, char field,
+                       int minus, int has_w, int width)
 {
-       unsigned long long elapsed = log_track_complete(t);
+       char format[64];
 
-       if (elapsed != -1ULL) {
-               unsigned long usec = elapsed / 1000;
+       if (has_w) {
+               if (minus)
+                       sprintf(format, "%%-%d", width);
+               else
+                       sprintf(format, "%%%d", width);
+       } else
+               sprintf(format, "%%");
+
+       switch (field) {
+       case 'a':
+               fprintf(ofp, strcat(format, "s"), act);
+               break;
+       case 'c':
+               fprintf(ofp, strcat(format, "d"), pci->cpu);
+               break;
+       case 'C':
+               fprintf(ofp, strcat(format, "s"), t->comm);
+               break;
+       case 'd': {
+               char rwbs[4];
+               int i = 0;
+               int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
+               int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
+               int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
+               if (w)
+                       rwbs[i++] = 'W';
+               else
+                       rwbs[i++] = 'R';
+               if (b)
+                       rwbs[i++] = 'B';
+               if (s)
+                       rwbs[i++] = 'S';
+               rwbs[i] = '\0';
+               fprintf(ofp, strcat(format, "s"), rwbs);
+               break;
+       }
+       case 'D':       /* format width ignored */
+               fprintf(ofp,"%3d,%-3d", MAJOR(t->device), MINOR(t->device));
+               break;
+       case 'e':
+               fprintf(ofp, strcat(format, "d"), t->error);
+               break;
+       case 'M':
+               fprintf(ofp, strcat(format, "d"), MAJOR(t->device));
+               break;
+       case 'm':
+               fprintf(ofp, strcat(format, "d"), MINOR(t->device));
+               break;
+       case 'n':
+               fprintf(ofp, strcat(format, "u"), t->bytes >> 9);
+               break;
+       case 'p':
+               fprintf(ofp, strcat(format, "u"), t->pid);
+               break;
+       case 'P':       /* format width ignored */
+               if ((pdu_len > 0) && (pdu_buf != NULL)) {
+                       int i;
+                       unsigned char *p = pdu_buf;
+                       for (i = 0; i < pdu_len; i++)
+                               fprintf(ofp, "%02x ", *p++);
+               }
+               break;
+       case 's':
+               fprintf(ofp, strcat(format, "ld"), t->sequence);
+               break;
+       case 'S':
+               fprintf(ofp, strcat(format, "lu"), t->sector);
+               break;
+       case 't':
+               sprintf(format, "%%0%dlu", has_w ? width : 9);
+               fprintf(ofp, format, NANO_SECONDS(t->time));
+               break;
+       case 'T':
+               fprintf(ofp, strcat(format, "d"), SECONDS(t->time));
+               break;
+       case 'u':
+               if (elapsed == -1ULL) {
+                       fprintf(stderr, "Expecting elapsed value\n");
+                       exit(1);
+               }
+               fprintf(ofp, strcat(format, "llu"), elapsed / 1000);
+               break;
+       case 'U': {
+               __u64 *depth = (__u64 *) ((char *) t + sizeof(*t));
+               fprintf(ofp, strcat(format, "u"),
+                                       (unsigned int) be64_to_cpu(*depth));
+               break;
+       }
+       default:
+               fprintf(ofp,strcat(format, "c"), field);
+               break;
+       }
+}
 
-               sprintf(tstring,"%s %Lu + %u (%8lu) [%d]\n",
-                       setup_header(pci, t, act),
-                       (unsigned long long)t->sector, t->bytes >> 9,
-                       usec, t->error);
-       } else {
-               sprintf(tstring,"%s %Lu + %u [%d]\n", setup_header(pci, t, act),
-                       (unsigned long long)t->sector, t->bytes >> 9, t->error);
+static char *parse_field(char *act, struct per_cpu_info *pci, 
+                        struct blk_io_trace *t, unsigned long long elapsed, 
+                        int pdu_len, unsigned char *pdu_buf, 
+                        char *master_format)
+{
+       int minus = 0;
+       int has_w = 0;
+       int width = 0;
+       char *p = master_format;
+
+       if (*p == '-') {
+               minus = 1;
+               p++;
        }
-       
-       output(pci, tstring);
+       if (isdigit(*p)) {
+               has_w = 1;
+               do {
+                       width = (width * 10) + (*p++ - '0');
+               } while ((*p) && (isdigit(*p)));
+       }
+       if (*p) {
+               print_field(act, pci, t, elapsed, pdu_len, pdu_buf, *p++,
+                           minus, has_w, width);
+       }
+       return p;
 }
 
-static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t,
-                     char *act)
+static char *fmt_select(int fmt_spec, struct blk_io_trace *t,
+                       unsigned long long elapsed)
 {
-       unsigned long long elapsed = log_track_queue(t);
+       char *fmt;
+       char scratch_format[1024];
 
-       if (elapsed != -1ULL) {
-               unsigned long usec = elapsed / 1000;
+       if (override_format[fmt_spec] != NULL)
+               return override_format[fmt_spec];
 
-               sprintf(tstring,"%s %Lu + %u (%8lu) [%s]\n",
-                       setup_header(pci, t, act),
-                       (unsigned long long)t->sector, t->bytes >> 9,
-                       usec, t->comm);
-       } else {
-               sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
-                       (unsigned long long)t->sector, t->bytes >> 9, t->comm);
+       switch (fmt_spec) {
+       case 'C':       /* Complete */
+               if (t->action & BLK_TC_ACT(BLK_TC_PC)) {
+                       strcpy(scratch_format, HEADER);
+                       strcat(scratch_format, "%P");
+               } else {
+                       strcpy(scratch_format, HEADER "%S + %n ");
+                       if (elapsed != -1ULL)
+                               strcat(scratch_format, "(%8u) ");
+               }
+               strcat(scratch_format, "[%e]\n");
+               fmt = scratch_format;
+               break;
+
+       case 'D':       /* Issue */
+               if (t->action & BLK_TC_ACT(BLK_TC_PC)) {
+                       strcpy(scratch_format, HEADER);
+                       strcat(scratch_format, "%P");
+               } else {
+                       strcpy(scratch_format, HEADER "%S + %n ");
+                       if (elapsed != -1ULL)
+                               strcat(scratch_format, "(%8u) ");
+               }
+               strcat(scratch_format,"[%C]\n");
+               fmt = scratch_format;
+               break;
+
+       case 'Q':       /* Queue */
+               strcpy(scratch_format, HEADER "%S + %n ");
+               if (elapsed != -1ULL)
+                       strcat(scratch_format, "(%8u) ");
+               strcat(scratch_format,"[%C]\n");
+               fmt = scratch_format;
+               break;
+
+       case 'B':       /* Back merge */
+       case 'F':       /* Front merge */
+       case 'M':       /* Front or back merge */
+               fmt = HEADER "%S + %n [%C]\n";
+               break;
+
+       case 'P':       /* Plug */
+               fmt = HEADER "[%C]\n";
+               break;
+
+       case 'G':       /* Get request */
+       case 'S':       /* Sleep request */
+               fmt = HEADER "%S + %n [%C]\n";
+               break;
+
+       case 'U':       /* Unplug IO */
+       case 'T':       /* Unplug timer */
+               fmt = HEADER "[%C] %U\n";
+               break;
+
+       default:
+               fprintf(stderr,"FATAL: Invalid format spec %c\n", fmt_spec);
+               exit(1);
+               /*NOTREACHED*/
        }
-       output(pci, tstring);
+
+       return fmt;
 }
 
-static void log_issue(struct per_cpu_info *pci, struct blk_io_trace *t,
-                     char *act)
+static void process_fmt(char *act, struct per_cpu_info *pci,
+                          struct blk_io_trace *t, unsigned long long elapsed,
+                          int pdu_len, unsigned char *pdu_buf)
 {
-       unsigned long long elapsed = log_track_issue(t);
-
-       if (elapsed != -1ULL) {
-               double usec = (double) elapsed / 1000;
+       char *p = fmt_select(act[0], t, elapsed);
 
-               sprintf(tstring,"%s %Lu + %u (%8.2f) [%s]\n",
-                       setup_header(pci, t, act),
-                       (unsigned long long)t->sector, t->bytes >> 9,
-                       usec, t->comm);
-       } else {
-               sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
-                       (unsigned long long)t->sector, t->bytes >> 9, t->comm);
+       while (*p) {
+               switch (*p) {
+               case '%':       /* Field specifier */
+                       p++;
+                       if (*p == '%')
+                               fprintf(ofp, "%c", *p++);
+                       else if (!*p)
+                               fprintf(ofp, "%c", '%');
+                       else
+                               p = parse_field(act, pci, t, elapsed,
+                                               pdu_len, pdu_buf, p);
+                       break;
+               case '\\': {    /* escape */
+                       switch (p[1]) {
+                       case 'b': fprintf(ofp, "\b"); break;
+                       case 'n': fprintf(ofp, "\n"); break;
+                       case 'r': fprintf(ofp, "\r"); break;
+                       case 't': fprintf(ofp, "\t"); break;
+                       default:
+                               fprintf(stderr, 
+                                       "Invalid escape char in format %c\n",
+                                       p[1]);
+                               exit(1);
+                               /*NOTREACHED*/
+                       }
+                       p += 2;
+                       break;
+               }
+               default:
+                       fprintf(ofp, "%c", *p++);
+                       break;
+               }
        }
+}
+
+static void log_complete(struct per_cpu_info *pci, struct blk_io_trace *t,
+                        char *act)
+{
+       process_fmt(act, pci, t, log_track_complete(t), 0, NULL);
+}
+
+static void log_queue(struct per_cpu_info *pci, struct blk_io_trace *t,
+                     char *act)
+{
+       process_fmt(act, pci, t, log_track_queue(t), 0, NULL);
+}
 
-       output(pci, tstring);
+static void log_issue(struct per_cpu_info *pci, struct blk_io_trace *t,
+                     char *act)
+{
+       process_fmt(act, pci, t, log_track_issue(t), 0, NULL);
 }
 
 static void log_merge(struct per_cpu_info *pci, struct blk_io_trace *t,
@@ -806,62 +1032,32 @@ static void log_merge(struct per_cpu_info *pci, struct blk_io_trace *t,
        if (act[0] == 'F')
                log_track_frontmerge(t);
 
-       sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
-               (unsigned long long)t->sector, t->bytes >> 9, t->comm);
-       output(pci, tstring);
+       process_fmt(act, pci, t, -1ULL, 0, NULL);
 }
 
 static void log_action(struct per_cpu_info *pci, struct blk_io_trace *t,
                        char *act)
 {
-       sprintf(tstring,"%s [%s]\n", setup_header(pci, t, act), t->comm);
-       output(pci, tstring);
+       process_fmt(act, pci, t, -1ULL, 0, NULL);
 }
 
 static void log_generic(struct per_cpu_info *pci, struct blk_io_trace *t,
                        char *act)
 {
-       sprintf(tstring,"%s %Lu + %u [%s]\n", setup_header(pci, t, act),
-               (unsigned long long)t->sector, t->bytes >> 9, t->comm);
-       output(pci, tstring);
+       process_fmt(act, pci, t, -1ULL, 0, NULL);
 }
 
-static int log_unplug(struct per_cpu_info *pci, struct blk_io_trace *t,
+static void log_unplug(struct per_cpu_info *pci, struct blk_io_trace *t,
                      char *act)
 {
-       __u64 *depth;
-       int len;
-
-       len = sprintf(tstring,"%s [%s] ", setup_header(pci, t, act), t->comm);
-       depth = (__u64 *) ((char *) t + sizeof(*t));
-       sprintf(tstring + len, "%u\n", (unsigned int) be64_to_cpu(*depth));
-       output(pci, tstring);
-
-       return 0;
+       process_fmt(act, pci, t, -1ULL, 0, NULL);
 }
 
-static int log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char *act)
+static void log_pc(struct per_cpu_info *pci, struct blk_io_trace *t, char *act)
 {
-       unsigned char *buf;
-       int i;
+       unsigned char *buf = (unsigned char *) t + sizeof(*t);
 
-       sprintf(tstring,"%s ", setup_header(pci, t, act));
-       output(pci, tstring);
-
-       buf = (unsigned char *) t + sizeof(*t);
-       for (i = 0; i < t->pdu_len; i++) {
-               sprintf(tstring,"%02x ", buf[i]);
-               output(pci, tstring);
-       }
-
-       if (act[0] == 'C') {
-               sprintf(tstring,"[%d]\n", t->error);
-               output(pci, tstring);
-       } else {
-               sprintf(tstring,"[%s]\n", t->comm);
-               output(pci, tstring);
-       }
-       return 0;
+       process_fmt(act, pci, t, -1ULL, t->pdu_len, buf);
 }
 
 static int dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci)
@@ -882,7 +1078,7 @@ static int dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci)
                        log_generic(pci, t, "R");
                        break;
                case __BLK_TA_ISSUE:
-                       ret = log_pc(pci, t, "D");
+                       log_pc(pci, t, "D");
                        break;
                case __BLK_TA_COMPLETE:
                        log_pc(pci, t, "C");
@@ -893,7 +1089,7 @@ static int dump_trace_pc(struct blk_io_trace *t, struct per_cpu_info *pci)
                        break;
        }
        
-       return ret;
+       return 0;
 }
 
 static void dump_trace_fs(struct blk_io_trace *t, struct per_cpu_info *pci)
@@ -1464,6 +1660,13 @@ int main(int argc, char *argv[])
                        if (find_stopwatch_interval(optarg) != 0)
                                return 1;
                        break;
+               case 'f':
+                       set_all_format_specs(optarg);
+                       break;
+               case 'F':
+                       if (add_format_spec(optarg) != 0)
+                               return 1;
+                       break;
                default:
                        usage(argv[0]);
                        return 1;
index 2bb38ed45b62d0f14d3331defa2ad40b60e69659..9304c248bd6f6ccc271e23f4bc777a33db93fa5a 100644 (file)
@@ -607,7 +607,7 @@ int main(int argc, char *argv[])
                case 'a':
                        i = find_mask_map(optarg);
                        if (i < 0) {
-                               fprintf(stderr,"Invalid action mask %s\n", 
+                               fprintf(stderr,"Invalid action mask %s\n",
                                        optarg);
                                return 1;
                        }
@@ -617,7 +617,7 @@ int main(int argc, char *argv[])
                case 'A':
                        if ((sscanf(optarg, "%x", &i) != 1) || !VALID_SET(i)) {
                                fprintf(stderr,
-                                       "Invalid set action mask %s/0x%x\n", 
+                                       "Invalid set action mask %s/0x%x\n",
                                        optarg, i);
                                return 1;
                        }