summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
authorHiroaki Mihara <hmihara@redhat.com>2019-09-25 07:32:50 +0900
committerJens Axboe <axboe@kernel.dk>2019-09-25 00:22:13 -0600
commit918e9797772bec65d83cf6c573042fc71fd8dfbd (patch)
tree30d0c262beab3b190708dc5c941e4f4cb77d3d54
parentd025d6c67760a52e34e6c7352f33ad5dbbb4f6f4 (diff)
downloadblktrace-918e9797772bec65d83cf6c573042fc71fd8dfbd.tar.gz
blktrace-918e9797772bec65d83cf6c573042fc71fd8dfbd.tar.bz2
blkparse: fix absolute timestamp when reading from file
This patch fixes the wrong absolute timestamps when blkparse reads data from files. The blkparse command prints out wrong timestamps if all the following conditions are met, * The blkparse command reads data from files created by blktrace. * "z" format option is set as OUTPUT DESCRIPTION. ex.) blkparse xxx.blktrace.0 -f "%z\n" * start_timestamp(=blktrace command started) != genesis_time(=first I/O traced) When blkparse reads data from pipe instead, it yields correct timestamps. The root cause of this issue comes from the fact that the time difference between start_timestamp and genesis_time is not added when blkparse reads data from files. When blkparse reads data from pipe, the time-difference is added through find_genesis() function. The following test cases show the contradictions in absolute timestams. Also the Step 4 shows that the issue is fixed with the blkparse command with the suggesting patch. * Step 1: After invoking blktrace command, test I/O traffic was generated by dd command as follows, # date +%Y%m%d_%H%M%S_%N; dd if=/dev/sda3 of=/dev/null count=1 iflag=direct 20190919_092726_077032490 1+0 records in 1+0 records out 512 bytes copied, 0.00122329 s, 419 kB/s The timestamp was recorded just before executing dd command. The test I/O would have been traced right after 09:27:26.077032490 . * Step 2: The blkparse command reads data from "pipe". $ cat test.blktrace.* | blkparse - -f "%T.%t %z %C\n" 0.000000000 09:27:22.427592 kworker/0:0 0.000002080 09:27:22.427594 kworker/0:0 . . 3.652263118 09:27:26.079855 dd 3.652265818 09:27:26.079857 dd 3.652274742 09:27:26.079866 dd 3.652277266 09:27:26.079869 dd The first I/O by dd command showed the relative timestamp as 3.652263118 and the absolute timestamp as 09:27:26.079855, which is right after the timestamp shown in the Step 1. * Step 3: The blkparse command reads from the trace "file" created in the Step 1. $ blkparse test -f "%T.%t %z %C\n" Input file test.blktrace.0 added Input file test.blktrace.1 added Input file test.blktrace.2 added Input file test.blktrace.3 added 0.000000000 09:27:21.187304 kworker/0:0 0.000002080 09:27:21.187306 kworker/0:0 . . 3.652263118 09:27:24.839567 dd 3.652265818 09:27:24.839570 dd 3.652274742 09:27:24.839578 dd 3.652277266 09:27:24.839581 dd In the previous step (Step 2), the data was passed via pipe. In this case, the blkparse command reads data from the same file, instead. The first I/O by dd command showed the relative timestamp as 3.652263118 and the absolute timestamp as 09:27:24.839567, which is a few seconds earlier than the absolute timestamp recorded in the Step 1. The order of events and the absolute timestamps contradict. * Step 4: The blkparse command with the suggesting patch (./blkparse_with_patch) reads data from the trace file created in the Step 1. $ ./blkparse_with_patch test -f "%T.%t %z %C\n" Input file test.blktrace.0 added Input file test.blktrace.1 added Input file test.blktrace.2 added Input file test.blktrace.3 added 0.000000000 09:27:22.427592 kworker/0:0 0.000002080 09:27:22.427594 kworker/0:0 . . 3.652263118 09:27:26.079855 dd 3.652265818 09:27:26.079857 dd 3.652274742 09:27:26.079866 dd 3.652277266 09:27:26.079869 dd In this case, the absolute timestamps showed the same value as shown in the Step 2(the case with pipe). The time gap between the genesis_ time and the start_timestamp was corrected even if the blkparse reads data from files. Signed-off-by: Hiroaki Mihara <hmihara@redhat.com> the# Signed-off-by: Jens Axboe <axboe@kernel.dk>
-rw-r--r--blkparse.c8
1 files changed, 8 insertions, 0 deletions
diff --git a/blkparse.c b/blkparse.c
index cf7a87b..28bdf15 100644
--- a/blkparse.c
+++ b/blkparse.c
@@ -2710,6 +2710,14 @@ static int do_file(void)
genesis_time = ms_peek_time(ms_head);
/*
+ * Correct abs_start_time if necessary
+ */
+ if (start_timestamp
+ && start_timestamp != genesis_time) {
+ correct_abs_start_time();
+ }
+
+ /*
* Keep processing traces while any are left
*/
while (!is_done() && ms_head && handle(ms_head))