trace_processor: Expose deltas of ftrace stats
In presence of overlapping traces the current practice of alerting on
overrun_end > 0 is incorrect instead, we should consider
overrun_end-overrun_begin > 0. Expose all the stats where deltas are
sensible while we're at it and finally also guard against new ftrace
stats notifications (e.g. in the middle of the trace, on a timer, etc).
Bug: 205939310
Change-Id: Id1d9fe279fb23ed308d8022c116abac32c6e69aa
diff --git a/src/trace_processor/importers/ftrace/ftrace_parser.cc b/src/trace_processor/importers/ftrace/ftrace_parser.cc
index 390d82f..403b300 100644
--- a/src/trace_processor/importers/ftrace/ftrace_parser.cc
+++ b/src/trace_processor/importers/ftrace/ftrace_parser.cc
@@ -223,8 +223,14 @@
void FtraceParser::ParseFtraceStats(ConstBytes blob) {
protos::pbzero::FtraceStats::Decoder evt(blob.data, blob.size);
- size_t phase =
- evt.phase() == protos::pbzero::FtraceStats_Phase_END_OF_TRACE ? 1 : 0;
+ bool is_start =
+ evt.phase() == protos::pbzero::FtraceStats_Phase_START_OF_TRACE;
+ bool is_end = evt.phase() == protos::pbzero::FtraceStats_Phase_END_OF_TRACE;
+ if (!is_start && !is_end) {
+ PERFETTO_ELOG("Ignoring unknown ftrace stats phase %d", evt.phase());
+ return;
+ }
+ size_t phase = is_end ? 1 : 0;
// This code relies on the fact that each ftrace_cpu_XXX_end event is
// just after the corresponding ftrace_cpu_XXX_begin event.
@@ -238,15 +244,81 @@
for (auto it = evt.cpu_stats(); it; ++it) {
protos::pbzero::FtraceCpuStats::Decoder cpu_stats(*it);
int cpu = static_cast<int>(cpu_stats.cpu());
+
+ int64_t entries = static_cast<int64_t>(cpu_stats.entries());
+ int64_t overrun = static_cast<int64_t>(cpu_stats.overrun());
+ int64_t commit_overrun = static_cast<int64_t>(cpu_stats.commit_overrun());
+ int64_t bytes_read = static_cast<int64_t>(cpu_stats.bytes_read());
+ int64_t dropped_events = static_cast<int64_t>(cpu_stats.dropped_events());
+ int64_t read_events = static_cast<int64_t>(cpu_stats.read_events());
+ int64_t now_ts = static_cast<int64_t>(cpu_stats.now_ts() * 1e9);
+
storage->SetIndexedStats(stats::ftrace_cpu_entries_begin + phase, cpu,
- static_cast<int64_t>(cpu_stats.entries()));
+ entries);
storage->SetIndexedStats(stats::ftrace_cpu_overrun_begin + phase, cpu,
- static_cast<int64_t>(cpu_stats.overrun()));
+ overrun);
storage->SetIndexedStats(stats::ftrace_cpu_commit_overrun_begin + phase,
- cpu,
- static_cast<int64_t>(cpu_stats.commit_overrun()));
+ cpu, commit_overrun);
storage->SetIndexedStats(stats::ftrace_cpu_bytes_read_begin + phase, cpu,
- static_cast<int64_t>(cpu_stats.bytes_read()));
+ bytes_read);
+ storage->SetIndexedStats(stats::ftrace_cpu_dropped_events_begin + phase,
+ cpu, dropped_events);
+ storage->SetIndexedStats(stats::ftrace_cpu_read_events_begin + phase, cpu,
+ read_events);
+ storage->SetIndexedStats(stats::ftrace_cpu_now_ts_begin + phase, cpu,
+ now_ts);
+
+ if (is_end) {
+ auto opt_entries_begin =
+ storage->GetIndexedStats(stats::ftrace_cpu_entries_begin, cpu);
+ if (opt_entries_begin) {
+ int64_t delta_entries = entries - opt_entries_begin.value();
+ storage->SetIndexedStats(stats::ftrace_cpu_entries_delta, cpu,
+ delta_entries);
+ }
+
+ auto opt_overrun_begin =
+ storage->GetIndexedStats(stats::ftrace_cpu_overrun_begin, cpu);
+ if (opt_overrun_begin) {
+ int64_t delta_overrun = overrun - opt_overrun_begin.value();
+ storage->SetIndexedStats(stats::ftrace_cpu_overrun_delta, cpu,
+ delta_overrun);
+ }
+
+ auto opt_commit_overrun_begin =
+ storage->GetIndexedStats(stats::ftrace_cpu_commit_overrun_begin, cpu);
+ if (opt_commit_overrun_begin) {
+ int64_t delta_commit_overrun =
+ commit_overrun - opt_commit_overrun_begin.value();
+ storage->SetIndexedStats(stats::ftrace_cpu_commit_overrun_delta, cpu,
+ delta_commit_overrun);
+ }
+
+ auto opt_bytes_read_begin =
+ storage->GetIndexedStats(stats::ftrace_cpu_bytes_read_begin, cpu);
+ if (opt_bytes_read_begin) {
+ int64_t delta_bytes_read = bytes_read - opt_bytes_read_begin.value();
+ storage->SetIndexedStats(stats::ftrace_cpu_bytes_read_delta, cpu,
+ delta_bytes_read);
+ }
+
+ auto opt_dropped_events_begin =
+ storage->GetIndexedStats(stats::ftrace_cpu_dropped_events_begin, cpu);
+ if (opt_dropped_events_begin) {
+ int64_t delta_dropped_events =
+ dropped_events - opt_dropped_events_begin.value();
+ storage->SetIndexedStats(stats::ftrace_cpu_dropped_events_delta, cpu,
+ delta_dropped_events);
+ }
+
+ auto opt_read_events_begin =
+ storage->GetIndexedStats(stats::ftrace_cpu_read_events_begin, cpu);
+ if (opt_read_events_begin) {
+ int64_t delta_read_events = read_events - opt_read_events_begin.value();
+ storage->SetIndexedStats(stats::ftrace_cpu_read_events_delta, cpu,
+ delta_read_events);
+ }
+ }
// oldest_event_ts can often be set to very high values, possibly because
// of wrapping. Ensure that we are not overflowing to avoid ubsan
@@ -266,14 +338,6 @@
storage->SetIndexedStats(stats::ftrace_cpu_oldest_event_ts_begin + phase,
cpu, static_cast<int64_t>(oldest_event_ts));
}
-
- storage->SetIndexedStats(stats::ftrace_cpu_now_ts_begin + phase, cpu,
- static_cast<int64_t>(cpu_stats.now_ts() * 1e9));
- storage->SetIndexedStats(stats::ftrace_cpu_dropped_events_begin + phase,
- cpu,
- static_cast<int64_t>(cpu_stats.dropped_events()));
- storage->SetIndexedStats(stats::ftrace_cpu_read_events_begin + phase, cpu,
- static_cast<int64_t>(cpu_stats.read_events()));
}
}
diff --git a/src/trace_processor/storage/stats.h b/src/trace_processor/storage/stats.h
index 7e537ca..b52a4c9 100644
--- a/src/trace_processor/storage/stats.h
+++ b/src/trace_processor/storage/stats.h
@@ -35,22 +35,28 @@
F(ftrace_bundle_tokenizer_errors, kSingle, kError, kAnalysis, ""), \
F(ftrace_cpu_bytes_read_begin, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_bytes_read_end, kIndexed, kInfo, kTrace, ""), \
- F(ftrace_cpu_commit_overrun_begin, kIndexed, kError, kTrace, ""), \
- F(ftrace_cpu_commit_overrun_end, kIndexed, kError, kTrace, ""), \
- F(ftrace_cpu_dropped_events_begin, kIndexed, kError, kTrace, ""), \
- F(ftrace_cpu_dropped_events_end, kIndexed, kError, kTrace, ""), \
+ F(ftrace_cpu_bytes_read_delta, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_commit_overrun_begin, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_commit_overrun_end, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_commit_overrun_delta, kIndexed, kError, kTrace, ""), \
+ F(ftrace_cpu_dropped_events_begin, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_dropped_events_end, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_dropped_events_delta, kIndexed, kError, kTrace, ""), \
F(ftrace_cpu_entries_begin, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_entries_end, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_entries_delta, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_now_ts_begin, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_now_ts_end, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_oldest_event_ts_begin, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_oldest_event_ts_end, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_overrun_begin, kIndexed, kInfo, kTrace, ""), \
- F(ftrace_cpu_overrun_end, kIndexed, kDataLoss, kTrace, \
+ F(ftrace_cpu_overrun_end, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_overrun_delta, kIndexed, kDataLoss, kTrace, \
"The kernel ftrace buffer cannot keep up with the rate of events " \
"produced. Indexed by CPU. This is likely a misconfiguration."), \
F(ftrace_cpu_read_events_begin, kIndexed, kInfo, kTrace, ""), \
F(ftrace_cpu_read_events_end, kIndexed, kInfo, kTrace, ""), \
+ F(ftrace_cpu_read_events_delta, kIndexed, kInfo, kTrace, ""), \
F(fuchsia_non_numeric_counters, kSingle, kError, kAnalysis, ""), \
F(fuchsia_timestamp_overflow, kSingle, kError, kAnalysis, ""), \
F(fuchsia_invalid_event, kSingle, kError, kAnalysis, ""), \
diff --git a/src/trace_processor/storage/trace_storage.h b/src/trace_processor/storage/trace_storage.h
index f092c74..af98024 100644
--- a/src/trace_processor/storage/trace_storage.h
+++ b/src/trace_processor/storage/trace_storage.h
@@ -256,6 +256,17 @@
stats_[key].indexed_values[index] = value;
}
+ // Example usage: opt_cpu_failure = GetIndexedStats(stats::cpu_failure, 1);
+ base::Optional<int64_t> GetIndexedStats(size_t key, int index) {
+ PERFETTO_DCHECK(key < stats::kNumKeys);
+ PERFETTO_DCHECK(stats::kTypes[key] == stats::kIndexed);
+ auto kv = stats_[key].indexed_values.find(index);
+ if (kv != stats_[key].indexed_values.end()) {
+ return kv->second;
+ }
+ return base::nullopt;
+ }
+
class ScopedStatsTracer {
public:
ScopedStatsTracer(TraceStorage* storage, size_t key)
diff --git a/test/trace_processor/parsing/android_sched_and_ps_stats.out b/test/trace_processor/parsing/android_sched_and_ps_stats.out
index 4ff60f7..fcc2279 100644
--- a/test/trace_processor/parsing/android_sched_and_ps_stats.out
+++ b/test/trace_processor/parsing/android_sched_and_ps_stats.out
@@ -15,38 +15,62 @@
"ftrace_cpu_bytes_read_end",5,"info","trace",1188
"ftrace_cpu_bytes_read_end",6,"info","trace",1576
"ftrace_cpu_bytes_read_end",7,"info","trace",3264
-"ftrace_cpu_commit_overrun_begin",0,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",1,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",2,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",3,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",4,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",5,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",6,"error","trace",0
-"ftrace_cpu_commit_overrun_begin",7,"error","trace",0
-"ftrace_cpu_commit_overrun_end",0,"error","trace",0
-"ftrace_cpu_commit_overrun_end",1,"error","trace",0
-"ftrace_cpu_commit_overrun_end",2,"error","trace",0
-"ftrace_cpu_commit_overrun_end",3,"error","trace",0
-"ftrace_cpu_commit_overrun_end",4,"error","trace",0
-"ftrace_cpu_commit_overrun_end",5,"error","trace",0
-"ftrace_cpu_commit_overrun_end",6,"error","trace",0
-"ftrace_cpu_commit_overrun_end",7,"error","trace",0
-"ftrace_cpu_dropped_events_begin",0,"error","trace",0
-"ftrace_cpu_dropped_events_begin",1,"error","trace",0
-"ftrace_cpu_dropped_events_begin",2,"error","trace",0
-"ftrace_cpu_dropped_events_begin",3,"error","trace",0
-"ftrace_cpu_dropped_events_begin",4,"error","trace",0
-"ftrace_cpu_dropped_events_begin",5,"error","trace",0
-"ftrace_cpu_dropped_events_begin",6,"error","trace",0
-"ftrace_cpu_dropped_events_begin",7,"error","trace",0
-"ftrace_cpu_dropped_events_end",0,"error","trace",0
-"ftrace_cpu_dropped_events_end",1,"error","trace",0
-"ftrace_cpu_dropped_events_end",2,"error","trace",0
-"ftrace_cpu_dropped_events_end",3,"error","trace",0
-"ftrace_cpu_dropped_events_end",4,"error","trace",0
-"ftrace_cpu_dropped_events_end",5,"error","trace",0
-"ftrace_cpu_dropped_events_end",6,"error","trace",0
-"ftrace_cpu_dropped_events_end",7,"error","trace",0
+"ftrace_cpu_bytes_read_delta",0,"info","trace",20236
+"ftrace_cpu_bytes_read_delta",1,"info","trace",11380
+"ftrace_cpu_bytes_read_delta",2,"info","trace",12336
+"ftrace_cpu_bytes_read_delta",3,"info","trace",6236
+"ftrace_cpu_bytes_read_delta",4,"info","trace",2676
+"ftrace_cpu_bytes_read_delta",5,"info","trace",1188
+"ftrace_cpu_bytes_read_delta",6,"info","trace",1576
+"ftrace_cpu_bytes_read_delta",7,"info","trace",3264
+"ftrace_cpu_commit_overrun_begin",0,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",1,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",2,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",3,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",4,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",5,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",6,"info","trace",0
+"ftrace_cpu_commit_overrun_begin",7,"info","trace",0
+"ftrace_cpu_commit_overrun_end",0,"info","trace",0
+"ftrace_cpu_commit_overrun_end",1,"info","trace",0
+"ftrace_cpu_commit_overrun_end",2,"info","trace",0
+"ftrace_cpu_commit_overrun_end",3,"info","trace",0
+"ftrace_cpu_commit_overrun_end",4,"info","trace",0
+"ftrace_cpu_commit_overrun_end",5,"info","trace",0
+"ftrace_cpu_commit_overrun_end",6,"info","trace",0
+"ftrace_cpu_commit_overrun_end",7,"info","trace",0
+"ftrace_cpu_commit_overrun_delta",0,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",1,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",2,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",3,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",4,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",5,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",6,"error","trace",0
+"ftrace_cpu_commit_overrun_delta",7,"error","trace",0
+"ftrace_cpu_dropped_events_begin",0,"info","trace",0
+"ftrace_cpu_dropped_events_begin",1,"info","trace",0
+"ftrace_cpu_dropped_events_begin",2,"info","trace",0
+"ftrace_cpu_dropped_events_begin",3,"info","trace",0
+"ftrace_cpu_dropped_events_begin",4,"info","trace",0
+"ftrace_cpu_dropped_events_begin",5,"info","trace",0
+"ftrace_cpu_dropped_events_begin",6,"info","trace",0
+"ftrace_cpu_dropped_events_begin",7,"info","trace",0
+"ftrace_cpu_dropped_events_end",0,"info","trace",0
+"ftrace_cpu_dropped_events_end",1,"info","trace",0
+"ftrace_cpu_dropped_events_end",2,"info","trace",0
+"ftrace_cpu_dropped_events_end",3,"info","trace",0
+"ftrace_cpu_dropped_events_end",4,"info","trace",0
+"ftrace_cpu_dropped_events_end",5,"info","trace",0
+"ftrace_cpu_dropped_events_end",6,"info","trace",0
+"ftrace_cpu_dropped_events_end",7,"info","trace",0
+"ftrace_cpu_dropped_events_delta",0,"error","trace",0
+"ftrace_cpu_dropped_events_delta",1,"error","trace",0
+"ftrace_cpu_dropped_events_delta",2,"error","trace",0
+"ftrace_cpu_dropped_events_delta",3,"error","trace",0
+"ftrace_cpu_dropped_events_delta",4,"error","trace",0
+"ftrace_cpu_dropped_events_delta",5,"error","trace",0
+"ftrace_cpu_dropped_events_delta",6,"error","trace",0
+"ftrace_cpu_dropped_events_delta",7,"error","trace",0
"ftrace_cpu_entries_begin",0,"info","trace",4
"ftrace_cpu_entries_begin",1,"info","trace",4
"ftrace_cpu_entries_begin",2,"info","trace",23
@@ -63,6 +87,14 @@
"ftrace_cpu_entries_end",5,"info","trace",21
"ftrace_cpu_entries_end",6,"info","trace",26
"ftrace_cpu_entries_end",7,"info","trace",54
+"ftrace_cpu_entries_delta",0,"info","trace",337
+"ftrace_cpu_entries_delta",1,"info","trace",191
+"ftrace_cpu_entries_delta",2,"info","trace",202
+"ftrace_cpu_entries_delta",3,"info","trace",107
+"ftrace_cpu_entries_delta",4,"info","trace",45
+"ftrace_cpu_entries_delta",5,"info","trace",21
+"ftrace_cpu_entries_delta",6,"info","trace",26
+"ftrace_cpu_entries_delta",7,"info","trace",54
"ftrace_cpu_now_ts_begin",0,"info","trace",81473010735000
"ftrace_cpu_now_ts_begin",1,"info","trace",81473010800000
"ftrace_cpu_now_ts_begin",2,"info","trace",81473010839000
@@ -103,14 +135,22 @@
"ftrace_cpu_overrun_begin",5,"info","trace",0
"ftrace_cpu_overrun_begin",6,"info","trace",0
"ftrace_cpu_overrun_begin",7,"info","trace",0
-"ftrace_cpu_overrun_end",0,"data_loss","trace",0
-"ftrace_cpu_overrun_end",1,"data_loss","trace",0
-"ftrace_cpu_overrun_end",2,"data_loss","trace",0
-"ftrace_cpu_overrun_end",3,"data_loss","trace",0
-"ftrace_cpu_overrun_end",4,"data_loss","trace",0
-"ftrace_cpu_overrun_end",5,"data_loss","trace",0
-"ftrace_cpu_overrun_end",6,"data_loss","trace",0
-"ftrace_cpu_overrun_end",7,"data_loss","trace",0
+"ftrace_cpu_overrun_end",0,"info","trace",0
+"ftrace_cpu_overrun_end",1,"info","trace",0
+"ftrace_cpu_overrun_end",2,"info","trace",0
+"ftrace_cpu_overrun_end",3,"info","trace",0
+"ftrace_cpu_overrun_end",4,"info","trace",0
+"ftrace_cpu_overrun_end",5,"info","trace",0
+"ftrace_cpu_overrun_end",6,"info","trace",0
+"ftrace_cpu_overrun_end",7,"info","trace",0
+"ftrace_cpu_overrun_delta",0,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",1,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",2,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",3,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",4,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",5,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",6,"data_loss","trace",0
+"ftrace_cpu_overrun_delta",7,"data_loss","trace",0
"ftrace_cpu_read_events_begin",0,"info","trace",0
"ftrace_cpu_read_events_begin",1,"info","trace",0
"ftrace_cpu_read_events_begin",2,"info","trace",0
@@ -127,6 +167,14 @@
"ftrace_cpu_read_events_end",5,"info","trace",23232
"ftrace_cpu_read_events_end",6,"info","trace",36733
"ftrace_cpu_read_events_end",7,"info","trace",39240
+"ftrace_cpu_read_events_delta",0,"info","trace",62303
+"ftrace_cpu_read_events_delta",1,"info","trace",54916
+"ftrace_cpu_read_events_delta",2,"info","trace",55882
+"ftrace_cpu_read_events_delta",3,"info","trace",47953
+"ftrace_cpu_read_events_delta",4,"info","trace",31345
+"ftrace_cpu_read_events_delta",5,"info","trace",23232
+"ftrace_cpu_read_events_delta",6,"info","trace",36733
+"ftrace_cpu_read_events_delta",7,"info","trace",39240
"traced_buf_buffer_size",0,"info","trace",0
"traced_buf_bytes_overwritten",0,"info","trace",0
"traced_buf_bytes_read",0,"info","trace",0