Merge changes Id8e45dd9,If1f99da9,Iebc6952a into main * changes: tp: diff tests for ftrace cropping tp: implement ftrace event cropping for traces recorded by perfetto v44+ ftrace: write "last read event timestamp" to assist parsing of ring buffer traces
diff --git a/CHANGELOG b/CHANGELOG index 46a6cd3..145aa78 100644 --- a/CHANGELOG +++ b/CHANGELOG
@@ -6,6 +6,11 @@ UI: * Per-cpu scheduling tracks now distinguish real-time priority threads with a hatched pattern and name prefix. Based on priority during switch-in. + * Added ftrace event cropping for traces recorded by perfetto v44+. + Events are ignored if they precede the earliest timestamp covered by all + per-cpu data streams. This should significantly improve the presentation + of RING_BUFFER traces, removing artifacts such as never-ending slices + starting at the beginning of the trace. SDK: *
diff --git a/include/perfetto/trace_processor/basic_types.h b/include/perfetto/trace_processor/basic_types.h index 7ecc934..ce468fb 100644 --- a/include/perfetto/trace_processor/basic_types.h +++ b/include/perfetto/trace_processor/basic_types.h
@@ -93,7 +93,25 @@ // trace, no data is dropped. // This option can be used in cases where R- traces are being considered and // |kTracingStart| cannot be used because the event was not present. - kAllDataSourcesStarted = 2, + kAllDataSourcesStarted = 2 +}; + +// Specifies whether the ftrace data should be "soft-dropped" until a given +// global timestamp, meaning we'll still populate the |ftrace_events| table +// and some other internal storage, but won't persist derived info such as +// slices. See also |DropFtraceDataBefore| above. +// Note: this might behave in surprising ways for traces using >1 tracefs +// instances, but those aren't seen in practice at the time of writing. +enum class SoftDropFtraceDataBefore { + // Drop until the earliest timestamp covered by all per-cpu event bundles. + // In other words, the maximum of all per-cpu "valid from" timestamps. + // Important for correct parsing of traces where the ftrace data is written + // into a central perfetto buffer in ring-buffer mode (as opposed to discard + // mode). + kAllPerCpuBuffersValid = 0, + + // Keep all events (though DropFtraceDataBefore still applies). + kNoDrop = 1 }; // Enum which encodes which timestamp source (if any) should be used to drop @@ -129,6 +147,11 @@ DropFtraceDataBefore drop_ftrace_data_before = DropFtraceDataBefore::kTracingStarted; + // Specifies whether the ftrace data should be "soft-dropped" until a given + // global timestamp. + SoftDropFtraceDataBefore soft_drop_ftrace_data_before = + SoftDropFtraceDataBefore::kAllPerCpuBuffersValid; + // Indicates the source of timestamp before which track events should be // dropped. See the enum documentation for more details. DropTrackEventDataBefore drop_track_event_data_before =
diff --git a/protos/perfetto/trace/ftrace/ftrace_event_bundle.proto b/protos/perfetto/trace/ftrace/ftrace_event_bundle.proto index 5bfab9dd..a884396 100644 --- a/protos/perfetto/trace/ftrace/ftrace_event_bundle.proto +++ b/protos/perfetto/trace/ftrace/ftrace_event_bundle.proto
@@ -112,6 +112,15 @@ optional FtraceParseStatus status = 2; } repeated FtraceError error = 8; + + // The timestamp (boottime) of the last event consumed from this per-cpu + // kernel buffer prior to starting this bundle. In other words: the last + // event in the previous bundle. + // Lets the trace processing find an initial timestamp after which ftrace + // data is known to be valid across all cpus. Of particular importance when + // the perfetto trace buffer is a ring buffer as well, as the overwriting of + // oldest bundles can skew the first valid timestamp per cpu significantly. + optional uint64 last_read_event_timestamp = 9; } enum FtraceClock {
diff --git a/protos/perfetto/trace/perfetto_trace.proto b/protos/perfetto/trace/perfetto_trace.proto index a166cae..0bae4d2 100644 --- a/protos/perfetto/trace/perfetto_trace.proto +++ b/protos/perfetto/trace/perfetto_trace.proto
@@ -10805,6 +10805,15 @@ optional FtraceParseStatus status = 2; } repeated FtraceError error = 8; + + // The timestamp (boottime) of the last event consumed from this per-cpu + // kernel buffer prior to starting this bundle. In other words: the last + // event in the previous bundle. + // Lets the trace processing find an initial timestamp after which ftrace + // data is known to be valid across all cpus. Of particular importance when + // the perfetto trace buffer is a ring buffer as well, as the overwriting of + // oldest bundles can skew the first valid timestamp per cpu significantly. + optional uint64 last_read_event_timestamp = 9; } enum FtraceClock {
diff --git a/protos/perfetto/trace_processor/trace_processor.proto b/protos/perfetto/trace_processor/trace_processor.proto index 1e579ca..e7a6cd5 100644 --- a/protos/perfetto/trace_processor/trace_processor.proto +++ b/protos/perfetto/trace_processor/trace_processor.proto
@@ -326,4 +326,5 @@ optional DropTrackEventDataBefore drop_track_event_data_before = 1; optional bool ingest_ftrace_in_raw_table = 2; optional bool analyze_trace_proto_content = 3; + optional bool ftrace_drop_until_all_cpus_valid = 4; }
diff --git a/python/perfetto/trace_processor/trace_processor.descriptor b/python/perfetto/trace_processor/trace_processor.descriptor index ce0bc66..bb8e8b9 100644 --- a/python/perfetto/trace_processor/trace_processor.descriptor +++ b/python/perfetto/trace_processor/trace_processor.descriptor Binary files differ
diff --git a/src/trace_processor/importers/common/metadata_tracker.cc b/src/trace_processor/importers/common/metadata_tracker.cc index 7468c42..743e115 100644 --- a/src/trace_processor/importers/common/metadata_tracker.cc +++ b/src/trace_processor/importers/common/metadata_tracker.cc
@@ -17,7 +17,6 @@ #include "src/trace_processor/importers/common/metadata_tracker.h" #include "perfetto/ext/base/crash_keys.h" -#include "src/trace_processor/importers/common/process_tracker.h" #include "src/trace_processor/storage/metadata.h" #include "src/trace_processor/types/trace_processor_context.h" @@ -68,21 +67,23 @@ return id_and_row.id; } -SqlValue MetadataTracker::GetMetadata(metadata::KeyId key) { +std::optional<SqlValue> MetadataTracker::GetMetadata(metadata::KeyId key) { // KeyType::kMulti not yet supported by this method: PERFETTO_CHECK(metadata::kKeyTypes[key] == metadata::KeyType::kSingle); auto* metadata_table = storage_->mutable_metadata_table(); uint32_t key_idx = static_cast<uint32_t>(key); - uint32_t row = - metadata_table->name().IndexOf(metadata::kNames[key_idx]).value(); + std::optional<uint32_t> row = + metadata_table->name().IndexOf(metadata::kNames[key_idx]); + if (!row.has_value()) + return {}; auto value_type = metadata::kValueTypes[key]; switch (value_type) { case Variadic::kInt: - return metadata_table->mutable_int_value()->Get(row); + return metadata_table->mutable_int_value()->Get(*row); case Variadic::kString: - return metadata_table->mutable_str_value()->Get(row); + return metadata_table->mutable_str_value()->Get(*row); case Variadic::kNull: return SqlValue(); case Variadic::kJson:
diff --git a/src/trace_processor/importers/common/metadata_tracker.h b/src/trace_processor/importers/common/metadata_tracker.h index 3bd7379..2c63e24 100644 --- a/src/trace_processor/importers/common/metadata_tracker.h +++ b/src/trace_processor/importers/common/metadata_tracker.h
@@ -20,6 +20,7 @@ #include <array> #include <cstddef> #include <cstdint> +#include <optional> #include "perfetto/trace_processor/basic_types.h" #include "src/trace_processor/storage/metadata.h" @@ -50,7 +51,7 @@ // Reads back a set metadata value. // Only kSingle types are supported right now. - SqlValue GetMetadata(metadata::KeyId key); + std::optional<SqlValue> GetMetadata(metadata::KeyId key); // Tracks how many ChromeMetadata bundles have been parsed. uint32_t IncrementChromeMetadataBundleCount() {
diff --git a/src/trace_processor/importers/common/sched_event_state.h b/src/trace_processor/importers/common/sched_event_state.h index 4ebc6ce..6a97aed 100644 --- a/src/trace_processor/importers/common/sched_event_state.h +++ b/src/trace_processor/importers/common/sched_event_state.h
@@ -17,15 +17,17 @@ #ifndef SRC_TRACE_PROCESSOR_IMPORTERS_COMMON_SCHED_EVENT_STATE_H_ #define SRC_TRACE_PROCESSOR_IMPORTERS_COMMON_SCHED_EVENT_STATE_H_ -#include <iosfwd> +#include <limits> +#include <vector> #include "src/trace_processor/storage/trace_storage.h" -#include "src/trace_processor/types/version_number.h" namespace perfetto { namespace trace_processor { // Responsible for keeping the state of pending sched events. +// TODO(rsavitski): consider folding back into ftrace parser. The ETW parser is +// probably better off replicating its own pending state struct. class SchedEventState { public: // Information retained from the preceding sched_switch seen on a given cpu.
diff --git a/src/trace_processor/importers/common/sched_event_tracker.h b/src/trace_processor/importers/common/sched_event_tracker.h index 68a2926..f83ffb6 100644 --- a/src/trace_processor/importers/common/sched_event_tracker.h +++ b/src/trace_processor/importers/common/sched_event_tracker.h
@@ -18,11 +18,8 @@ #define SRC_TRACE_PROCESSOR_IMPORTERS_COMMON_SCHED_EVENT_TRACKER_H_ #include "perfetto/ext/base/string_view.h" -#include "perfetto/ext/base/utils.h" #include "src/trace_processor/importers/common/event_tracker.h" -#include "src/trace_processor/importers/common/process_tracker.h" #include "src/trace_processor/importers/common/system_info_tracker.h" -#include "src/trace_processor/importers/common/thread_state_tracker.h" #include "src/trace_processor/storage/trace_storage.h" #include "src/trace_processor/types/destructible.h" #include "src/trace_processor/types/task_state.h" @@ -31,11 +28,13 @@ namespace perfetto { namespace trace_processor { -// Tracks sched events and stores them into the storage as sched slices. +// Tracks per-cpu scheduling events, storing them as slices in the |sched| +// table. class SchedEventTracker : public Destructible { public: PERFETTO_ALWAYS_INLINE - SchedEventTracker(TraceProcessorContext* context) : context_(context) {} + explicit SchedEventTracker(TraceProcessorContext* context) + : context_(context) {} SchedEventTracker(const SchedEventTracker&) = delete; ~SchedEventTracker() override; @@ -58,12 +57,11 @@ bool UpdateEventTrackerTimestamp(int64_t ts, const char* event_name, size_t stats) { - // At this stage all events should be globally timestamp ordered. - if (ts < context_->event_tracker->max_timestamp()) { - PERFETTO_ELOG( - "%s event out of order by %.4f ms, skipping", event_name, - static_cast<double>(context_->event_tracker->max_timestamp() - ts) / - 1e6); + // Post sorter stage, all events should be globally timestamp ordered. + int64_t max_ts = context_->event_tracker->max_timestamp(); + if (ts < max_ts) { + PERFETTO_ELOG("%s event out of order by %.4f ms, skipping", event_name, + static_cast<double>(max_ts - ts) / 1e6); context_->storage->IncrementStats(stats); return false; } @@ -86,6 +84,7 @@ slices->mutable_end_state()->Set(pending_slice_idx, prev_state); } + // TODO(rsavitski): fold back into ftrace parser, this is specific to Linux. PERFETTO_ALWAYS_INLINE StringId TaskStateToStringId(int64_t task_state_int) { using ftrace_utils::TaskState;
diff --git a/src/trace_processor/importers/ftrace/ftrace_module_impl.cc b/src/trace_processor/importers/ftrace/ftrace_module_impl.cc index 3c535fb..bd67c64 100644 --- a/src/trace_processor/importers/ftrace/ftrace_module_impl.cc +++ b/src/trace_processor/importers/ftrace/ftrace_module_impl.cc
@@ -15,10 +15,11 @@ */ #include "src/trace_processor/importers/ftrace/ftrace_module_impl.h" -#include "perfetto/base/build_config.h" + #include "perfetto/trace_processor/trace_blob_view.h" #include "src/trace_processor/importers/ftrace/ftrace_parser.h" #include "src/trace_processor/importers/ftrace/ftrace_tokenizer.h" +#include "src/trace_processor/importers/proto/proto_importer_module.h" #include "protos/perfetto/trace/trace_packet.pbzero.h"
diff --git a/src/trace_processor/importers/ftrace/ftrace_module_impl.h b/src/trace_processor/importers/ftrace/ftrace_module_impl.h index a341869..658bafc 100644 --- a/src/trace_processor/importers/ftrace/ftrace_module_impl.h +++ b/src/trace_processor/importers/ftrace/ftrace_module_impl.h
@@ -17,7 +17,6 @@ #ifndef SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_MODULE_IMPL_H_ #define SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_MODULE_IMPL_H_ -#include "perfetto/base/build_config.h" #include "protos/perfetto/trace/trace_packet.pbzero.h" #include "src/trace_processor/importers/common/parser_types.h" #include "src/trace_processor/importers/ftrace/ftrace_module.h"
diff --git a/src/trace_processor/importers/ftrace/ftrace_parser.cc b/src/trace_processor/importers/ftrace/ftrace_parser.cc index 69f1b58..95cf0d8 100644 --- a/src/trace_processor/importers/ftrace/ftrace_parser.cc +++ b/src/trace_processor/importers/ftrace/ftrace_parser.cc
@@ -17,18 +17,21 @@ #include "src/trace_processor/importers/ftrace/ftrace_parser.h" #include "perfetto/base/logging.h" +#include "perfetto/base/status.h" #include "perfetto/ext/base/string_utils.h" -#include "perfetto/ext/base/string_writer.h" #include "perfetto/protozero/proto_decoder.h" +#include "perfetto/trace_processor/basic_types.h" #include "src/trace_processor/importers/common/args_tracker.h" #include "src/trace_processor/importers/common/async_track_set_tracker.h" #include "src/trace_processor/importers/common/metadata_tracker.h" #include "src/trace_processor/importers/common/parser_types.h" #include "src/trace_processor/importers/common/process_tracker.h" +#include "src/trace_processor/importers/common/system_info_tracker.h" #include "src/trace_processor/importers/common/thread_state_tracker.h" #include "src/trace_processor/importers/common/track_tracker.h" #include "src/trace_processor/importers/ftrace/binder_tracker.h" +#include "src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h" #include "src/trace_processor/importers/ftrace/v4l2_tracker.h" #include "src/trace_processor/importers/ftrace/virtio_video_tracker.h" #include "src/trace_processor/importers/i2c/i2c_tracker.h" @@ -59,7 +62,6 @@ #include "protos/perfetto/trace/ftrace/ion.pbzero.h" #include "protos/perfetto/trace/ftrace/irq.pbzero.h" #include "protos/perfetto/trace/ftrace/kmem.pbzero.h" -#include "protos/perfetto/trace/ftrace/lowmemorykiller.pbzero.h" #include "protos/perfetto/trace/ftrace/lwis.pbzero.h" #include "protos/perfetto/trace/ftrace/mali.pbzero.h" #include "protos/perfetto/trace/ftrace/mdss.pbzero.h" @@ -229,6 +231,7 @@ RPM_SUSPENDING, }; } // namespace + FtraceParser::FtraceParser(TraceProcessorContext* context) : context_(context), rss_stat_tracker_(context), @@ -654,6 +657,15 @@ ParseTypedFtraceToRaw(fld.id(), ts, cpu, pid, fld_bytes, seq_state); } + // Skip everything besides the |raw| write if we're at the start of the + // trace and not all per-cpu buffers cover this region yet. Otherwise if + // this event signifies a beginning of an operation that can end on a + // different cpu, we could conclude that the operation never ends. + // See b/192586066. + if (PERFETTO_UNLIKELY(ts < soft_drop_ftrace_data_before_ts_)) { + return base::OkStatus(); + } + if (PkvmHypervisorCpuTracker::IsPkvmHypervisorEvent(fld.id())) { pkvm_hyp_cpu_tracker_.ParseHypEvent(cpu, ts, fld.id(), fld_bytes); } @@ -1145,10 +1157,14 @@ int64_t ts, const InlineSchedSwitch& data) { MaybeOnFirstFtraceEvent(); - if (PERFETTO_UNLIKELY(ts < drop_ftrace_data_before_ts_)) { - context_->storage->IncrementStats( - stats::ftrace_packet_before_tracing_start); - return util::OkStatus(); + bool parse_only_into_raw = false; + if (PERFETTO_UNLIKELY(ts < soft_drop_ftrace_data_before_ts_)) { + parse_only_into_raw = true; + if (ts < drop_ftrace_data_before_ts_) { + context_->storage->IncrementStats( + stats::ftrace_packet_before_tracing_start); + return util::OkStatus(); + } } using protos::pbzero::FtraceEvent; @@ -1156,7 +1172,7 @@ FtraceSchedEventTracker::GetOrCreate(context_); ftrace_sched_tracker->PushSchedSwitchCompact( cpu, ts, data.prev_state, static_cast<uint32_t>(data.next_pid), - data.next_prio, data.next_comm); + data.next_prio, data.next_comm, parse_only_into_raw); return util::OkStatus(); } @@ -1165,17 +1181,22 @@ int64_t ts, const InlineSchedWaking& data) { MaybeOnFirstFtraceEvent(); - if (PERFETTO_UNLIKELY(ts < drop_ftrace_data_before_ts_)) { - context_->storage->IncrementStats( - stats::ftrace_packet_before_tracing_start); - return util::OkStatus(); + bool parse_only_into_raw = false; + if (PERFETTO_UNLIKELY(ts < soft_drop_ftrace_data_before_ts_)) { + parse_only_into_raw = true; + if (ts < drop_ftrace_data_before_ts_) { + context_->storage->IncrementStats( + stats::ftrace_packet_before_tracing_start); + return util::OkStatus(); + } } + using protos::pbzero::FtraceEvent; FtraceSchedEventTracker* ftrace_sched_tracker = FtraceSchedEventTracker::GetOrCreate(context_); ftrace_sched_tracker->PushSchedWakingCompact( cpu, ts, static_cast<uint32_t>(data.pid), data.target_cpu, data.prio, - data.comm, data.common_flags); + data.comm, data.common_flags, parse_only_into_raw); return util::OkStatus(); } @@ -1184,6 +1205,8 @@ return; } + // Calculate the timestamp used to skip events that predate the time when + // tracing started. DropFtraceDataBefore drop_before = preserve_ftrace_buffer_ ? DropFtraceDataBefore::kNoDrop : context_->config.drop_ftrace_data_before; @@ -1198,15 +1221,34 @@ drop_before == DropFtraceDataBefore::kAllDataSourcesStarted ? metadata::all_data_source_started_ns : metadata::tracing_started_ns; - const auto& metadata = context_->storage->metadata_table(); - std::optional<uint32_t> opt_row = - metadata.name().IndexOf(metadata::kNames[event_key]); - if (opt_row) { - drop_ftrace_data_before_ts_ = *metadata.int_value()[*opt_row]; - } + + drop_ftrace_data_before_ts_ = + context_->metadata_tracker->GetMetadata(event_key) + .value_or(SqlValue::Long(0)) + .AsLong(); break; } } + + // Calculate the timestamp used to skip events since, while still populating + // the |ftrace_events| table. + switch (context_->config.soft_drop_ftrace_data_before) { + case SoftDropFtraceDataBefore::kNoDrop: { + soft_drop_ftrace_data_before_ts_ = 0; + break; + } + case SoftDropFtraceDataBefore::kAllPerCpuBuffersValid: { + soft_drop_ftrace_data_before_ts_ = + context_->metadata_tracker + ->GetMetadata(metadata::ftrace_latest_data_start_ns) + .value_or(SqlValue::Long(0)) + .AsLong(); + break; + } + } + soft_drop_ftrace_data_before_ts_ = + std::max(soft_drop_ftrace_data_before_ts_, drop_ftrace_data_before_ts_); + has_seen_first_ftrace_packet_ = true; } @@ -1277,7 +1319,7 @@ StringId name_id = message_strings.field_name_ids[field_id]; // Check if this field represents a kernel function. - auto it = std::find_if( + const auto* it = std::find_if( kKernelFunctionFields.begin(), kKernelFunctionFields.end(), [ftrace_id, field_id](const FtraceEventAndFieldId& ev) { return ev.event_id == ftrace_id && ev.field_id == field_id;
diff --git a/src/trace_processor/importers/ftrace/ftrace_parser.h b/src/trace_processor/importers/ftrace/ftrace_parser.h index de0b3bb..a3f8fc6 100644 --- a/src/trace_processor/importers/ftrace/ftrace_parser.h +++ b/src/trace_processor/importers/ftrace/ftrace_parser.h
@@ -17,16 +17,19 @@ #ifndef SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_PARSER_H_ #define SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_PARSER_H_ +#include <cstdint> + +#include <string> +#include <unordered_set> +#include <vector> + #include "perfetto/ext/base/flat_hash_map.h" #include "perfetto/ext/base/hash.h" -#include "perfetto/trace_processor/status.h" #include "src/trace_processor/importers/common/event_tracker.h" #include "src/trace_processor/importers/common/parser_types.h" -#include "src/trace_processor/importers/common/system_info_tracker.h" #include "src/trace_processor/importers/common/trace_parser.h" #include "src/trace_processor/importers/ftrace/drm_tracker.h" #include "src/trace_processor/importers/ftrace/ftrace_descriptors.h" -#include "src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h" #include "src/trace_processor/importers/ftrace/gpu_work_period_tracker.h" #include "src/trace_processor/importers/ftrace/iostat_tracker.h" #include "src/trace_processor/importers/ftrace/mali_gpu_event_tracker.h" @@ -35,8 +38,6 @@ #include "src/trace_processor/importers/ftrace/virtio_gpu_tracker.h" #include "src/trace_processor/types/trace_processor_context.h" -#include <unordered_set> - namespace perfetto { namespace trace_processor { @@ -439,10 +440,14 @@ bool has_seen_first_ftrace_packet_ = false; - // Stores information about the timestamp from the metadata table which is - // used to filter ftrace packets which happen before this point. + // Ftrace events before this timestamp get dropped. int64_t drop_ftrace_data_before_ts_ = 0; + // Ftrace events before this timestamp get parsed into the |ftrace_events| + // table, but don't get propagated into other tables/trackers. + // Must be no less than drop_ftrace_data_before_ts_. + int64_t soft_drop_ftrace_data_before_ts_ = 0; + // Does not skip any ftrace events. bool preserve_ftrace_buffer_ = false;
diff --git a/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.cc b/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.cc index 36bf028..67c3691 100644 --- a/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.cc +++ b/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.cc
@@ -16,19 +16,16 @@ #include "src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h" -#include <math.h> +#include <limits> -#include "perfetto/ext/base/utils.h" #include "src/trace_processor/importers/common/args_tracker.h" #include "src/trace_processor/importers/common/event_tracker.h" #include "src/trace_processor/importers/common/process_tracker.h" -#include "src/trace_processor/importers/common/sched_event_tracker.h" #include "src/trace_processor/importers/common/sched_event_state.h" -#include "src/trace_processor/importers/common/system_info_tracker.h" +#include "src/trace_processor/importers/common/sched_event_tracker.h" #include "src/trace_processor/importers/common/thread_state_tracker.h" #include "src/trace_processor/importers/ftrace/ftrace_descriptors.h" #include "src/trace_processor/storage/stats.h" -#include "src/trace_processor/types/task_state.h" #include "src/trace_processor/types/trace_processor_context.h" #include "src/trace_processor/types/variadic.h" @@ -132,21 +129,21 @@ int64_t prev_state, uint32_t next_pid, int32_t next_prio, - StringId next_comm_id) { - if (!context_->sched_event_tracker->UpdateEventTrackerTimestamp(ts, - "sched_switch", stats::sched_switch_out_of_order)) { + StringId next_comm_id, + bool parse_only_into_raw) { + if (!context_->sched_event_tracker->UpdateEventTrackerTimestamp( + ts, "sched_switch", stats::sched_switch_out_of_order)) { return; } UniqueTid next_utid = context_->process_tracker->UpdateThreadName( next_pid, next_comm_id, ThreadNamePriority::kFtrace); - auto* pending_sched = sched_event_state_.GetPendingSchedInfoForCpu(cpu); - // If we're processing the first compact event for this cpu, don't start a // slice since we're missing the "prev_*" fields. The successive events will // create slices as normal, but the first per-cpu switch is effectively // discarded. + auto* pending_sched = sched_event_state_.GetPendingSchedInfoForCpu(cpu); if (pending_sched->last_utid == std::numeric_limits<UniqueTid>::max()) { context_->storage->IncrementStats(stats::compact_sched_switch_skipped); @@ -161,14 +158,15 @@ // Close the pending slice if any (we won't have one when processing the first // two compact events for a given cpu). uint32_t pending_slice_idx = pending_sched->pending_slice_storage_idx; - StringId prev_state_string_id = context_->sched_event_tracker - ->TaskStateToStringId(prev_state); - if (prev_state_string_id == kNullStringId) { + StringId prev_state_str_id = + context_->sched_event_tracker->TaskStateToStringId(prev_state); + if (prev_state_str_id == kNullStringId) { context_->storage->IncrementStats(stats::task_state_invalid); } - if (pending_slice_idx < std::numeric_limits<uint32_t>::max()) + if (pending_slice_idx != std::numeric_limits<uint32_t>::max()) { context_->sched_event_tracker->ClosePendingSlice(pending_slice_idx, ts, - prev_state_string_id); + prev_state_str_id); + } // Use the previous event's values to infer this event's "prev_*" fields. // There are edge cases, but this assumption should still produce sensible @@ -184,19 +182,28 @@ kNullStringId); AddRawSchedSwitchEvent(cpu, ts, prev_utid, prev_pid, prev_comm_id, prev_prio, - prev_state, next_pid, next_comm_id, next_prio); - auto new_slice_idx = context_->sched_event_tracker - ->AddStartSlice(cpu, ts, next_utid, next_prio); + prev_state, next_pid, next_comm_id, next_prio); - // Finally, update the info for the next sched switch on this CPU. - pending_sched->pending_slice_storage_idx = new_slice_idx; + // Update the info for the next sched switch on this CPU. pending_sched->last_pid = next_pid; pending_sched->last_utid = next_utid; pending_sched->last_prio = next_prio; - // Update the ThreadState table. + // Subtle: if only inserting into raw, we're ending with: + // * updated |pending_sched->last_*| fields + // * still-defaulted |pending_slice_storage_idx| + // This is similar to the first compact_sched_switch per cpu. + if (PERFETTO_UNLIKELY(parse_only_into_raw)) + return; + + // Update per-cpu Sched table. + auto new_slice_idx = context_->sched_event_tracker->AddStartSlice( + cpu, ts, next_utid, next_prio); + pending_sched->pending_slice_storage_idx = new_slice_idx; + + // Update the per-thread ThreadState table. ThreadStateTracker::GetOrCreate(context_)->PushSchedSwitchEvent( - ts, cpu, prev_utid, prev_state_string_id, next_utid); + ts, cpu, prev_utid, prev_state_str_id, next_utid); } // Processes a sched_waking that was decoded from a compact representation, @@ -207,9 +214,10 @@ uint16_t target_cpu, uint16_t prio, StringId comm_id, - uint16_t common_flags) { - if (!context_->sched_event_tracker->UpdateEventTrackerTimestamp(ts, - "sched_waking", stats::sched_waking_out_of_order)) { + uint16_t common_flags, + bool parse_only_into_raw) { + if (!context_->sched_event_tracker->UpdateEventTrackerTimestamp( + ts, "sched_waking", stats::sched_waking_out_of_order)) { return; } @@ -248,6 +256,9 @@ add_raw_arg(SW::kTargetCpuFieldNumber, Variadic::Integer(target_cpu)); } + if (PERFETTO_UNLIKELY(parse_only_into_raw)) + return; + // Add a waking entry to the ThreadState table. auto wakee_utid = context_->process_tracker->GetOrCreateThread(wakee_pid); ThreadStateTracker::GetOrCreate(context_)->PushWakingEvent(
diff --git a/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h b/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h index bc90532..42b0d4f 100644 --- a/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h +++ b/src/trace_processor/importers/ftrace/ftrace_sched_event_tracker.h
@@ -17,12 +17,11 @@ #ifndef SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_SCHED_EVENT_TRACKER_H_ #define SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_SCHED_EVENT_TRACKER_H_ +#include <cstdint> + #include <array> -#include <limits> #include "perfetto/ext/base/string_view.h" -#include "perfetto/ext/base/utils.h" -#include "src/trace_processor/importers/common/sched_event_tracker.h" #include "src/trace_processor/importers/common/sched_event_state.h" #include "src/trace_processor/storage/trace_storage.h" #include "src/trace_processor/types/destructible.h" @@ -82,7 +81,8 @@ int64_t prev_state, uint32_t next_pid, int32_t next_prio, - StringId next_comm_id); + StringId next_comm_id, + bool parse_only_into_raw); // This method is called when parsing a sched_waking encoded in the compact // format. Note that the default encoding is handled by @@ -93,7 +93,8 @@ uint16_t target_cpu, uint16_t prio, StringId comm_id, - uint16_t common_flags); + uint16_t common_flags, + bool parse_only_into_raw); private: static constexpr uint8_t kSchedSwitchMaxFieldId = 7;
diff --git a/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc b/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc index 53ba885..9d678d1 100644 --- a/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc +++ b/src/trace_processor/importers/ftrace/ftrace_tokenizer.cc
@@ -17,12 +17,18 @@ #include "src/trace_processor/importers/ftrace/ftrace_tokenizer.h" #include "perfetto/base/logging.h" +#include "perfetto/base/status.h" #include "perfetto/protozero/proto_decoder.h" #include "perfetto/protozero/proto_utils.h" +#include "perfetto/trace_processor/basic_types.h" +#include "src/trace_processor/importers/common/metadata_tracker.h" #include "src/trace_processor/importers/proto/packet_sequence_state.h" #include "src/trace_processor/sorter/trace_sorter.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/variadic.h" +#include "src/trace_processor/util/status_macros.h" #include "protos/perfetto/common/builtin_clock.pbzero.h" #include "protos/perfetto/trace/ftrace/ftrace_event.pbzero.h" @@ -160,6 +166,39 @@ TokenizeFtraceEvent(cpu, clock_id, bundle.slice(it->data(), it->size()), state); } + + // First bundle on each cpu is special since ftrace is recorded in per-cpu + // buffers. In traces written by perfetto v44+ we know the timestamp from + // which this cpu's data stream is valid. This is important for parsing ring + // buffer traces, as not all per-cpu data streams will be valid from the same + // timestamp. + if (cpu >= per_cpu_seen_first_bundle_.size()) { + per_cpu_seen_first_bundle_.resize(cpu + 1); + } + 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()) { + int64_t timestamp = 0; + ASSIGN_OR_RETURN( + timestamp, + ResolveTraceTime( + context_, clock_id, + static_cast<int64_t>(decoder.last_read_event_timestamp()))); + + std::optional<SqlValue> curr_latest_timestamp = + context_->metadata_tracker->GetMetadata( + metadata::ftrace_latest_data_start_ns); + + if (!curr_latest_timestamp.has_value() || + timestamp > curr_latest_timestamp->AsLong()) { + context_->metadata_tracker->SetMetadata( + metadata::ftrace_latest_data_start_ns, + Variadic::Integer(timestamp)); + } + } + } return base::OkStatus(); }
diff --git a/src/trace_processor/importers/ftrace/ftrace_tokenizer.h b/src/trace_processor/importers/ftrace/ftrace_tokenizer.h index 6e905c8..915ee9c 100644 --- a/src/trace_processor/importers/ftrace/ftrace_tokenizer.h +++ b/src/trace_processor/importers/ftrace/ftrace_tokenizer.h
@@ -17,6 +17,8 @@ #ifndef SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_TOKENIZER_H_ #define SRC_TRACE_PROCESSOR_IMPORTERS_FTRACE_FTRACE_TOKENIZER_H_ +#include <vector> + #include "perfetto/trace_processor/trace_blob_view.h" #include "src/trace_processor/importers/common/clock_tracker.h" #include "src/trace_processor/storage/trace_storage.h" @@ -64,13 +66,14 @@ TraceBlobView event, PacketSequenceState* state); - void DlogWithLimit(base::Status status) { + void DlogWithLimit(const base::Status& status) { static std::atomic<uint32_t> dlog_count(0); if (dlog_count++ < 10) PERFETTO_DLOG("%s", status.c_message()); } int64_t latest_ftrace_clock_snapshot_ts_ = 0; + std::vector<bool> per_cpu_seen_first_bundle_; TraceProcessorContext* context_; };
diff --git a/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc b/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc index e612709..545418f 100644 --- a/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc +++ b/src/trace_processor/importers/proto/proto_trace_parser_unittest.cc
@@ -2901,7 +2901,8 @@ ASSERT_TRUE(Tokenize().ok()); context_.sorter->ExtractEventsForced(); - SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid); + SqlValue value = + context_.metadata_tracker->GetMetadata(metadata::trace_uuid).value(); EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001"); ASSERT_TRUE(context_.uuid_found_in_trace); } @@ -2914,7 +2915,8 @@ ASSERT_TRUE(Tokenize().ok()); context_.sorter->ExtractEventsForced(); - SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid); + SqlValue value = + context_.metadata_tracker->GetMetadata(metadata::trace_uuid).value(); EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001"); ASSERT_TRUE(context_.uuid_found_in_trace); } @@ -2933,7 +2935,8 @@ ASSERT_TRUE(Tokenize().ok()); context_.sorter->ExtractEventsForced(); - SqlValue value = context_.metadata_tracker->GetMetadata(metadata::trace_uuid); + SqlValue value = + context_.metadata_tracker->GetMetadata(metadata::trace_uuid).value(); EXPECT_STREQ(value.string_value, "00000000-0000-0002-0000-000000000001"); ASSERT_TRUE(context_.uuid_found_in_trace); } @@ -2946,7 +2949,8 @@ context_.sorter->ExtractEventsForced(); SqlValue value = - context_.metadata_tracker->GetMetadata(metadata::trace_config_pbtxt); + context_.metadata_tracker->GetMetadata(metadata::trace_config_pbtxt) + .value(); EXPECT_THAT(value.string_value, HasSubstr("size_kb: 42")); }
diff --git a/src/trace_processor/rpc/rpc.cc b/src/trace_processor/rpc/rpc.cc index 58fb245..b4552e5 100644 --- a/src/trace_processor/rpc/rpc.cc +++ b/src/trace_processor/rpc/rpc.cc
@@ -28,6 +28,7 @@ #include "perfetto/ext/trace_processor/rpc/query_result_serializer.h" #include "perfetto/protozero/scattered_heap_buffer.h" #include "perfetto/protozero/scattered_stream_writer.h" +#include "perfetto/trace_processor/basic_types.h" #include "perfetto/trace_processor/trace_processor.h" #include "src/trace_processor/tp_metatrace.h" @@ -346,6 +347,12 @@ config.analyze_trace_proto_content = reset_trace_processor_args.analyze_trace_proto_content(); } + if (reset_trace_processor_args.has_ftrace_drop_until_all_cpus_valid()) { + config.soft_drop_ftrace_data_before = + reset_trace_processor_args.ftrace_drop_until_all_cpus_valid() + ? SoftDropFtraceDataBefore::kAllPerCpuBuffersValid + : SoftDropFtraceDataBefore::kNoDrop; + } ResetTraceProcessorInternal(config); }
diff --git a/src/trace_processor/storage/metadata.h b/src/trace_processor/storage/metadata.h index 1fa85ae..864d223 100644 --- a/src/trace_processor/storage/metadata.h +++ b/src/trace_processor/storage/metadata.h
@@ -19,7 +19,6 @@ #include <stddef.h> -#include "src/trace_processor/containers/string_pool.h" #include "src/trace_processor/types/variadic.h" namespace perfetto { @@ -43,6 +42,7 @@ F(benchmark_story_run_time_us, KeyType::kSingle, Variadic::kInt), \ F(benchmark_story_tags, KeyType::kMulti, Variadic::kString), \ F(ftrace_setup_errors, KeyType::kMulti, Variadic::kString), \ + F(ftrace_latest_data_start_ns, KeyType::kSingle, Variadic::kInt), \ F(range_of_interest_start_us, KeyType::kSingle, Variadic::kInt), \ F(statsd_triggering_subscription_id, KeyType::kSingle, Variadic::kInt), \ F(system_machine, KeyType::kSingle, Variadic::kString), \
diff --git a/src/traced/probes/ftrace/cpu_reader.cc b/src/traced/probes/ftrace/cpu_reader.cc index c161203..462c992 100644 --- a/src/traced/probes/ftrace/cpu_reader.cc +++ b/src/traced/probes/ftrace/cpu_reader.cc
@@ -114,8 +114,7 @@ } // Reads a signed ftrace value as an int64_t, sign extending if necessary. -static int64_t ReadSignedFtraceValue(const uint8_t* ptr, - FtraceFieldType ftrace_type) { +int64_t ReadSignedFtraceValue(const uint8_t* ptr, FtraceFieldType ftrace_type) { if (ftrace_type == kFtraceInt32) { int32_t value; memcpy(&value, reinterpret_cast<const void*>(ptr), sizeof(value)); @@ -302,30 +301,36 @@ ProcessPagesForDataSource( data_source->trace_writer(), data_source->mutable_metadata(), cpu_, data_source->parsing_config(), data_source->mutable_parse_errors(), - parsing_buf, pages_read, compact_sched_buf, table_, symbolizer_, - ftrace_clock_snapshot_, ftrace_clock_); + &last_read_event_ts_, parsing_buf, pages_read, compact_sched_buf, + table_, symbolizer_, ftrace_clock_snapshot_, ftrace_clock_); } return pages_read; } -void CpuReader::Bundler::StartNewPacket(bool lost_events) { +void CpuReader::Bundler::StartNewPacket(bool lost_events, + uint64_t last_read_event_timestamp) { FinalizeAndRunSymbolizer(); packet_ = trace_writer_->NewTracePacket(); bundle_ = packet_->set_ftrace_events(); - if (ftrace_clock_) { - bundle_->set_ftrace_clock(ftrace_clock_); - - if (ftrace_clock_snapshot_ && ftrace_clock_snapshot_->ftrace_clock_ts) { - bundle_->set_ftrace_timestamp(ftrace_clock_snapshot_->ftrace_clock_ts); - bundle_->set_boot_timestamp(ftrace_clock_snapshot_->boot_clock_ts); - } - } bundle_->set_cpu(static_cast<uint32_t>(cpu_)); if (lost_events) { bundle_->set_lost_events(true); } + + // note: set-to-zero is valid and expected for the first bundle per cpu + // (outside of concurrent tracing), with the effective meaning of "all data is + // valid since the data source was started". + bundle_->set_last_read_event_timestamp(last_read_event_timestamp); + + if (ftrace_clock_) { + bundle_->set_ftrace_clock(ftrace_clock_); + if (ftrace_clock_snapshot_ && ftrace_clock_snapshot_->ftrace_clock_ts) { + bundle_->set_ftrace_timestamp(ftrace_clock_snapshot_->ftrace_clock_ts); + bundle_->set_boot_timestamp(ftrace_clock_snapshot_->boot_clock_ts); + } + } } void CpuReader::Bundler::FinalizeAndRunSymbolizer() { @@ -409,6 +414,7 @@ size_t cpu, const FtraceDataSourceConfig* ds_config, base::FlatSet<protos::pbzero::FtraceParseStatus>* parse_errors, + uint64_t* last_read_event_ts, const uint8_t* parsing_buf, const size_t pages_read, CompactSchedBuffer* compact_sched_buf, @@ -420,7 +426,7 @@ Bundler bundler(trace_writer, metadata, ds_config->symbolize_ksyms ? symbolizer : nullptr, cpu, ftrace_clock_snapshot, ftrace_clock, compact_sched_buf, - ds_config->compact_sched.enabled); + ds_config->compact_sched.enabled, *last_read_event_ts); bool success = true; size_t pages_parsed = 0; @@ -456,11 +462,14 @@ kCompactSchedInternerThreshold; if (page_header->lost_events || interner_past_threshold) { - bundler.StartNewPacket(page_header->lost_events); + // pass in an updated last_read_event_ts since we're starting a new + // bundle, which needs to reference the last timestamp from the prior one. + bundler.StartNewPacket(page_header->lost_events, *last_read_event_ts); } - FtraceParseStatus status = ParsePagePayload( - parse_pos, &page_header.value(), table, ds_config, &bundler, metadata); + FtraceParseStatus status = + ParsePagePayload(parse_pos, &page_header.value(), table, ds_config, + &bundler, metadata, last_read_event_ts); if (status != FtraceParseStatus::FTRACE_STATUS_OK) { WriteAndSetParseError(&bundler, parse_errors, page_header->timestamp, @@ -540,11 +549,13 @@ const ProtoTranslationTable* table, const FtraceDataSourceConfig* ds_config, Bundler* bundler, - FtraceMetadata* metadata) { + FtraceMetadata* metadata, + uint64_t* last_read_event_ts) { const uint8_t* ptr = start_of_payload; const uint8_t* const end = ptr + page_header->size; uint64_t timestamp = page_header->timestamp; + uint64_t last_data_record_ts = 0; while (ptr < end) { EventHeader event_header; @@ -674,11 +685,13 @@ } } } - // Jump to next event. - ptr = next; + last_data_record_ts = timestamp; + ptr = next; // jump to next event } // default case } // switch (event_header.type_or_length) } // while (ptr < end) + if (last_data_record_ts) + *last_read_event_ts = last_data_record_ts; return FtraceParseStatus::FTRACE_STATUS_OK; } @@ -715,7 +728,7 @@ protos::pbzero::FtraceEvent::kGenericFieldNumber)) { nested->AppendString(GenericFtraceEvent::kEventNameFieldNumber, info.name); for (const Field& field : info.fields) { - auto generic_field = nested->BeginNestedMessage<protozero::Message>( + auto* generic_field = nested->BeginNestedMessage<protozero::Message>( GenericFtraceEvent::kFieldFieldNumber); generic_field->AppendString(GenericFtraceEvent::Field::kNameFieldNumber, field.ftrace_name);
diff --git a/src/traced/probes/ftrace/cpu_reader.h b/src/traced/probes/ftrace/cpu_reader.h index 9282901..821ba48 100644 --- a/src/traced/probes/ftrace/cpu_reader.h +++ b/src/traced/probes/ftrace/cpu_reader.h
@@ -17,8 +17,8 @@ #ifndef SRC_TRACED_PROBES_FTRACE_CPU_READER_H_ #define SRC_TRACED_PROBES_FTRACE_CPU_READER_H_ -#include <stdint.h> #include <string.h> +#include <cstdint> #include <optional> #include <set> @@ -115,7 +115,8 @@ const FtraceClockSnapshot* ftrace_clock_snapshot, protos::pbzero::FtraceClock ftrace_clock, CompactSchedBuffer* compact_sched_buf, - bool compact_sched_enabled) + bool compact_sched_enabled, + uint64_t last_read_event_ts) : trace_writer_(trace_writer), metadata_(metadata), symbolizer_(symbolizer), @@ -123,7 +124,8 @@ ftrace_clock_snapshot_(ftrace_clock_snapshot), ftrace_clock_(ftrace_clock), compact_sched_enabled_(compact_sched_enabled), - compact_sched_buf_(compact_sched_buf) { + compact_sched_buf_(compact_sched_buf), + initial_last_read_event_ts_(last_read_event_ts) { if (compact_sched_enabled_) compact_sched_buf_->Reset(); } @@ -132,13 +134,13 @@ protos::pbzero::FtraceEventBundle* GetOrCreateBundle() { if (!bundle_) { - StartNewPacket(false); + StartNewPacket(false, initial_last_read_event_ts_); } return bundle_; } // Forces the creation of a new TracePacket. - void StartNewPacket(bool lost_events); + void StartNewPacket(bool lost_events, uint64_t last_read_event_timestamp); // This function is called after the contents of a FtraceBundle are written. void FinalizeAndRunSymbolizer(); @@ -158,10 +160,11 @@ const FtraceClockSnapshot* const ftrace_clock_snapshot_; protos::pbzero::FtraceClock const ftrace_clock_; const bool compact_sched_enabled_; + CompactSchedBuffer* const compact_sched_buf_; + uint64_t initial_last_read_event_ts_; TraceWriter::TracePacketHandle packet_; protos::pbzero::FtraceEventBundle* bundle_ = nullptr; - CompactSchedBuffer* const compact_sched_buf_; }; struct PageHeader { @@ -302,7 +305,8 @@ const ProtoTranslationTable* table, const FtraceDataSourceConfig* ds_config, Bundler* bundler, - FtraceMetadata* metadata); + FtraceMetadata* metadata, + uint64_t* last_read_event_ts); // Parse a single raw ftrace event beginning at |start| and ending at |end| // and write it into the provided bundle as a proto. @@ -370,8 +374,9 @@ size_t cpu, const FtraceDataSourceConfig* ds_config, base::FlatSet<protos::pbzero::FtraceParseStatus>* parse_errors, + uint64_t* last_read_event_ts, const uint8_t* parsing_buf, - const size_t pages_read, + size_t pages_read, CompactSchedBuffer* compact_sched_buf, const ProtoTranslationTable* table, LazyKernelSymbolizer* symbolizer, @@ -397,6 +402,7 @@ const ProtoTranslationTable* table_; LazyKernelSymbolizer* symbolizer_; base::ScopedFile trace_fd_; + uint64_t last_read_event_ts_ = 0; protos::pbzero::FtraceClock ftrace_clock_{}; const FtraceClockSnapshot* ftrace_clock_snapshot_; };
diff --git a/src/traced/probes/ftrace/cpu_reader_benchmark.cc b/src/traced/probes/ftrace/cpu_reader_benchmark.cc index b9a08db..ae5de7d 100644 --- a/src/traced/probes/ftrace/cpu_reader_benchmark.cc +++ b/src/traced/probes/ftrace/cpu_reader_benchmark.cc
@@ -840,7 +840,7 @@ &writer, &metadata, /*symbolizer=*/nullptr, /*cpu=*/0, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED, compact_sched_buf.get(), - /*compact_sched_enabled=*/false); + /*compact_sched_enabled=*/false, /*last_read_event_ts=*/0); ProtoTranslationTable* table = GetTable(test_case.name); auto page = PageFromXxd(test_case.data); @@ -874,8 +874,10 @@ if (!page_header.has_value()) return; + uint64_t last_read_event_ts = 0; CpuReader::ParsePagePayload(parse_pos, &page_header.value(), table, - &ds_config, &bundler, &metadata); + &ds_config, &bundler, &metadata, + &last_read_event_ts); metadata.Clear(); bundler.FinalizeAndRunSymbolizer(); @@ -967,13 +969,15 @@ FtraceMetadata metadata{}; auto compact_sched_buf = std::make_unique<CompactSchedBuffer>(); + uint64_t last_read_event_ts = 0; base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; while (state.KeepRunning()) { CpuReader::ProcessPagesForDataSource( &writer, &metadata, /*cpu=*/0, &ds_config, &parse_errors, - repeated_pages.get(), page_repetition, compact_sched_buf.get(), table, + &last_read_event_ts, repeated_pages.get(), page_repetition, + compact_sched_buf.get(), table, /*symbolizer=*/nullptr, /*ftrace_clock_snapshot=*/nullptr, - /*ftrace_clock=*/protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); + protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); metadata.Clear(); }
diff --git a/src/traced/probes/ftrace/cpu_reader_fuzzer.cc b/src/traced/probes/ftrace/cpu_reader_fuzzer.cc index afd5bc4..f92aab9 100644 --- a/src/traced/probes/ftrace/cpu_reader_fuzzer.cc +++ b/src/traced/probes/ftrace/cpu_reader_fuzzer.cc
@@ -15,15 +15,13 @@ */ #include <stddef.h> -#include <stdint.h> +#include <cstdint> #include <algorithm> #include "perfetto/base/flat_set.h" #include "perfetto/base/logging.h" #include "perfetto/ext/base/utils.h" -#include "perfetto/protozero/scattered_stream_null_delegate.h" -#include "perfetto/protozero/scattered_stream_writer.h" #include "src/traced/probes/ftrace/cpu_reader.h" #include "src/traced/probes/ftrace/ftrace_config_muxer.h" #include "src/traced/probes/ftrace/test/cpu_reader_support.h" @@ -69,8 +67,10 @@ NullTraceWriter null_writer; auto compact_sched_buf = std::make_unique<CompactSchedBuffer>(); base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; + uint64_t last_read_event_ts = 0; CpuReader::ProcessPagesForDataSource( - &null_writer, &metadata, /*cpu=*/0, &ds_config, &parse_errors, g_page, + &null_writer, &metadata, /*cpu=*/0, &ds_config, &parse_errors, + &last_read_event_ts, g_page, /*pages_read=*/1, compact_sched_buf.get(), table, /*symbolizer*/ nullptr, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED);
diff --git a/src/traced/probes/ftrace/cpu_reader_unittest.cc b/src/traced/probes/ftrace/cpu_reader_unittest.cc index 2d4671c..33a8ca3 100644 --- a/src/traced/probes/ftrace/cpu_reader_unittest.cc +++ b/src/traced/probes/ftrace/cpu_reader_unittest.cc
@@ -405,7 +405,8 @@ /*cpu=*/0, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED, - compact_sched_buf_.get(), ds_config.compact_sched.enabled); + compact_sched_buf_.get(), ds_config.compact_sched.enabled, + /*last_read_event_ts=*/0); return &bundler_.value(); } @@ -433,6 +434,7 @@ std::optional<TraceWriterForTesting> writer_; std::unique_ptr<CompactSchedBuffer> compact_sched_buf_; std::optional<CpuReader::Bundler> bundler_; + uint64_t last_read_event_ts_ = 0; }; TEST_F(CpuReaderParsePagePayloadTest, ParseSinglePrint) { @@ -457,7 +459,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -578,7 +580,8 @@ EXPECT_LE(parse_pos + page_header->size, page_end); CpuReader::ParsePagePayload(parse_pos, &page_header.value(), table, - &ds_config, CreateBundler(ds_config), &metadata_); + &ds_config, CreateBundler(ds_config), &metadata_, + &last_read_event_ts_); auto bundle = GetBundle(); const protos::gen::FtraceEvent& long_print = bundle.event()[0]; @@ -622,7 +625,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -666,7 +669,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -696,7 +699,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -758,7 +761,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -812,7 +815,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config_no_filter, - CreateBundler(ds_config_no_filter), &metadata_); + CreateBundler(ds_config_no_filter), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); auto bundle = GetBundle(); @@ -845,7 +848,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config_with_filter, - CreateBundler(ds_config_with_filter), &metadata_); + CreateBundler(ds_config_with_filter), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); auto bundle = GetBundle(); @@ -898,9 +901,11 @@ TraceWriterForTesting trace_writer; base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; + uint64_t last_read_event_ts = 0; bool success = CpuReader::ProcessPagesForDataSource( &trace_writer, &metadata, /*cpu=*/1, &with_filter, &parse_errors, - buf.get(), kTestPages, compact_sched_buf.get(), table, + &last_read_event_ts, buf.get(), kTestPages, compact_sched_buf.get(), + table, /*symbolizer=*/nullptr, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); @@ -920,9 +925,11 @@ TraceWriterForTesting trace_writer; base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; + uint64_t last_read_event_ts = 0; bool success = CpuReader::ProcessPagesForDataSource( &trace_writer, &metadata, /*cpu=*/1, &without_filter, &parse_errors, - buf.get(), kTestPages, compact_sched_buf.get(), table, + &last_read_event_ts, buf.get(), kTestPages, compact_sched_buf.get(), + table, /*symbolizer=*/nullptr, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); @@ -1008,13 +1015,13 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); + EXPECT_EQ(last_read_event_ts_, 1'045'157'726'697'236ULL); auto bundle = GetBundle(); ASSERT_EQ(bundle.event().size(), 6u); - { const protos::gen::FtraceEvent& event = bundle.event()[1]; EXPECT_EQ(event.pid(), 3733ul); @@ -1057,9 +1064,10 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); + EXPECT_EQ(last_read_event_ts_, 1'045'157'726'697'236ULL); // sched switch fields were buffered: EXPECT_LT(0u, bundler_->compact_sched_buf()->sched_switch().size()); @@ -1172,7 +1180,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -1642,9 +1650,11 @@ TraceWriterForTesting trace_writer; auto compact_sched_buf = std::make_unique<CompactSchedBuffer>(); base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; + uint64_t last_read_event_ts = 0; bool success = CpuReader::ProcessPagesForDataSource( - &trace_writer, &metadata, /*cpu=*/1, &ds_config, &parse_errors, buf.get(), - kTestPages, compact_sched_buf.get(), table, /*symbolizer=*/nullptr, + &trace_writer, &metadata, /*cpu=*/1, &ds_config, &parse_errors, + &last_read_event_ts, buf.get(), kTestPages, compact_sched_buf.get(), + table, /*symbolizer=*/nullptr, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); @@ -1695,9 +1705,11 @@ TraceWriterForTesting trace_writer; auto compact_sched_buf = std::make_unique<CompactSchedBuffer>(); base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; + uint64_t last_read_event_ts = 0; bool success = CpuReader::ProcessPagesForDataSource( - &trace_writer, &metadata, /*cpu=*/1, &ds_config, &parse_errors, buf.get(), - kTestPages, compact_sched_buf.get(), table, /*symbolizer=*/nullptr, + &trace_writer, &metadata, /*cpu=*/1, &ds_config, &parse_errors, + &last_read_event_ts, buf.get(), kTestPages, compact_sched_buf.get(), + table, /*symbolizer=*/nullptr, /*ftrace_clock_snapshot=*/nullptr, protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); @@ -1926,7 +1938,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -2410,7 +2422,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -2443,6 +2455,8 @@ // <...>-9290 [000] .... 1352.724567: suspend_resume: resume_console[1] begin // <...>-9290 [000] .... 1352.724570: suspend_resume: resume_console[1] end // <...>-9290 [000] .... 1352.724574: suspend_resume: thaw_processes[0] begin +// clang-format on + static ExamplePage g_suspend_resume { "synthetic", R"(00000000: edba 155a 3201 0000 7401 0000 0000 0000 ...Z2...t....... @@ -2488,8 +2502,9 @@ CpuReader::ParsePageHeader(&parse_pos, table->page_header_size_len()); ASSERT_TRUE(page_header.has_value()); - CpuReader::ParsePagePayload( - parse_pos, &page_header.value(), table, &ds_config, CreateBundler(ds_config), &metadata_); + CpuReader::ParsePagePayload(parse_pos, &page_header.value(), table, + &ds_config, CreateBundler(ds_config), &metadata_, + &last_read_event_ts_); auto bundle = GetBundle(); ASSERT_EQ(bundle.event().size(), 13u); EXPECT_EQ(bundle.event()[0].suspend_resume().action(), "sync_filesystems"); @@ -2933,7 +2948,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -3039,7 +3054,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); // successfully parsed the whole 32 byte event ASSERT_EQ(32u, page_header->size); @@ -3321,7 +3336,7 @@ // the header says there's valid data, but the contents are a run of zeros // (which doesn't decode to valid events per the ring buffer ABI). Confirm that // the error is reported in the ftrace event bundle. -TEST_F(CpuReaderParsePagePayloadTest, ZeroPaddedPageWorkaround) { +TEST_F(CpuReaderParsePagePayloadTest, InvalidZeroPaddedPage) { const ExamplePage* test_case = &g_zero_padded; ProtoTranslationTable* table = GetTable(test_case->name); auto page = PageFromXxd(test_case->data); @@ -3341,7 +3356,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(0xff0u, page_header->size); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_ABI_ZERO_DATA_LENGTH); @@ -3375,7 +3390,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(4u, page_header->size); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_ABI_SHORT_DATA_LENGTH); @@ -3420,7 +3435,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -3474,7 +3489,7 @@ FtraceParseStatus status = CpuReader::ParsePagePayload( parse_pos, &page_header.value(), table, &ds_config, - CreateBundler(ds_config), &metadata_); + CreateBundler(ds_config), &metadata_, &last_read_event_ts_); EXPECT_EQ(status, FtraceParseStatus::FTRACE_STATUS_OK); @@ -3491,5 +3506,132 @@ EXPECT_EQ(event.f2fs_truncate_partial_nodes().err(), 3); } +// one print +char g_last_ts_test_page_0[] = R"( + 00000000: cd79 fb3a 2fa4 0400 2c00 0000 0000 0000 .y.:/...,....... + 00000010: 7eb6 e5eb 8f11 0000 0800 0000 0500 0000 ~............... + 00000020: 1e83 1400 42ab e0af ffff ffff 6669 7273 ....B.......firs + 00000030: 745f 7072 696e 740a 0000 0000 0000 0000 t_print......... + )"; + +// one print +char g_last_ts_test_page_1[] = R"( + 00000000: 3c11 d579 99a5 0400 2c00 0000 0000 0000 <..y....,....... + 00000010: 3ed1 6315 3701 0000 0800 0000 0500 0000 >.c.7........... + 00000020: 9e8c 1400 42ab e0af ffff ffff 7365 636f ....B.......seco + 00000030: 6e64 5f70 7269 6e74 0a00 0000 0000 0000 nd_print........ + )"; + +// data loss marker ("since last read") + multiple sched_switch + one print +char g_last_ts_test_page_2[] = R"( + 00000000: 8ac6 cb70 a8a5 0400 4c02 0080 ffff ffff ...p....L....... + 00000010: 1000 0000 4701 0102 01b1 0f00 636f 6465 ....G.......code + 00000020: 0000 0000 0000 0000 0000 0000 01b1 0f00 ................ + 00000030: 7800 0000 0100 0000 0000 0000 7377 6170 x...........swap + 00000040: 7065 722f 3000 0000 0000 0000 0000 0000 per/0........... + 00000050: 7800 0000 b0e3 f602 4701 0102 0000 0000 x.......G....... + 00000060: 7377 6170 7065 722f 3000 0000 0000 0000 swapper/0....... + 00000070: 0000 0000 7800 0000 0000 0000 0000 0000 ....x........... + 00000080: 6b77 6f72 6b65 722f 303a 3500 0000 0000 kworker/0:5..... + 00000090: ac85 1400 7800 0000 1002 0300 4701 0102 ....x.......G... + 000000a0: ac85 1400 6b77 6f72 6b65 722f 303a 3500 ....kworker/0:5. + 000000b0: 0000 0000 ac85 1400 7800 0000 8000 0000 ........x....... + 000000c0: 0000 0000 7377 6170 7065 722f 3000 0000 ....swapper/0... + 000000d0: 0000 0000 0000 0000 7800 0000 f086 7106 ........x.....q. + 000000e0: 4701 0102 0000 0000 7377 6170 7065 722f G.......swapper/ + 000000f0: 3000 0000 0000 0000 0000 0000 7800 0000 0...........x... + 00000100: 0000 0000 0000 0000 6f62 6e6f 2d64 6573 ........obno-des + 00000110: 6b74 6f70 2d6e 6f00 d513 0000 7800 0000 ktop-no.....x... + 00000120: 3013 1000 4701 0102 d513 0000 6f62 6e6f 0...G.......obno + 00000130: 2d64 6573 6b74 6f70 2d6e 6f00 d513 0000 -desktop-no..... + 00000140: 7800 0000 0100 0000 0000 0000 7377 6170 x...........swap + 00000150: 7065 722f 3000 0000 0000 0000 0000 0000 per/0........... + 00000160: 7800 0000 10b0 2703 4701 0102 0000 0000 x.....'.G....... + 00000170: 7377 6170 7065 722f 3000 0000 0000 0000 swapper/0....... + 00000180: 0000 0000 7800 0000 0000 0000 0000 0000 ....x........... + 00000190: 6b77 6f72 6b65 722f 303a 3500 0000 0000 kworker/0:5..... + 000001a0: ac85 1400 7800 0000 70e7 0200 4701 0102 ....x...p...G... + 000001b0: ac85 1400 6b77 6f72 6b65 722f 303a 3500 ....kworker/0:5. + 000001c0: 0000 0000 ac85 1400 7800 0000 8000 0000 ........x....... + 000001d0: 0000 0000 6b73 6f66 7469 7271 642f 3000 ....ksoftirqd/0. + 000001e0: 0000 0000 0f00 0000 7800 0000 10a4 0200 ........x....... + 000001f0: 4701 0102 0f00 0000 6b73 6f66 7469 7271 G.......ksoftirq + 00000200: 642f 3000 0000 0000 0f00 0000 7800 0000 d/0.........x... + 00000210: 0100 0000 0000 0000 7377 6170 7065 722f ........swapper/ + 00000220: 3000 0000 0000 0000 0000 0000 7800 0000 0...........x... + 00000230: fef2 0a4d 7500 0000 0800 0000 0500 0000 ...Mu........... + 00000240: 1a8d 1400 42ab e0af ffff ffff 7468 6972 ....B.......thir + 00000250: 645f 7072 696e 740a 0000 0000 0000 0000 d_print......... + )"; + +// Tests that |last_read_event_timestamp| is correctly updated in cases where a +// single ProcessPagesForDataSource call produces multiple ftrace bundle packets +// (due to splitting on data loss markers). +TEST(CpuReaderTest, LastReadEventTimestampWithSplitBundles) { + // build test buffer with 3 pages + ProtoTranslationTable* table = GetTable("synthetic"); + std::vector<std::unique_ptr<uint8_t[]>> test_pages; + test_pages.emplace_back(PageFromXxd(g_last_ts_test_page_0)); + test_pages.emplace_back(PageFromXxd(g_last_ts_test_page_1)); + test_pages.emplace_back(PageFromXxd(g_last_ts_test_page_2)); + size_t num_pages = test_pages.size(); + size_t page_sz = base::GetSysPageSize(); + auto buf = std::make_unique<uint8_t[]>(page_sz * num_pages); + for (size_t i = 0; i < num_pages; i++) { + void* dest = buf.get() + (i * page_sz); + memcpy(dest, static_cast<const void*>(test_pages[i].get()), page_sz); + } + + // build cfg requesting ftrace/print + auto compact_sched_buf = std::make_unique<CompactSchedBuffer>(); + FtraceMetadata metadata{}; + FtraceDataSourceConfig ftrace_cfg = EmptyConfig(); + ftrace_cfg.event_filter.AddEnabledEvent( + table->EventToFtraceId(GroupAndName("ftrace", "print"))); + + // invoke ProcessPagesForDataSource + TraceWriterForTesting trace_writer; + base::FlatSet<protos::pbzero::FtraceParseStatus> parse_errors; + uint64_t last_read_event_ts = 0; + bool success = CpuReader::ProcessPagesForDataSource( + &trace_writer, &metadata, /*cpu=*/0, &ftrace_cfg, &parse_errors, + &last_read_event_ts, buf.get(), num_pages, compact_sched_buf.get(), table, + /*symbolizer=*/nullptr, + /*ftrace_clock_snapshot=*/nullptr, + protos::pbzero::FTRACE_CLOCK_UNSPECIFIED); + + EXPECT_TRUE(success); + + // We've read three pages, one print event on each. There is a data loss + // marker on the third page, indicating that the kernel overwrote events + // between 2nd and 3rd page (imagine our daemon getting cpu starved between + // those reads). + // + // Therefore we expect two bundles, as we start a new one whenever we + // encounter data loss (to set the |lost_events| field in the bundle proto). + // + // In terms of |last_read_event_timestamp|, the first bundle will emit zero + // since that's our initial input. The second bundle needs to emit the + // timestamp of the last event in the first bundle. + auto packets = trace_writer.GetAllTracePackets(); + ASSERT_EQ(2u, packets.size()); + + // 2 prints + auto const& first_bundle = packets[0].ftrace_events(); + EXPECT_FALSE(first_bundle.lost_events()); + ASSERT_EQ(2u, first_bundle.event().size()); + EXPECT_TRUE(first_bundle.has_last_read_event_timestamp()); + EXPECT_EQ(0u, first_bundle.last_read_event_timestamp()); + + const uint64_t kSecondPrintTs = 1308020252356549ULL; + EXPECT_EQ(kSecondPrintTs, first_bundle.event()[1].timestamp()); + + // 1 print + lost_events + updated last_read_event_timestamp + auto const& second_bundle = packets[1].ftrace_events(); + EXPECT_TRUE(second_bundle.lost_events()); + EXPECT_EQ(1u, second_bundle.event().size()); + EXPECT_EQ(kSecondPrintTs, second_bundle.last_read_event_timestamp()); +} + } // namespace } // namespace perfetto
diff --git a/src/traced/probes/ftrace/cpu_stats_parser.cc b/src/traced/probes/ftrace/cpu_stats_parser.cc index 1d1cf5a..b3aaf49 100644 --- a/src/traced/probes/ftrace/cpu_stats_parser.cc +++ b/src/traced/probes/ftrace/cpu_stats_parser.cc
@@ -74,11 +74,13 @@ } bool DumpAllCpuStats(FtraceProcfs* ftrace, FtraceStats* stats) { - stats->cpu_stats.resize(ftrace->NumberOfCpus(), {}); - for (size_t cpu = 0; cpu < ftrace->NumberOfCpus(); cpu++) { + size_t num_cpus = ftrace->NumberOfCpus(); + stats->cpu_stats.resize(num_cpus, {}); + for (size_t cpu = 0; cpu < num_cpus; cpu++) { stats->cpu_stats[cpu].cpu = cpu; - if (!DumpCpuStats(ftrace->ReadCpuStats(cpu), &stats->cpu_stats[cpu])) + if (!DumpCpuStats(ftrace->ReadCpuStats(cpu), &stats->cpu_stats[cpu])) { return false; + } } return true; }
diff --git a/src/traced/probes/ftrace/ftrace_procfs.cc b/src/traced/probes/ftrace/ftrace_procfs.cc index 5576627..5346c0d 100644 --- a/src/traced/probes/ftrace/ftrace_procfs.cc +++ b/src/traced/probes/ftrace/ftrace_procfs.cc
@@ -397,7 +397,7 @@ // We cannot use PERFETTO_CHECK as we might get a permission denied error // on Android. The permissions to these files are configured in // platform/framework/native/cmds/atrace/atrace.rc. - for (size_t cpu = 0; cpu < NumberOfCpus(); cpu++) { + for (size_t cpu = 0, num_cpus = NumberOfCpus(); cpu < num_cpus; cpu++) { ClearPerCpuTrace(cpu); } }
diff --git a/test/trace_processor/diff_tests/include_index.py b/test/trace_processor/diff_tests/include_index.py index 7da78d7..0d2c515 100644 --- a/test/trace_processor/diff_tests/include_index.py +++ b/test/trace_processor/diff_tests/include_index.py
@@ -127,6 +127,7 @@ from diff_tests.tables.tests import Tables from diff_tests.tables.tests_counters import TablesCounters from diff_tests.tables.tests_sched import TablesSched +from diff_tests.parser.ftrace.ftrace_crop_tests import FtraceCrop sys.path.pop() @@ -198,6 +199,7 @@ *ParsingRssStats(index_path, 'parser/parsing', 'ParsingRssStats').fetch(), *ParsingMemoryCounters(index_path, 'parser/parsing', 'ParsingMemoryCounters').fetch(), + *FtraceCrop(index_path, 'parser/ftrace', 'FtraceCrop').fetch(), ] metrics_tests = [
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 new file mode 100644 index 0000000..d69bce7 --- /dev/null +++ b/test/trace_processor/diff_tests/parser/ftrace/ftrace_crop_tests.py
@@ -0,0 +1,136 @@ +#!/usr/bin/env python3 +# Copyright (C) 2024 The Android Open Source Project +# +# Licensed under the Apache License, Version 2.0 (the "License"); +# you may not use this file except in compliance with the License. +# You may obtain a copy of the License a +# +# http://www.apache.org/licenses/LICENSE-2.0 +# +# Unless required by applicable law or agreed to in writing, software +# distributed under the License is distributed on an "AS IS" BASIS, +# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. +# See the License for the specific language governing permissions and +# limitations under the License. + +from python.generators.diff_tests.testing import Csv, TextProto +from python.generators.diff_tests.testing import DiffTestBlueprint +from python.generators.diff_tests.testing import TestSuite + + +class FtraceCrop(TestSuite): + + # Expect the first begin event on cpu1 gets suppressed as it is below the + # maximum of last_read_event_timestamps. + def test_crop_atrace_slice(self): + return DiffTestBlueprint( + trace=TextProto(r""" + packet { ftrace_events { + cpu: 1 + last_read_event_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 + last_read_event_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]" + """)) + + # 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. + def test_crop_compact_sched_switch(self): + return DiffTestBlueprint( + trace=TextProto(r""" + packet { + ftrace_events { + last_read_event_timestamp: 1000 + cpu: 3 + compact_sched { + intern_table: "zero:3" + intern_table: "one:3" + switch_timestamp: 1100 + switch_timestamp: 100 + switch_next_pid: 50 + switch_next_pid: 51 + switch_prev_state: 0 + switch_prev_state: 0 + switch_next_prio: 120 + switch_next_prio: 120 + switch_next_comm_index: 0 + switch_next_comm_index: 1 + } + } + } + packet { + ftrace_events { + last_read_event_timestamp: 0 + cpu: 6 + compact_sched { + intern_table: "zero:6" + intern_table: "one:6" + intern_table: "two:6" + intern_table: "three:6" + switch_timestamp: 500 + switch_timestamp: 100 + switch_timestamp: 500 + switch_timestamp: 100 + switch_next_pid: 40 + switch_next_pid: 41 + switch_next_pid: 42 + switch_next_pid: 43 + switch_prev_state: 0 + switch_prev_state: 0 + switch_prev_state: 0 + switch_prev_state: 0 + switch_next_prio: 120 + switch_next_prio: 120 + switch_next_prio: 120 + switch_next_prio: 120 + switch_next_comm_index: 0 + switch_next_comm_index: 1 + switch_next_comm_index: 2 + switch_next_comm_index: 3 + } + } + } + """), + query=""" + select cpu, ts, dur, tid, thread.name + from sched join thread using (utid) + order by cpu asc, ts asc + """, + out=Csv(""" + "cpu","ts","dur","tid","name" + 3,1200,-1,51,"one:3" + 6,1100,100,42,"two:6" + 6,1200,-1,43,"three:6" + """))
diff --git a/ui/src/controller/trace_controller.ts b/ui/src/controller/trace_controller.ts index 136607f..7f3b2a3 100644 --- a/ui/src/controller/trace_controller.ts +++ b/ui/src/controller/trace_controller.ts
@@ -169,9 +169,17 @@ const ANALYZE_TRACE_PROTO_CONTENT_FLAG = featureFlags.register({ id: 'analyzeTraceProtoContent', name: 'Analyze trace proto content', - description: 'Enables trace proto content analysis', + description: + 'Enables trace proto content analysis (experimental_proto_content table)', defaultValue: false, }); +const FTRACE_DROP_UNTIL_FLAG = featureFlags.register({ + id: 'ftraceDropUntilAllCpusValid', + name: 'Crop ftrace events', + description: + 'Drop ftrace events until all per-cpu data streams are known to be valid', + defaultValue: true, +}); // A local storage key where the indication that JSON warning has been shown is // stored. @@ -402,6 +410,7 @@ cropTrackEvents: CROP_TRACK_EVENTS_FLAG.get(), ingestFtraceInRawTable: INGEST_FTRACE_IN_RAW_TABLE_FLAG.get(), analyzeTraceProtoContent: ANALYZE_TRACE_PROTO_CONTENT_FLAG.get(), + ftraceDropUntilAllCpusValid: FTRACE_DROP_UNTIL_FLAG.get(), }); } this.engine = engine;
diff --git a/ui/src/trace_processor/engine.ts b/ui/src/trace_processor/engine.ts index 6a4dd76..b234c16 100644 --- a/ui/src/trace_processor/engine.ts +++ b/ui/src/trace_processor/engine.ts
@@ -63,6 +63,7 @@ cropTrackEvents: boolean; ingestFtraceInRawTable: boolean; analyzeTraceProtoContent: boolean; + ftraceDropUntilAllCpusValid: boolean; } // Abstract interface of a trace proccessor. @@ -273,6 +274,7 @@ cropTrackEvents, ingestFtraceInRawTable, analyzeTraceProtoContent, + ftraceDropUntilAllCpusValid, }: TraceProcessorConfig): Promise<void> { const asyncRes = defer<void>(); this.pendingResetTraceProcessors.push(asyncRes); @@ -285,6 +287,7 @@ : ResetTraceProcessorArgs.DropTrackEventDataBefore.NO_DROP; args.ingestFtraceInRawTable = ingestFtraceInRawTable; args.analyzeTraceProtoContent = analyzeTraceProtoContent; + args.ftraceDropUntilAllCpusValid = ftraceDropUntilAllCpusValid; this.rpcSendRequest(rpc); return asyncRes; }