ftrace: fix erroneous parsing of absolute timestamps (RINGBUF_TYPE_TIME_STAMP) on 4.17+ kernels

Historically, absolute timestamps were partially implemented in the
kernel, but not written in practice. Starting with 4.17, the kernel has
reimplemented this record type. The crucial difference is that the
record was downsized (16 -> 8 bytes), while traced_probes still assumes
the historical size and layout (in retrospect, we should've errored upon
encountering this record type, instead of swallowing the bytes).

So currently, traced_probes reads too many bytes when seeing this
record, and the rest of the parsing for that tracing page is
nonsensical, as we're no longer aligned to a valid event boundary. The
most likely scenario is that we discard the rest of the tracing page due
to invalid parsing, but in theory we can also produce bogus events if
they just happen to parse correctly. Note that none of these effects
should persist beyond the tracing page, so the rest of the trace would
still look correct.

This patch adds proper parsing for such absolute timestamps, per their
modern layout. The format is identical to the time extension record
(KBUFFER_TYPE_TIME_EXTEND), except that the combined timestamp is
treated as a new baseline, instead of a delta on top of the previous
accumulated timestamp.

An another fault of ours is never following up on a TODO to put event
parsing failures into the ftrace stats, as it would've detected this
issue. Let's fix that in a follow-up.

[1] https://github.com/torvalds/linux/commit/dc4e2801d400b0346fb281ce9cf010d611e2243c

Bug: 191160035
(cherry picked from commit 61a85c29cb94835c8313ce4374ecbb00d54d0c29)
Change-Id: Idf49660b3f3d32f7b3073ddf0bec78cdbff48bb1
Merged-In: Idf49660b3f3d32f7b3073ddf0bec78cdbff48bb1

2 files changed, 257 insertions, 9 deletions

diff --git a/src/traced/probes/ftrace/cpu_reader.cc b/src/traced/probes/ftrace/cpu_reader.cc
index a6a6f6eae..9b1d4f878 100644
--- a/src/traced/probes/ftrace/cpu_reader.cc
+++ b/src/traced/probes/ftrace/cpu_reader.cc
@@ -509,7 +509,7 @@ size_t CpuReader::ParsePagePayload(const uint8_t* start_of_payload,
           PERFETTO_DFATAL("Empty padding event.");
           return 0;
         }
-        uint32_t length;
+        uint32_t length = 0;
         if (!ReadAndAdvance<uint32_t>(&ptr, end, &length))
           return 0;
         // length includes itself (4 bytes)
@@ -520,20 +520,23 @@ size_t CpuReader::ParsePagePayload(const uint8_t* start_of_payload,
       }
       case kTypeTimeExtend: {
         // Extend the time delta.
-        uint32_t time_delta_ext;
+        uint32_t time_delta_ext = 0;
         if (!ReadAndAdvance<uint32_t>(&ptr, end, &time_delta_ext))
           return 0;
-        // See https://goo.gl/CFBu5x
         timestamp += (static_cast<uint64_t>(time_delta_ext)) << 27;
         break;
       }
       case kTypeTimeStamp: {
-        // Sync time stamp with external clock.
-        TimeStamp time_stamp;
-        if (!ReadAndAdvance<TimeStamp>(&ptr, end, &time_stamp))
+        // Absolute timestamp. This was historically partially implemented, but
+        // not written. Kernels 4.17+ reimplemented this record, changing its
+        // size in the process. We assume the newer layout. Parsed the same as
+        // kTypeTimeExtend, except that the timestamp is interpreted as an
+        // absolute, instead of a delta on top of the previous state.
+        timestamp = event_header.time_delta;
+        uint32_t time_delta_ext = 0;
+        if (!ReadAndAdvance<uint32_t>(&ptr, end, &time_delta_ext))
           return 0;
-        // Not implemented in the kernel, nothing should generate this.
-        PERFETTO_DFATAL("Unimplemented in kernel. Should be unreachable.");
+        timestamp += (static_cast<uint64_t>(time_delta_ext)) << 27;
         break;
       }
       // Data record:
