blkparse: split off the timestamp correction code in to a separate function
[blktrace.git] / blkparse_fmt.c
index 30bab91a02195347bb880f8097af04d4e9aecb9d..c42e6d7b7219d532c4ae34d937e0ea9660535426 100644 (file)
@@ -7,10 +7,11 @@
 #include <stdlib.h>
 #include <unistd.h>
 #include <ctype.h>
+#include <time.h>
 
 #include "blktrace.h"
 
-#define VALID_SPECS    "BCDFGMPQRSTU"
+#define VALID_SPECS    "ABCDFGIMPQRSTUWX"
 
 #define HEADER         "%D %2c %8s %5T.%9t %5p %2a %3d "
 
@@ -43,19 +44,8 @@ int add_format_spec(char *option)
                return 1;
        }
        option += 2;
-       if (*option == '\0') {
-               fprintf(stderr,"Bad format specifier - need fmt %s\n", option);
-               return 1;
-       }
 
-       /*
-        * Set both merges (front and back)
-        */
-       if (spec == 'M') {
-               override_format['B'] = strdup(option);
-               override_format['M'] = strdup(option);
-       } else
-               override_format[spec] = strdup(option);
+       override_format[spec] = strdup(option);
 
        return 0;
 }
@@ -63,22 +53,70 @@ int add_format_spec(char *option)
 static inline void fill_rwbs(char *rwbs, struct blk_io_trace *t)
 {
        int w = t->action & BLK_TC_ACT(BLK_TC_WRITE);
-       int b = t->action & BLK_TC_ACT(BLK_TC_BARRIER);
+       int a = t->action & BLK_TC_ACT(BLK_TC_AHEAD);
        int s = t->action & BLK_TC_ACT(BLK_TC_SYNC);
+       int m = t->action & BLK_TC_ACT(BLK_TC_META);
+       int d = t->action & BLK_TC_ACT(BLK_TC_DISCARD);
+       int f = t->action & BLK_TC_ACT(BLK_TC_FLUSH);
+       int u = t->action & BLK_TC_ACT(BLK_TC_FUA);
        int i = 0;
 
-       if (w)
+       if (f)
+               rwbs[i++] = 'F'; /* flush */
+
+       if (d)
+               rwbs[i++] = 'D';
+       else if (w)
                rwbs[i++] = 'W';
-       else
+       else if (t->bytes)
                rwbs[i++] = 'R';
-       if (b)
-               rwbs[i++] = 'B';
+       else
+               rwbs[i++] = 'N';
+
+       if (u)
+               rwbs[i++] = 'F'; /* fua */
+       if (a)
+               rwbs[i++] = 'A';
        if (s)
                rwbs[i++] = 'S';
+       if (m)
+               rwbs[i++] = 'M';
 
        rwbs[i] = '\0';
 }
 
+static const char *
+print_time(unsigned long long timestamp)
+{
+       static char     timebuf[128];
+       struct tm       *tm;
+       time_t          sec;
+       unsigned long   nsec;
+
+       sec  = abs_start_time.tv_sec + SECONDS(timestamp);
+       nsec = abs_start_time.tv_nsec + NANO_SECONDS(timestamp);
+       if (nsec >= 1000000000) {
+               nsec -= 1000000000;
+               sec += 1;
+       }
+
+       tm = localtime(&sec);
+       snprintf(timebuf, sizeof(timebuf),
+                       "%02u:%02u:%02u.%06lu",
+                       tm->tm_hour,
+                       tm->tm_min,
+                       tm->tm_sec,
+                       nsec / 1000);
+       return timebuf;
+}
+
+static inline int pdu_rest_is_zero(unsigned char *pdu, int len)
+{
+       static char zero[4096];
+
+       return !memcmp(pdu, zero, len);
+}
+
 static char *dump_pdu(unsigned char *pdu_buf, int pdu_len)
 {
        static char p[4096];
@@ -92,18 +130,40 @@ static char *dump_pdu(unsigned char *pdu_buf, int pdu_len)
                        len += sprintf(p + len, " ");
 
                len += sprintf(p + len, "%02x", pdu_buf[i]);
+
+               /*
+                * usually dump for cdb dumps where we can see lots of
+                * zeroes, stop when the rest is just zeroes and indicate
+                * so with a .. appended
+                */
+               if (!pdu_buf[i] && pdu_rest_is_zero(pdu_buf + i, pdu_len - i)) {
+                       sprintf(p + len, " ..");
+                       break;
+               }
        }
 
        return p;
 }
 
