From 63ce251b6738df4d5b0f841f57d3b19d372fef66 Mon Sep 17 00:00:00 2001 From: Ryan Savitski Date: Mon, 19 Aug 2024 15:47:21 +0100 Subject: [PATCH] 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 | 4 +- .../importers/ftrace/ftrace_parser.cc | 20 +++++++- .../importers/ftrace/ftrace_tokenizer.cc | 14 +++-- .../parser/ftrace/ftrace_crop_tests.py | 51 +++++++++++++++++-- 4 files changed, 77 insertions(+), 12 deletions(-) diff --git a/CHANGELOG b/CHANGELOG index f61d5769ce..06e4100116 100644 --- a/CHANGELOG +++ b/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: diff --git a/src/trace_processor/importers/ftrace/ftrace_parser.cc b/src/trace_processor/importers/ftrace/ftrace_parser.cc index ae7cb306e4..95f1b76135 100644 --- a/src/trace_processor/importers/ftrace/ftrace_parser.cc +++ b/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; diff --git a/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc b/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc index 39c01aba8e..14f25c8ef9 100644 --- a/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc +++ b/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(decoder.last_read_event_timestamp()))); + ResolveTraceTime(context_, clock_id, static_cast(raw_ts))); std::optional curr_latest_timestamp = context_->metadata_tracker->GetMetadata( diff --git a/test/trace_processor/diff_tests/parser/ftrace/ftrace_crop_tests.py b/test/trace_processor/diff_tests/parser/ftrace/ftrace_crop_tests.py index d69bce723b..9863d10f7a 100644 --- a/test/trace_processor/diff_tests/parser/ftrace/ftrace_crop_tests.py +++ b/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"