@@ -543,7 +546,7 @@ size_t CpuReader::ParsePagePayload(const uint8_t* start_of_payload,
         // record. if == 0, this is an extended record and the size of the
         // record is stored in the first uint32_t word in the payload. See
         // Kernel's include/linux/ring_buffer.h
-        uint32_t event_size;
+        uint32_t event_size = 0;
         if (event_header.type_or_length == 0) {
           if (!ReadAndAdvance<uint32_t>(&ptr, end, &event_size))
             return 0;
diff --git a/src/traced/probes/ftrace/cpu_reader_unittest.cc b/src/traced/probes/ftrace/cpu_reader_unittest.cc
index 688dd7cdf..dd596efc5 100644
--- a/src/traced/probes/ftrace/cpu_reader_unittest.cc
+++ b/src/traced/probes/ftrace/cpu_reader_unittest.cc
@@ -1202,6 +1202,251 @@ TEST(CpuReaderTest, NewPacketOnLostEvents) {
   EXPECT_EQ(4u, packets[2].ftrace_events().event().size());
 }
 
+// Page containing an absolute timestamp (RINGBUF_TYPE_TIME_STAMP).
+static char g_abs_timestamp[] =
+    R"(
+00000000: 8949 fbfb 38e4 0400 6407 0000 0000 0000  .I..8...d.......
+00000010: 5032 0a2d 3b01 0100 0000 0000 7377 6170  P2.-;.......swap
+00000020: 7065 722f 3000 0000 0000 0000 0000 0000  per/0...........
+00000030: 7800 0000 0000 0000 0000 0000 6776 6673  x...........gvfs
+00000040: 2d61 6663 2d76 6f6c 756d 6500 6483 0000  -afc-volume.d...
+00000050: 7800 0000 f0de 1700 3b01 0100 6483 0000  x.......;...d...
+00000060: 6776 6673 2d61 6663 2d76 6f6c 756d 6500  gvfs-afc-volume.
+00000070: 6483 0000 7800 0000 0100 0000 0000 0000  d...x...........
+00000080: 7377 6170 7065 722f 3000 0000 0000 0000  swapper/0.......
+00000090: 0000 0000 7800 0000 aaa1 5c08 0401 1100  ....x.....\.....
+000000a0: 0000 0000 88fc 31eb 029f ffff 609e d3c0  ......1.....`...
+000000b0: ffff ffff 0076 b4a1 029f ffff 0020 0000  .....v....... ..
+000000c0: ffff ffff e477 1700 0301 1100 0000 0000  .....w..........
+000000d0: 88fc 31eb 029f ffff aa26 0100 3e01 1100  ..1......&..>...
+000000e0: 0000 0000 6b77 6f72 6b65 722f 7538 3a35  ....kworker/u8:5
+000000f0: 0000 0000 24c0 0c00 7800 0000 0100 0000  ....$...x.......
+00000100: 0300 0000 90e6 e700 3b01 0100 0000 0000  ........;.......
+00000110: 7377 6170 7065 722f 3000 0000 0000 0000  swapper/0.......
+00000120: 0000 0000 7800 0000 0000 0000 0000 0000  ....x...........
+00000130: 6b77 6f72 6b65 722f 7538 3a35 0000 0000  kworker/u8:5....
+00000140: 24c0 0c00 7800 0000 aa56 0300 3e01 0100  $...x....V..>...
+00000150: 24c0 0c00 6b77 6f72 6b65 722f 7538 3a31  $...kworker/u8:1
+00000160: 0000 0000 8eb5 0c00 7800 0000 0100 0000  ........x.......
+00000170: 0300 0000 06eb 0300 0201 0000 24c0 0c00  ............$...
+00000180: 6026 f22a 049f ffff f0e4 4cc0 ffff ffff  `&.*......L.....
+00000190: ca45 0f00 3e01 0100 24c0 0c00 646d 6372  .E..>...$...dmcr
+000001a0: 7970 745f 7772 6974 652f 3200 2601 0000  ypt_write/2.&...
+000001b0: 7800 0000 0100 0000 0100 0000 c617 0200  x...............
+000001c0: 0101 0000 24c0 0c00 6026 f22a 049f ffff  ....$...`&.*....
+000001d0: f0e4 4cc0 ffff ffff a47c 0000 0301 0100  ..L......|......
+000001e0: 24c0 0c00 6015 f22a 049f ffff 0685 0000  $...`..*........
+000001f0: 0201 0000 24c0 0c00 a05d f22a 049f ffff  ....$....].*....
+00000200: f0e4 4cc0 ffff ffff c6dd 0800 0101 0000  ..L.............
+00000210: 24c0 0c00 a05d f22a 049f ffff f0e4 4cc0  $....].*......L.
+00000220: ffff ffff 8444 0000 0301 0100 24c0 0c00  .....D......$...
+00000230: 6059 f22a 049f ffff e672 0000 0201 0000  `Y.*.....r......
+00000240: 24c0 0c00 e050 f22a 049f ffff f0e4 4cc0  $....P.*......L.
+00000250: ffff ffff 4673 0a00 0101 0000 24c0 0c00  ....Fs......$...
+00000260: e050 f22a 049f ffff f0e4 4cc0 ffff ffff  .P.*......L.....
+00000270: 04ca 0000 0301 0100 24c0 0c00 2000 f22a  ........$... ..*
+00000280: 049f ffff 86b1 0000 0201 0000 24c0 0c00  ............$...
+00000290: 6015 f22a 049f ffff f0e4 4cc0 ffff ffff  `..*......L.....
+000002a0: e640 0c00 0101 0000 24c0 0c00 6015 f22a  .@......$...`..*
+000002b0: 049f ffff f0e4 4cc0 ffff ffff 64b4 0000  ......L.....d...
+000002c0: 0301 0100 24c0 0c00 2011 f22a 049f ffff  ....$... ..*....
+000002d0: 66b9 0000 0201 0000 24c0 0c00 a06e f22a  f.......$....n.*
+000002e0: 049f ffff f0e4 4cc0 ffff ffff 6ae1 4200  ......L.....j.B.
+000002f0: 3e01 1100 24c0 0c00 6a62 6432 2f64 6d2d  >...$...jbd2/dm-
+00000300: 312d 3800 0000 0000 6a01 0000 7800 0000  1-8.....j...x...
+00000310: 0100 0000 0300 0000 269b 0400 0101 0000  ........&.......
+00000320: 24c0 0c00 a06e f22a 049f ffff f0e4 4cc0  $....n.*......L.
+00000330: ffff ffff ff9d 6fb6 1f87 9c00 1000 0000  ......o.........
+00000340: 3b01 0100 24c0 0c00 6b77 6f72 6b65 722f  ;...$...kworker/
+00000350: 7538 3a35 0000 0000 24c0 0c00 7800 0000  u8:5....$...x...
+00000360: 8000 0000 0000 0000 7377 6170 7065 722f  ........swapper/
+00000370: 3000 0000 0000 0000 0000 0000 7800 0000  0...........x...
+00000380: 6ad2 3802 0401 1100 0000 0000 c800 384b  j.8...........8K
+00000390: 029f ffff 7018 75c0 ffff ffff 00ac edce  ....p.u.........
+000003a0: 039f ffff 0020 0000 0000 0000 c4de 0000  ..... ..........
+000003b0: 0301 1100 0000 0000 c800 384b 029f ffff  ..........8K....
+000003c0: 8a27 0100 3e01 1100 0000 0000 6b77 6f72  .'..>.......kwor
+000003d0: 6b65 722f 303a 3200 0000 0000 48b4 0c00  ker/0:2.....H...
+000003e0: 7800 0000 0100 0000 0000 0000 706d 0800  x...........pm..
+000003f0: 3b01 0100 0000 0000 7377 6170 7065 722f  ;.......swapper/
+00000400: 3000 0000 0000 0000 0000 0000 7800 0000  0...........x...
+00000410: 0000 0000 0000 0000 6b77 6f72 6b65 722f  ........kworker/
+00000420: 303a 3200 0000 0000 48b4 0c00 7800 0000  0:2.....H...x...
+00000430: 4636 0200 0201 0000 48b4 0c00 c800 384b  F6......H.....8K
+00000440: 029f ffff 7018 75c0 ffff ffff ca56 0500  ....p.u......V..
+00000450: 0401 0100 48b4 0c00 606a ad55 029f ffff  ....H...`j.U....
+00000460: f0e4 4cc0 ffff ffff 002c 04d0 039f ffff  ..L......,......
+00000470: 0020 0000 ffff ffff e435 0000 0301 0100  . .......5......
+00000480: 48b4 0c00 606a ad55 029f ffff ca67 0000  H...`j.U.....g..
+00000490: 3e01 0100 48b4 0c00 6b77 6f72 6b65 722f  >...H...kworker/
+000004a0: 7538 3a35 0000 0000 24c0 0c00 7800 0000  u8:5....$...x...
+000004b0: 0100 0000 0000 0000 e6fc 0200 0101 0000  ................
+000004c0: 48b4 0c00 c800 384b 029f ffff 7018 75c0  H.....8K....p.u.
+000004d0: ffff ffff 708f 0200 3b01 0100 48b4 0c00  ....p...;...H...
+000004e0: 6b77 6f72 6b65 722f 303a 3200 0000 0000  kworker/0:2.....
+000004f0: 48b4 0c00 7800 0000 8000 0000 0000 0000  H...x...........
+00000500: 6b77 6f72 6b65 722f 7538 3a35 0000 0000  kworker/u8:5....
+00000510: 24c0 0c00 7800 0000 0614 0100 0201 0000  $...x...........
+00000520: 24c0 0c00 606a ad55 029f ffff f0e4 4cc0  $...`j.U......L.
+00000530: ffff ffff ea7e 0c00 3e01 0100 24c0 0c00  .....~..>...$...
+00000540: 646d 6372 7970 745f 7772 6974 652f 3200  dmcrypt_write/2.
+00000550: 2601 0000 7800 0000 0100 0000 0100 0000  &...x...........
+00000560: 4645 0200 0101 0000 24c0 0c00 606a ad55  FE......$...`j.U
+00000570: 029f ffff f0e4 4cc0 ffff ffff b043 0900  ......L......C..
+00000580: 3b01 0100 24c0 0c00 6b77 6f72 6b65 722f  ;...$...kworker/
+00000590: 7538 3a35 0000 0000 24c0 0c00 7800 0000  u8:5....$...x...
+000005a0: 8000 0000 0000 0000 7377 6170 7065 722f  ........swapper/
+000005b0: 3000 0000 0000 0000 0000 0000 7800 0000  0...........x...
+000005c0: ca7a 3900 0401 1100 0000 0000 48bc d5a1  .z9.........H...
+000005d0: 029f ffff 10e2 62bb ffff ffff 00e0 40d0  ......b.......@.
+000005e0: 039f ffff 0020 0000 0000 0000 c4bb 0000  ..... ..........
+000005f0: 0301 1100 0000 0000 48bc d5a1 029f ffff  ........H.......
+00000600: 2aea 0000 3e01 1100 0000 0000 6b77 6f72  *...>.......kwor
+00000610: 6b65 722f 303a 3148 0000 0000 cfc1 0c00  ker/0:1H........
+00000620: 6400 0000 0100 0000 0000 0000 90bb 0600  d...............
+00000630: 3b01 0100 0000 0000 7377 6170 7065 722f  ;.......swapper/
+00000640: 3000 0000 0000 0000 0000 0000 7800 0000  0...........x...
+00000650: 0000 0000 0000 0000 6b77 6f72 6b65 722f  ........kworker/
+00000660: 303a 3148 0000 0000 cfc1 0c00 6400 0000  0:1H........d...
+00000670: 8617 0200 0201 0000 cfc1 0c00 48bc d5a1  ............H...
+00000680: 029f ffff 10e2 62bb ffff ffff c68f 0400  ......b.........
+00000690: 0101 0000 cfc1 0c00 48bc d5a1 029f ffff  ........H.......
+000006a0: 10e2 62bb ffff ffff b063 0300 3b01 0100  ..b......c..;...
+000006b0: cfc1 0c00 6b77 6f72 6b65 722f 303a 3148  ....kworker/0:1H
+000006c0: 0000 0000 cfc1 0c00 6400 0000 8000 0000  ........d.......
+000006d0: 0000 0000 7377 6170 7065 722f 3000 0000  ....swapper/0...
+000006e0: 0000 0000 0000 0000 7800 0000 4a10 ad01  ........x...J...
+000006f0: 3e01 1100 0000 0000 6a62 6432 2f64 6d2d  >.......jbd2/dm-
+00000700: 312d 3800 0000 0000 6a01 0000 7800 0000  1-8.....j...x...
+00000710: 0100 0000 0300 0000 ea27 b900 3e01 1100  .........'..>...
+00000720: 0000 0000 7263 755f 7363 6865 6400 0000  ....rcu_sched...
+00000730: 0000 0000 0d00 0000 7800 0000 0100 0000  ........x.......
+00000740: 0200 0000 3d00 0000 2c00 0000 0000 0000  ....=...,.......
+00000750: 0000 0000 0000 0000 0000 0000 0000 0000  ................
+00000760: 0000 0000 0000 0000 0000 0000 0000 0000  ................
+00000770: 0000 0000 0000 0000 0000 0000 0000 0000  ................
+  )";
+
+TEST(CpuReaderTest, ParseAbsoluteTimestamp) {
+  BundleProvider bundle_provider(base::kPageSize);
+  auto page = PageFromXxd(g_abs_timestamp);
+
+  // Hand-build a translation table that handles sched_switch for this test
+  // page. We cannot reuse the test data format file, since the ftrace id for
+  // sched_switch in this page is different.
+  std::vector<Field> common_fields;
+  {  // common_pid
+    common_fields.emplace_back(Field{});
+    Field* field = &common_fields.back();
+    field->ftrace_offset = 4;
+    field->ftrace_size = 4;
+    field->ftrace_type = kFtraceCommonPid32;
+    field->proto_field_id = 2;
+    field->proto_field_type = ProtoSchemaType::kInt32;
+    SetTranslationStrategy(field->ftrace_type, field->proto_field_type,
+                           &field->strategy);
+  }
+  Event sched_switch_event{
+      "sched_switch",
+      "sched",
+      {
+          {8, 16, FtraceFieldType::kFtraceFixedCString, "prev_comm", 1,
+           ProtoSchemaType::kString,
+           TranslationStrategy::kInvalidTranslationStrategy},
+          {24, 4, FtraceFieldType::kFtracePid32, "prev_pid", 2,
+           ProtoSchemaType::kInt32,
+           TranslationStrategy::kInvalidTranslationStrategy},
+          {28, 4, FtraceFieldType::kFtraceInt32, "prev_prio", 3,
+           ProtoSchemaType::kInt32,
+           TranslationStrategy::kInvalidTranslationStrategy},
+          {32, 8, FtraceFieldType::kFtraceInt64, "prev_state", 4,
+           ProtoSchemaType::kInt64,
+           TranslationStrategy::kInvalidTranslationStrategy},
+          {40, 16, FtraceFieldType::kFtraceFixedCString, "next_comm", 5,
+           ProtoSchemaType::kString,
+           TranslationStrategy::kInvalidTranslationStrategy},
+          {56, 4, FtraceFieldType::kFtracePid32, "next_pid", 6,
+           ProtoSchemaType::kInt32,
+           TranslationStrategy::kInvalidTranslationStrategy},
+          {60, 4, FtraceFieldType::kFtraceInt32, "next_prio", 7,
+           ProtoSchemaType::kInt32,
+           TranslationStrategy::kInvalidTranslationStrategy},
+      },
+      /*ftrace_event_id=*/315,
+      /*proto_field_id=*/4,
+      /*size=*/64};
+  for (Field& field : sched_switch_event.fields) {
+    SetTranslationStrategy(field.ftrace_type, field.proto_field_type,
+                           &field.strategy);
+  }
+  std::vector<Event> events;
+  events.emplace_back(std::move(sched_switch_event));
+
+  NiceMock<MockFtraceProcfs> mock_ftrace;
+  PrintkMap printk_formats;
+  ProtoTranslationTable translation_table(
+      &mock_ftrace, events, std::move(common_fields),
+      ProtoTranslationTable::DefaultPageHeaderSpecForTesting(),
+      InvalidCompactSchedEventFormatForTesting(), printk_formats);
+  ProtoTranslationTable* table = &translation_table;
+
+  FtraceDataSourceConfig ds_config = EmptyConfig();
+  ds_config.event_filter.AddEnabledEvent(
+      table->EventToFtraceId(GroupAndName("sched", "sched_switch")));
+
+  FtraceMetadata metadata{};
+  CompactSchedBuffer compact_buffer;
+  const uint8_t* parse_pos = page.get();
+  base::Optional<CpuReader::PageHeader> page_header =
+      CpuReader::ParsePageHeader(&parse_pos, table->page_header_size_len());
+
+  const uint8_t* page_end = page.get() + base::kPageSize;
+  ASSERT_TRUE(page_header.has_value());
+  EXPECT_FALSE(page_header->lost_events);
+  EXPECT_TRUE(parse_pos < page_end);
+  EXPECT_TRUE(parse_pos + page_header->size < page_end);
+
+  size_t evt_bytes = CpuReader::ParsePagePayload(
+      parse_pos, &page_header.value(), table, &ds_config, &compact_buffer,
+      bundle_provider.writer(), &metadata);
+
+  ASSERT_LT(0u, evt_bytes);
+
+  auto bundle = bundle_provider.ParseProto();
+  ASSERT_TRUE(bundle);
+
+  // There should be 9 sched_switch events within the above page.
+  // We assert that all of their timestamps are exactly as expected.
+  //
+  // The key record that we're testing is an absolute timestamp
+  // (RINGBUF_TYPE_TIME_STAMP) between the 3rd and 4th sched_switch events.
+  //
+  // This timestamp record starts at 0x334 bytes into the page.
+  // The event header (first 4 bytes): 0xb66f9dff
+  // -> type (bottom 5 bits): 31 (RINGBUF_TYPE_TIME_STAMP)
+  // -> bottom 27 bits of ts: 0x5b37cef
+  // Next 4 bytes have the top bits (28..59) of ts.
+  // -> post-shift: 0x4e438f8000000
+  // Adding the two parts of the timestamp, we get: 1376833332542703.
+  //
+  // The next event (sched_switch at 0x33c) after this timestamp has a
+  // delta-timestamp of 0 in its event header, so we expect the 4th
+  // sched_switch to have a timestamp of exactly 1376833332542703.
+  EXPECT_EQ(bundle->event().size(), 9u);
+
+  std::vector<uint64_t> switch_timestamps;
+  for (const auto& e : bundle->event())
+    switch_timestamps.push_back(e.timestamp());
+
+  uint64_t expected_timestamps[] = {
+      1376833327307547ull, 1376833327356434ull, 1376833332265799ull,
+      1376833332542703ull, 1376833333729055ull, 1376833333757142ull,
+      1376833333808564ull, 1376833333943445ull, 1376833333964012ull};
+
+  ASSERT_THAT(switch_timestamps,
+              testing::ElementsAreArray(expected_timestamps));
+}
+
 TEST(CpuReaderTest, TranslateBlockDeviceIDToUserspace) {
   const uint32_t kKernelBlockDeviceId = 271581216;
   const BlockDeviceID kUserspaceBlockDeviceId = 66336;