tp: recognise new field for ftrace cropping and work around b/344969928

The new timestamp is treated exactly the same as the previous one, so
the distinction is mostly for manual debugging at this point in time.

The workaround is hacky since it relies on a magical unique_session_name
field, but it is more than likely the only case where the pessimistic
cropping is relevant.

Bug: 344969928
Change-Id: I10a83f5bb8e8eb0fba90eb5b57fac565e6982f85

CHANGELOG

@@ -1,6 +1,8 @@
 Unreleased:
   Tracing service and probes:
-    *
+    * Improved accuracy of ftrace event cropping when there are multiple
+      concurrent tracing sessions. See `previous_bundle_end_timestamp` in
+      ftrace_event_bundle.proto.
   SQL Standard library:
     *
   Trace Processor:

src/trace_processor/importers/ftrace/ftrace_parser.cc

@@ -20,6 +20,7 @@
 #include "perfetto/base/logging.h"
 #include "perfetto/base/status.h"
 #include "perfetto/ext/base/string_utils.h"
+#include "perfetto/ext/base/string_view.h"
 #include "perfetto/protozero/proto_decoder.h"
 
 #include "perfetto/trace_processor/basic_types.h"
@@ -40,6 +41,7 @@
 #include "src/trace_processor/importers/proto/packet_sequence_state_generation.h"
 #include "src/trace_processor/importers/syscalls/syscall_tracker.h"
 #include "src/trace_processor/importers/systrace/systrace_parser.h"
+#include "src/trace_processor/storage/metadata.h"
 #include "src/trace_processor/storage/stats.h"
 #include "src/trace_processor/storage/trace_storage.h"
 #include "src/trace_processor/types/softirq_action.h"
@@ -1382,9 +1384,23 @@ void FtraceParser::MaybeOnFirstFtraceEvent() {
     }
   }
 
-  // Calculate the timestamp used to skip events since, while still populating
+  // Calculate the timestamp used to skip early events, while still populating
   // the |ftrace_events| table.
-  switch (context_->config.soft_drop_ftrace_data_before) {
+  SoftDropFtraceDataBefore soft_drop_before =
+      context_->config.soft_drop_ftrace_data_before;
+
+  // TODO(b/344969928): Workaround, can be removed when perfetto v47+ traces are
+  // the norm in Android.
+  base::StringView unique_session_name =
+      context_->metadata_tracker->GetMetadata(metadata::unique_session_name)
+          .value_or(SqlValue::String(""))
+          .AsString();
+  if (unique_session_name ==
+      base::StringView("session_with_lightweight_battery_tracing")) {
+    soft_drop_before = SoftDropFtraceDataBefore::kNoDrop;
+  }
+
+  switch (soft_drop_before) {
     case SoftDropFtraceDataBefore::kNoDrop: {
       soft_drop_ftrace_data_before_ts_ = 0;
       break;

src/trace_processor/importers/ftrace/ftrace_tokenizer.cc

@@ -180,14 +180,18 @@ base::Status FtraceTokenizer::TokenizeFtraceBundle(
   if (!per_cpu_seen_first_bundle_[cpu]) {
     per_cpu_seen_first_bundle_[cpu] = true;
 
-    // if this cpu's timestamp is the new max, update the metadata table entry
-    if (decoder.has_last_read_event_timestamp()) {
+    // If this cpu's timestamp is the new max, update the metadata table entry.
+    // previous_bundle_end_timestamp is the replacement for
+    // last_read_event_timestamp on perfetto v47+, at most one will be set.
+    if (decoder.has_previous_bundle_end_timestamp() ||
+        decoder.has_last_read_event_timestamp()) {
+      uint64_t raw_ts = decoder.has_previous_bundle_end_timestamp()
+                            ? decoder.previous_bundle_end_timestamp()
+                            : decoder.last_read_event_timestamp();
       int64_t timestamp = 0;
       ASSIGN_OR_RETURN(
           timestamp,
-          ResolveTraceTime(
-              context_, clock_id,
-              static_cast<int64_t>(decoder.last_read_event_timestamp())));
+          ResolveTraceTime(context_, clock_id, static_cast<int64_t>(raw_ts)));
 
       std::optional<SqlValue> curr_latest_timestamp =
           context_->metadata_tracker->GetMetadata(

test/trace_processor/diff_tests/parser/ftrace/ftrace_crop_tests.py

@@ -21,8 +21,51 @@
 class FtraceCrop(TestSuite):
 
   # Expect the first begin event on cpu1 gets suppressed as it is below the
-  # maximum of last_read_event_timestamps.
+  # maximum of previous_bundle_end_timestamps.
   def test_crop_atrace_slice(self):
+    return DiffTestBlueprint(
+        trace=TextProto(r"""
+        packet { ftrace_events {
+          cpu: 1
+          previous_bundle_end_timestamp: 1000
+          event {
+            timestamp: 1500
+            pid: 42
+            print { buf: "B|42|FilteredOut\n" }
+          }
+          event {
+            timestamp: 2700
+            pid: 42
+            print { buf: "E|42\n" }
+          }
+        }}
+        packet { ftrace_events {
+          cpu: 0
+          previous_bundle_end_timestamp: 2000
+          event {
+            timestamp: 2200
+            pid: 42
+            print { buf: "B|42|Kept\n" }
+          }
+        }}
+        """),
+        query="""
+        select
+          ts,
+          rtrim(extract_arg(raw.arg_set_id, "buf"), char(0x0a)) as raw_print,
+          slice.dur as slice_dur,
+          slice.name as slice_name
+        from raw left join slice using (ts)
+        """,
+        out=Csv("""
+        "ts","raw_print","slice_dur","slice_name"
+        1500,"B|42|FilteredOut","[NULL]","[NULL]"
+        2200,"B|42|Kept",500,"Kept"
+        2700,"E|42","[NULL]","[NULL]"
+        """))
+
+  # As test_crop_atrace_slice, with the older "last_read_event_timestamp" field
+  def test_crop_atrace_slice_legacy_field(self):
     return DiffTestBlueprint(
         trace=TextProto(r"""
         packet { ftrace_events {
@@ -66,13 +109,13 @@ def test_crop_atrace_slice(self):
 
   # First compact_switch per cpu doesn't generate any events, successive
   # switches generate a |raw| entry, but no scheduling slices until past all
-  # last_read_event_timestamps.
+  # previous_bundle_end_timestamps.
   def test_crop_compact_sched_switch(self):
     return DiffTestBlueprint(
         trace=TextProto(r"""
         packet {
           ftrace_events {
-            last_read_event_timestamp: 1000
+            previous_bundle_end_timestamp: 1000
             cpu: 3
             compact_sched {
               intern_table: "zero:3"
@@ -92,7 +135,7 @@ def test_crop_compact_sched_switch(self):
         }
         packet {
           ftrace_events {
-            last_read_event_timestamp: 0
+            previous_bundle_end_timestamp: 0
             cpu: 6
             compact_sched {
               intern_table: "zero:6"