From mboxrd@z Thu Jan 1 00:00:00 1970 From: Hiroaki Mihara Date: Tue, 24 Sep 2019 22:32:50 +0000 Subject: [PATCH 2/3] blkparse: fix absolute timestamp when reading from file Message-Id: <20190924223250.20185-1-hmihara@redhat.com> List-Id: MIME-Version: 1.0 Content-Type: text/plain; charset="us-ascii" Content-Transfer-Encoding: 7bit To: linux-btrace@vger.kernel.org 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 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