tp: parse tracing_started event and drop ftrace packets before it
ftrace can occasionally be buggy and may lead to events being included
in the trace from well before the tracing started. Until now we've just
included these events in the trace even though they really shouldn't be.
This CL introduces parsing of the tracing_started TraceServiceEvent
which gives the timestamp where tracing started (before any producer
is informed of tracing being ready).
We then use this timestamp and filter out all events before it. This
filtering is restricted to ftrace only as it's the only data source
fully under our control - if other producers want to write data from
before trace start, that's their choice.
Bug: 154156099
Change-Id: I8be103d091cd13c85a695688ae7e13c852b93e25
diff --git a/src/trace_processor/export_json.cc b/src/trace_processor/export_json.cc
index c9dc1b3..649b7da 100644
--- a/src/trace_processor/export_json.cc
+++ b/src/trace_processor/export_json.cc
@@ -1197,16 +1197,16 @@
const auto& str_values = trace_metadata.str_value();
// Create a mapping from key string ids to keys.
- std::unordered_map<StringId, metadata::KeyIDs> key_map;
+ std::unordered_map<StringId, metadata::KeyId> key_map;
for (uint32_t i = 0; i < metadata::kNumKeys; ++i) {
auto id = *storage_->string_pool().GetId(metadata::kNames[i]);
- key_map[id] = static_cast<metadata::KeyIDs>(i);
+ key_map[id] = static_cast<metadata::KeyId>(i);
}
for (uint32_t pos = 0; pos < trace_metadata.row_count(); pos++) {
// Cast away from enum type, as otherwise -Wswitch-enum will demand an
// exhaustive list of cases, even if there's a default case.
- metadata::KeyIDs key = key_map[keys[pos]];
+ metadata::KeyId key = key_map[keys[pos]];
switch (static_cast<size_t>(key)) {
case metadata::benchmark_description:
writer_.AppendTelemetryMetadataString(
diff --git a/src/trace_processor/importers/ftrace/ftrace_parser.cc b/src/trace_processor/importers/ftrace/ftrace_parser.cc
index ec10e52..d272cb7 100644
--- a/src/trace_processor/importers/ftrace/ftrace_parser.cc
+++ b/src/trace_processor/importers/ftrace/ftrace_parser.cc
@@ -205,8 +205,28 @@
PERFETTO_ALWAYS_INLINE
util::Status FtraceParser::ParseFtraceEvent(uint32_t cpu,
const TimestampedTracePiece& ttp) {
- using protos::pbzero::FtraceEvent;
int64_t ts = ttp.timestamp;
+
+ // On the first ftrace packet, check the metadata table for the tracing start
+ // ts. If it exists we can use it to filter out ftrace packets which happen
+ // earlier than it.
+ if (PERFETTO_UNLIKELY(!has_seen_first_ftrace_packet_)) {
+ const auto& metadata = context_->storage->metadata_table();
+ base::Optional<uint32_t> opt_row =
+ metadata.name().IndexOf(metadata::kNames[metadata::tracing_started_ns]);
+ if (opt_row) {
+ tracing_start_ts_ = *metadata.int_value()[*opt_row];
+ }
+ has_seen_first_ftrace_packet_ = true;
+ }
+
+ if (PERFETTO_UNLIKELY(ts < tracing_start_ts_)) {
+ context_->storage->IncrementStats(
+ stats::ftrace_packet_before_tracing_start);
+ return util::OkStatus();
+ }
+
+ using protos::pbzero::FtraceEvent;
SchedEventTracker* sched_tracker = SchedEventTracker::GetOrCreate(context_);
// Handle the (optional) alternative encoding format for sched_switch.
diff --git a/src/trace_processor/importers/ftrace/ftrace_parser.h b/src/trace_processor/importers/ftrace/ftrace_parser.h
index 55f44d2..199e377 100644
--- a/src/trace_processor/importers/ftrace/ftrace_parser.h
+++ b/src/trace_processor/importers/ftrace/ftrace_parser.h
@@ -168,6 +168,13 @@
// Keep kMmEventCounterSize equal to mm_event_type::MM_TYPE_NUM in the kernel.
static constexpr size_t kMmEventCounterSize = 7;
std::array<MmEventCounterNames, kMmEventCounterSize> mm_event_counter_names_;
+
+ bool has_seen_first_ftrace_packet_ = false;
+
+ // Stores information about the "tracing_start" timestamp from the metadata
+ // table which is used to filter ftrace packets which happen before this
+ // point.
+ int64_t tracing_start_ts_ = 0;
};
} // namespace trace_processor
diff --git a/src/trace_processor/importers/proto/metadata_tracker.cc b/src/trace_processor/importers/proto/metadata_tracker.cc
index 757ac1a..0162392 100644
--- a/src/trace_processor/importers/proto/metadata_tracker.cc
+++ b/src/trace_processor/importers/proto/metadata_tracker.cc
@@ -33,7 +33,7 @@
}
}
-MetadataId MetadataTracker::SetMetadata(metadata::KeyIDs key, Variadic value) {
+MetadataId MetadataTracker::SetMetadata(metadata::KeyId key, Variadic value) {
PERFETTO_DCHECK(metadata::kKeyTypes[key] == metadata::KeyType::kSingle);
PERFETTO_DCHECK(value.type == metadata::kValueTypes[key]);
@@ -55,7 +55,7 @@
return id_and_row.id;
}
-MetadataId MetadataTracker::AppendMetadata(metadata::KeyIDs key,
+MetadataId MetadataTracker::AppendMetadata(metadata::KeyId key,
Variadic value) {
PERFETTO_DCHECK(key < metadata::kNumKeys);
PERFETTO_DCHECK(metadata::kKeyTypes[key] == metadata::KeyType::kMulti);
diff --git a/src/trace_processor/importers/proto/metadata_tracker.h b/src/trace_processor/importers/proto/metadata_tracker.h
index b2ecda3..fc8bba2 100644
--- a/src/trace_processor/importers/proto/metadata_tracker.h
+++ b/src/trace_processor/importers/proto/metadata_tracker.h
@@ -33,17 +33,17 @@
// SetMetadata(metadata::benchmark_name,
// Variadic::String(storage->InternString("foo"));
// Returns the id of the new entry.
- MetadataId SetMetadata(metadata::KeyIDs key, Variadic value);
+ MetadataId SetMetadata(metadata::KeyId key, Variadic value);
// Example usage:
// AppendMetadata(metadata::benchmark_story_tags,
// Variadic::String(storage->InternString("bar"));
// Returns the id of the new entry.
- MetadataId AppendMetadata(metadata::KeyIDs key, Variadic value);
+ MetadataId AppendMetadata(metadata::KeyId key, Variadic value);
private:
static constexpr size_t kNumKeys =
- static_cast<size_t>(metadata::KeyIDs::kNumKeys);
+ static_cast<size_t>(metadata::KeyId::kNumKeys);
static constexpr size_t kNumKeyTypes =
static_cast<size_t>(metadata::KeyType::kNumKeyTypes);
diff --git a/src/trace_processor/importers/proto/proto_trace_parser.cc b/src/trace_processor/importers/proto/proto_trace_parser.cc
index efca5a4..1184aea 100644
--- a/src/trace_processor/importers/proto/proto_trace_parser.cc
+++ b/src/trace_processor/importers/proto/proto_trace_parser.cc
@@ -53,7 +53,6 @@
#include "protos/perfetto/trace/chrome/chrome_trace_event.pbzero.h"
#include "protos/perfetto/trace/interned_data/interned_data.pbzero.h"
#include "protos/perfetto/trace/perfetto/perfetto_metatrace.pbzero.h"
-#include "protos/perfetto/trace/perfetto/tracing_service_event.pbzero.h"
#include "protos/perfetto/trace/profiling/profile_common.pbzero.h"
#include "protos/perfetto/trace/profiling/profile_packet.pbzero.h"
#include "protos/perfetto/trace/profiling/smaps.pbzero.h"
@@ -154,10 +153,6 @@
ParseTrigger(ts, packet.trigger());
}
- if (packet.has_service_event()) {
- ParseServiceEvent(ts, packet.service_event());
- }
-
if (packet.has_smaps_packet()) {
ParseSmapsPacket(ts, packet.smaps_packet());
}
@@ -740,14 +735,6 @@
});
}
-void ProtoTraceParser::ParseServiceEvent(int64_t ts, ConstBytes blob) {
- protos::pbzero::TracingServiceEvent::Decoder tse(blob.data, blob.size);
- if (tse.all_data_sources_started()) {
- context_->metadata_tracker->SetMetadata(
- metadata::all_data_source_started_ns, Variadic::Integer(ts));
- }
-}
-
void ProtoTraceParser::ParseSmapsPacket(int64_t ts, ConstBytes blob) {
protos::pbzero::SmapsPacket::Decoder sp(blob.data, blob.size);
auto upid = context_->process_tracker->GetOrCreateProcess(sp.pid());
diff --git a/src/trace_processor/importers/proto/proto_trace_parser.h b/src/trace_processor/importers/proto/proto_trace_parser.h
index 87bdcfc..995c5b3 100644
--- a/src/trace_processor/importers/proto/proto_trace_parser.h
+++ b/src/trace_processor/importers/proto/proto_trace_parser.h
@@ -73,7 +73,6 @@
void ParseTraceConfig(ConstBytes);
void ParseModuleSymbols(ConstBytes);
void ParseTrigger(int64_t ts, ConstBytes);
- void ParseServiceEvent(int64_t ts, ConstBytes);
void ParseSmapsPacket(int64_t ts, ConstBytes);
private:
diff --git a/src/trace_processor/importers/proto/proto_trace_tokenizer.cc b/src/trace_processor/importers/proto/proto_trace_tokenizer.cc
index 3c9b90b..7f41b9d 100644
--- a/src/trace_processor/importers/proto/proto_trace_tokenizer.cc
+++ b/src/trace_processor/importers/proto/proto_trace_tokenizer.cc
@@ -32,6 +32,7 @@
#include "src/trace_processor/importers/ftrace/ftrace_module.h"
#include "src/trace_processor/importers/gzip/gzip_utils.h"
#include "src/trace_processor/importers/proto/args_table_utils.h"
+#include "src/trace_processor/importers/proto/metadata_tracker.h"
#include "src/trace_processor/importers/proto/packet_sequence_state.h"
#include "src/trace_processor/importers/proto/proto_incremental_state.h"
#include "src/trace_processor/storage/stats.h"
@@ -42,6 +43,7 @@
#include "protos/perfetto/config/trace_config.pbzero.h"
#include "protos/perfetto/trace/clock_snapshot.pbzero.h"
#include "protos/perfetto/trace/extension_descriptor.pbzero.h"
+#include "protos/perfetto/trace/perfetto/tracing_service_event.pbzero.h"
#include "protos/perfetto/trace/profiling/profile_common.pbzero.h"
#include "protos/perfetto/trace/trace.pbzero.h"
#include "protos/perfetto/trace/trace_packet.pbzero.h"
@@ -231,6 +233,12 @@
decoder.trusted_packet_sequence_id());
}
+ if (decoder.has_service_event()) {
+ PERFETTO_DCHECK(decoder.has_timestamp());
+ int64_t ts = static_cast<int64_t>(decoder.timestamp());
+ return ParseServiceEvent(ts, decoder.service_event());
+ }
+
if (decoder.has_extension_descriptor()) {
return ParseExtensionDescriptor(decoder.extension_descriptor());
}
@@ -492,6 +500,24 @@
return util::OkStatus();
}
+util::Status ProtoTraceTokenizer::ParseServiceEvent(int64_t ts,
+ ConstBytes blob) {
+ protos::pbzero::TracingServiceEvent::Decoder tse(blob);
+ if (tse.tracing_started()) {
+ context_->metadata_tracker->SetMetadata(metadata::tracing_started_ns,
+ Variadic::Integer(ts));
+ }
+ if (tse.tracing_disabled()) {
+ context_->metadata_tracker->SetMetadata(metadata::tracing_disabled_ns,
+ Variadic::Integer(ts));
+ }
+ if (tse.all_data_sources_started()) {
+ context_->metadata_tracker->SetMetadata(
+ metadata::all_data_source_started_ns, Variadic::Integer(ts));
+ }
+ return util::OkStatus();
+}
+
void ProtoTraceTokenizer::NotifyEndOfFile() {}
} // namespace trace_processor
diff --git a/src/trace_processor/importers/proto/proto_trace_tokenizer.h b/src/trace_processor/importers/proto/proto_trace_tokenizer.h
index 1d9a560..ba94d75 100644
--- a/src/trace_processor/importers/proto/proto_trace_tokenizer.h
+++ b/src/trace_processor/importers/proto/proto_trace_tokenizer.h
@@ -65,6 +65,7 @@
uint8_t* data,
size_t size);
util::Status ParsePacket(TraceBlobView);
+ util::Status ParseServiceEvent(int64_t ts, ConstBytes);
util::Status ParseClockSnapshot(ConstBytes blob, uint32_t seq_id);
void HandleIncrementalStateCleared(
const protos::pbzero::TracePacket_Decoder&);
diff --git a/src/trace_processor/storage/metadata.h b/src/trace_processor/storage/metadata.h
index dd8aa89..4796ae4 100644
--- a/src/trace_processor/storage/metadata.h
+++ b/src/trace_processor/storage/metadata.h
@@ -46,8 +46,10 @@
F(system_release, KeyType::kSingle, Variadic::kString), \
F(system_machine, KeyType::kSingle, Variadic::kString), \
F(android_build_fingerprint, KeyType::kSingle, Variadic::kString), \
- F(trace_size_bytes, KeyType::kSingle, Variadic::kInt), \
- F(all_data_source_started_ns, KeyType::kSingle, Variadic::kInt)
+ F(trace_size_bytes, KeyType::kSingle, Variadic::kInt), \
+ F(all_data_source_started_ns, KeyType::kSingle, Variadic::kInt), \
+ F(tracing_started_ns, KeyType::kSingle, Variadic::kInt), \
+ F(tracing_disabled_ns, KeyType::kSingle, Variadic::kInt)
// clang-format on
// Compile time list of metadata items.
@@ -74,7 +76,7 @@
// Declares an enum of literals (one for each item). The enum values of each
// literal corresponds to the string index in the arrays below.
#define PERFETTO_TP_META_ENUM(name, ...) name
-enum KeyIDs : size_t {
+enum KeyId : size_t {
PERFETTO_TP_METADATA(PERFETTO_TP_META_ENUM),
kNumKeys
};
diff --git a/src/trace_processor/storage/stats.h b/src/trace_processor/storage/stats.h
index a163ac9..4656953 100644
--- a/src/trace_processor/storage/stats.h
+++ b/src/trace_processor/storage/stats.h
@@ -151,7 +151,12 @@
F(perf_samples_skipped_dataloss, kSingle, kDataLoss, kTrace, ""), \
F(thread_time_in_state_out_of_order, kSingle, kError, kAnalysis, ""), \
F(thread_time_in_state_unknown_cpu_freq, \
- kSingle, kError, kAnalysis, "")
+ kSingle, kError, kAnalysis, ""), \
+ F(ftrace_packet_before_tracing_start, kSingle, kInfo, kAnalysis, \
+ "An ftrace packet was seen before the tracing start timestamp from " \
+ "the tracing service. This happens if the ftrace buffers were not " \
+ "cleared properly. These packets are silently dropped by trace " \
+ "processor.")
// clang-format on
enum Type {
