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@xxxxxxxxxx>
the#
---
blkparse.c | 8 ++++++++
1 file changed, 8 insertions(+)
diff --git a/blkparse.c b/blkparse.c
index cf7a87b..28bdf15 100644
--- a/blkparse.c
+++ b/blkparse.c
@@ -2709,6 +2709,14 @@ static int do_file(void)
if (ms_head)
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
*/
--
2.21.0
