[PATCH 2/3] blkparse: fix absolute timestamp when reading from file

[PATCH 2/3] blkparse: fix absolute timestamp when reading from file

[Hiroaki Mihara]

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