From 7bd4fd0a4fca645bb50a641afac1e460a4e32dfd Mon Sep 17 00:00:00 2001 From: Olaf Kirch Date: Fri, 1 Dec 2006 10:34:11 +0100 Subject: [PATCH] [PATCH] Add timestamp support Signed-off-by: Jens Axboe --- blkparse.c | 60 ++++++++++++++++++++++++++++++++++++++++++++++++-- blkparse_fmt.c | 32 +++++++++++++++++++++++++-- blktrace.h | 1 + blktrace_api.h | 11 +++++++++ 4 files changed, 100 insertions(+), 4 deletions(-) diff --git a/blkparse.c b/blkparse.c index f029341..8e16c7a 100644 --- 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 f74832d..bc38114 100644 --- a/blkparse_fmt.c +++ b/blkparse_fmt.c @@ -7,6 +7,7 @@ #include #include #include +#include #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 cb4ee3b..f629314 100644 --- 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 7585eac..61b405a 100644 --- 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 -- 2.25.1