[PATCH] Add timestamp support

Signed-off-by: Jens Axboe <jens.axboe@oracle.com>

diff --git a/blkparse.c b/blkparse.c
index f02934120817d7df7a00320af37973df4d621d6d..8e16c7a314c18a82ee06b8a1c2b0ab20b263f7cc 100644 (file)
--- a/blkparse.c
+++ b/blkparse.c
@@ -288,6 +288,9 @@ static int text_output = 1;
 #define is_done()      (*(volatile int *)(&done))
 static volatile int done;
 
+struct timespec                abs_start_time;
+static unsigned long long start_timestamp;
+
 #define JHASH_RANDOM   (0x3af5f2ee)
 
 #define CPUS_PER_LONG  (8 * sizeof(unsigned long))
@@ -556,6 +559,40 @@ static void add_ppm_hash(pid_t pid, const char *name)
        }
 }
 
+static void handle_notify(struct blk_io_trace *bit)
+{
+       void    *payload = (caddr_t) bit + sizeof(*bit);
+       __u32   two32[2];
+
+       switch (bit->action) {
+       case BLK_TN_PROCESS:
+               add_ppm_hash(bit->pid, payload);
+               break;
+
+       case BLK_TN_TIMESTAMP:
+               if (bit->pdu_len != sizeof(two32))
+                       return;
+               memcpy(two32, payload, sizeof(two32));
+               if (!data_is_native) {
+                       two32[0] = be32_to_cpu(two32[0]);
+                       two32[1] = be32_to_cpu(two32[1]);
+               }
+               start_timestamp = bit->time;
+               abs_start_time.tv_sec  = two32[0];
+               abs_start_time.tv_nsec = two32[1];
+               if (abs_start_time.tv_nsec < 0) {
+                       abs_start_time.tv_sec--;
+                       abs_start_time.tv_nsec += 1000000000;
+               }
+
+               break;
+
+       default:
+               /* Ignore unknown notify events */
+               ;
+       }
+}
+
 char *find_process_name(pid_t pid)
 {
        struct process_pid_map *ppm = find_ppm(pid);
@@ -1654,6 +1691,25 @@ static void find_genesis(void)
 
                t = t->next;
        }
+
+       /* The time stamp record will usually be the first
+        * record in the trace, but not always.
+        */
+       if (start_timestamp
+        && start_timestamp != genesis_time) {
+               long delta = genesis_time - start_timestamp;
+
+               abs_start_time.tv_sec  += SECONDS(delta);
+               abs_start_time.tv_nsec += NANO_SECONDS(delta);
+               if (abs_start_time.tv_nsec < 0) {
+                       abs_start_time.tv_nsec += 1000000000;
+                       abs_start_time.tv_sec -= 1;
+               } else
+               if (abs_start_time.tv_nsec > 1000000000) {
+                       abs_start_time.tv_nsec -= 1000000000;
+                       abs_start_time.tv_sec += 1;
+               }
+       }
 }
 
 static inline int check_stopwatch(struct blk_io_trace *bit)
@@ -1975,7 +2031,7 @@ static int read_events(int fd, int always_block, int *fdblock)
                 * not a real trace, so grab and handle it here
                 */
                if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY)) {
-                       add_ppm_hash(bit->pid, (char *) bit + sizeof(*bit));
+                       handle_notify(bit);
                        output_binary(bit, sizeof(*bit) + bit->pdu_len);
                        continue;
                }
@@ -2117,7 +2173,7 @@ static int ms_prime(struct ms_stream *msp)
                        goto err;
 
                if (bit->action & BLK_TC_ACT(BLK_TC_NOTIFY)) {
-                       add_ppm_hash(bit->pid, (char *) bit + sizeof(*bit));
+                       handle_notify(bit);
                        output_binary(bit, sizeof(*bit) + bit->pdu_len);
                        bit_free(bit);
 

diff --git a/blkparse_fmt.c b/blkparse_fmt.c
index f74832d8c7832f2409dd062f6d979f272e68febd..bc38114ea893f7d745035747c5ceaa42d6d91595 100644 (file)
--- a/blkparse_fmt.c
+++ b/blkparse_fmt.c
@@ -7,6 +7,7 @@
 #include <stdlib.h>
 #include <unistd.h>
 #include <ctype.h>
+#include <time.h>
 
 #include "blktrace.h"
 
@@ -85,6 +86,31 @@ static inline void fill_rwbs(char *rwbs, struct blk_io_trace *t)
        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];
@@ -221,10 +247,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;

diff --git a/blktrace.h b/blktrace.h
index cb4ee3badbbcbbc7b821baecd470a4d40cd7beff..f629314693ba740d9572c5554944c9fee147477f 100644 (file)
--- a/blktrace.h
+++ b/blktrace.h
@@ -55,6 +55,7 @@ struct per_cpu_info {
 
 extern FILE *ofp;
 extern int data_is_native;
+extern struct timespec abs_start_time;
 
 #define CHECK_MAGIC(t)         (((t)->magic & 0xffffff00) == BLK_IO_TRACE_MAGIC)
 #define SUPPORTED_VERSION      (0x07)

diff --git a/blktrace_api.h b/blktrace_api.h
index 7585eacef26cbb2e742e8a6600b32b1c862856df..61b405a25653ea77d121713f173a4ebbe245fc0c 100644 (file)
--- a/blktrace_api.h
+++ b/blktrace_api.h
@@ -48,6 +48,14 @@ enum {
        __BLK_TA_REMAP,                 /* bio was remapped */
 };
 
+/*
+ * Notify events.
+ */
+enum blktrace_notify {
+       __BLK_TN_PROCESS = 0,           /* establish pid/name mapping */
+       __BLK_TN_TIMESTAMP,             /* include system clock */
+};
+
 /*
  * Trace actions in full. Additionally, read or write is masked
  */
@@ -67,6 +75,9 @@ enum {
 #define BLK_TA_BOUNCE          (__BLK_TA_BOUNCE)
 #define BLK_TA_REMAP           (__BLK_TA_REMAP | BLK_TC_ACT(BLK_TC_QUEUE))
 
+#define BLK_TN_PROCESS         (__BLK_TN_PROCESS | BLK_TC_ACT(BLK_TC_NOTIFY))
+#define BLK_TN_TIMESTAMP       (__BLK_TN_TIMESTAMP | BLK_TC_ACT(BLK_TC_NOTIFY))
+
 #define BLK_IO_TRACE_MAGIC     0x65617400
 #define BLK_IO_TRACE_VERSION   0x07