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>

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))