+#define pdu_start(t)   (((void *) (t) + sizeof(struct blk_io_trace)))
+
 static unsigned int get_pdu_int(struct blk_io_trace *t)
 {
-       __u64 *val = (__u64 *) ((char *) t + sizeof(*t));
+       __u64 *val = pdu_start(t);
 
        return be64_to_cpu(*val);
 }
 
+static void get_pdu_remap(struct blk_io_trace *t, struct blk_io_trace_remap *r)
+{
+       struct blk_io_trace_remap *__r = pdu_start(t);
+       __u64 sector_from = __r->sector_from;
+
+       r->device_from = be32_to_cpu(__r->device_from);
+       r->device_to   = be32_to_cpu(__r->device_to);
+       r->sector_from = be64_to_cpu(sector_from);
+}
+
 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,
@@ -126,11 +186,14 @@ static void print_field(char *act, struct per_cpu_info *pci,
        case 'c':
                fprintf(ofp, strcat(format, "d"), pci->cpu);
                break;
-       case 'C':
-               fprintf(ofp, strcat(format, "s"), t->comm);
+       case 'C': {
+               char *name = find_process_name(t->pid);
+
+               fprintf(ofp, strcat(format, "s"), name);
                break;
+       }
        case 'd': {
-               char rwbs[4];
+               char rwbs[8];
 
                fill_rwbs(rwbs, t);
                fprintf(ofp, strcat(format, "s"), rwbs);
@@ -149,7 +212,7 @@ static void print_field(char *act, struct per_cpu_info *pci,
                fprintf(ofp, strcat(format, "d"), MINOR(t->device));
                break;
        case 'n':
-               fprintf(ofp, strcat(format, "u"), t->bytes >> 9);
+               fprintf(ofp, strcat(format, "u"), t_sec(t));
                break;
        case 'N':
                fprintf(ofp, strcat(format, "u"), t->bytes);
@@ -183,10 +246,12 @@ static void print_field(char *act, struct per_cpu_info *pci,
                }
                fprintf(ofp, strcat(format, "llu"), elapsed / 1000);
                break;
-       case 'U': {
+       case 'U':
                fprintf(ofp, strcat(format, "u"), get_pdu_int(t));
                break;
-       }
+       case 'z':
+               fprintf(ofp, strcat(format, "s"), print_time(t->time));
+               break;
        default:
                fprintf(ofp,strcat(format, "c"), field);
                break;
@@ -224,10 +289,21 @@ static void process_default(char *act, struct per_cpu_info *pci,
                            struct blk_io_trace *t, unsigned long long elapsed,
                            int pdu_len, unsigned char *pdu_buf)
 {
-       char rwbs[4];
+       struct blk_io_trace_remap r = { .device_from = 0, };
+       char rwbs[8];
+       char *name;
 
        fill_rwbs(rwbs, t);
 
+        /*
+         * For remaps we have to modify the device using the remap structure
+         * passed up.
+         */
+        if (act[0] == 'A') {
+                get_pdu_remap(t, &r);
+                t->device = r.device_to;
+        }
+
        /*
         * The header is always the same
         */
@@ -236,7 +312,10 @@ static void process_default(char *act, struct per_cpu_info *pci,
                (int) SECONDS(t->time), (unsigned long) NANO_SECONDS(t->time),
                t->pid, act, rwbs);
 
+       name = find_process_name(t->pid);
+
        switch (act[0]) {
+       case 'R':       /* Requeue */
        case 'C':       /* Complete */
                if (t->action & BLK_TC_ACT(BLK_TC_PC)) {
                        char *p = dump_pdu(pdu_buf, pdu_len);
@@ -245,13 +324,23 @@ static void process_default(char *act, struct per_cpu_info *pci,
                        fprintf(ofp, "[%d]\n", t->error);
                } else {
                        if (elapsed != -1ULL) {
-                               fprintf(ofp, "%llu + %u (%8llu) [%d]\n",
-                                       (unsigned long long) t->sector,
-                                       t->bytes >> 9, elapsed, t->error);
+                               if (t_sec(t))
+                                       fprintf(ofp, "%llu + %u (%8llu) [%d]\n",
+                                               (unsigned long long) t->sector,
+                                               t_sec(t), elapsed, t->error);
+                               else
+                                       fprintf(ofp, "%llu (%8llu) [%d]\n",
+                                               (unsigned long long) t->sector,
+                                               elapsed, t->error);
                        } else {
-                               fprintf(ofp, "%llu + %u [%d]\n",
-                                       (unsigned long long) t->sector,
-                                       t->bytes >> 9, t->error);
+                               if (t_sec(t))
+                                       fprintf(ofp, "%llu + %u [%d]\n",
+                                               (unsigned long long) t->sector,
+                                               t_sec(t), t->error);
+                               else
+                                       fprintf(ofp, "%llu [%d]\n",
+                                               (unsigned long long) t->sector,
+                                               t->error);
                        }
                }
                break;
@@ -259,49 +348,69 @@ static void process_default(char *act, struct per_cpu_info *pci,
        case 'D':       /* Issue */
        case 'I':       /* Insert */
        case 'Q':       /* Queue */
-       case 'W':       /* Bounce */
+       case 'B':       /* Bounce */
                if (t->action & BLK_TC_ACT(BLK_TC_PC)) {
                        char *p;
                        fprintf(ofp, "%u ", t->bytes);
                        p = dump_pdu(pdu_buf, pdu_len);
                        if (p)
                                fprintf(ofp, "(%s) ", p);
-                       fprintf(ofp, "[%s]\n", t->comm);
+                       fprintf(ofp, "[%s]\n", name);
                } else {
                        if (elapsed != -1ULL) {
-                               fprintf(ofp, "%llu + %u (%8llu) [%s]\n",
-                                       (unsigned long long) t->sector,
-                                       t->bytes >> 9, elapsed, t->comm);
+                               if (t_sec(t))
+                                       fprintf(ofp, "%llu + %u (%8llu) [%s]\n",
+                                               (unsigned long long) t->sector,
+                                               t_sec(t), elapsed, name);
+                               else
+                                       fprintf(ofp, "(%8llu) [%s]\n", elapsed,
+                                               name);
                        } else {
-                               fprintf(ofp, "%llu + %u [%s]\n",
-                                       (unsigned long long) t->sector,
-                                       t->bytes >> 9, t->comm);
+                               if (t_sec(t))
+                                       fprintf(ofp, "%llu + %u [%s]\n",
+                                               (unsigned long long) t->sector,
+                                               t_sec(t), name);
+                               else
+                                       fprintf(ofp, "[%s]\n", name);
                        }
                }
                break;
 
-       case 'B':       /* Back merge */
+       case 'M':       /* Back merge */
        case 'F':       /* Front merge */
-       case 'M':       /* Front or back merge */
        case 'G':       /* Get request */
        case 'S':       /* Sleep request */
-               fprintf(ofp, "%llu + %u [%s]\n", (unsigned long long) t->sector,
-                       t->bytes >> 9, t->comm);
+               if (t_sec(t))
+                       fprintf(ofp, "%llu + %u [%s]\n",
+                               (unsigned long long) t->sector, t_sec(t), name);
+               else
+                       fprintf(ofp, "[%s]\n", name);
                break;
 
        case 'P':       /* Plug */
-               fprintf(ofp, "[%s]\n", t->comm);
+               fprintf(ofp, "[%s]\n", name);
                break;
 
        case 'U':       /* Unplug IO */
-       case 'T': {     /* Unplug timer */
-               fprintf(ofp, "[%s] %u\n", t->comm, get_pdu_int(t));
+       case 'T':       /* Unplug timer */
+               fprintf(ofp, "[%s] %u\n", name, get_pdu_int(t));
+               break;
+
+       case 'A':       /* remap */
+               get_pdu_remap(t, &r);
+               fprintf(ofp, "%llu + %u <- (%d,%d) %llu\n",
+                       (unsigned long long) t->sector, t_sec(t),
+                       MAJOR(r.device_from), MINOR(r.device_from),
+                       (unsigned long long) r.sector_from);
                break;
-       }
 
        case 'X':       /* Split */
                fprintf(ofp, "%llu / %u [%s]\n", (unsigned long long) t->sector,
-                       get_pdu_int(t), t->comm);
+                       get_pdu_int(t), name);
+               break;
+
+       case 'm':       /* Message */
+               fprintf(ofp, "%*s\n", pdu_len, pdu_buf);
                break;
 
        default:
@@ -341,7 +450,7 @@ void process_fmt(char *act, struct per_cpu_info *pci, struct blk_io_trace *t,
                        case 'r': fprintf(ofp, "\r"); break;
                        case 't': fprintf(ofp, "\t"); break;
                        default:
-                               fprintf(stderr, 
+                               fprintf(stderr,
                                        "Invalid escape char in format %c\n",
                                        p[1]);
                                exit(1);