f833623b17
blktrace: backport upstream bugfix patches Signed-off-by: Zhiqiang Liu <liuzhiqiang26@huawei.com>
137 lines
4.3 KiB
Diff
137 lines
4.3 KiB
Diff
From 985aa086d949963717d4f730f14eeb8cafd789da Mon Sep 17 00:00:00 2001
|
|
From: Hiroaki Mihara <hmihara@redhat.com>
|
|
Date: Wed, 25 Sep 2019 07:32:50 +0900
|
|
Subject: [PATCH 11/15] 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>
|
|
---
|
|
blkparse.c | 8 ++++++++
|
|
1 file changed, 8 insertions(+)
|
|
|
|
diff --git a/blkparse.c b/blkparse.c
|
|
index fb540ee..08c9f60 100644
|
|
--- a/blkparse.c
|
|
+++ b/blkparse.c
|
|
@@ -2608,6 +2608,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))
|
|
--
|
|
1.8.3.1
|
|
|