trace_processor: add support for sched priorities and descheduling reason
Bug: 122876520
Change-Id: I06efa2c4363a2430d865deb5af7bcfeee96a23cf
diff --git a/src/trace_processor/event_tracker.cc b/src/trace_processor/event_tracker.cc
index d4f8b9a..63df47e 100644
--- a/src/trace_processor/event_tracker.cc
+++ b/src/trace_processor/event_tracker.cc
@@ -38,9 +38,10 @@
void EventTracker::PushSchedSwitch(uint32_t cpu,
int64_t timestamp,
uint32_t prev_pid,
- uint32_t,
+ int64_t prev_state,
uint32_t next_pid,
- base::StringView next_comm) {
+ base::StringView next_comm,
+ int32_t next_priority) {
// At this stage all events should be globally timestamp ordered.
if (timestamp < prev_timestamp_) {
PERFETTO_ELOG("sched_switch event out of order by %.4f ms, skipping",
@@ -54,21 +55,26 @@
auto* slices = context_->storage->mutable_slices();
auto* pending_slice = &pending_sched_per_cpu_[cpu];
if (pending_slice->storage_index < std::numeric_limits<size_t>::max()) {
- // If the this events previous pid does not match the previous event's next
- // pid, make a note of this.
- if (prev_pid != pending_slice->pid) {
- context_->storage->IncrementStats(stats::mismatched_sched_switch_tids);
- }
-
size_t idx = pending_slice->storage_index;
int64_t duration = timestamp - slices->start_ns()[idx];
slices->set_duration(idx, duration);
+
+ if (prev_pid == pending_slice->pid) {
+ // TODO(lalitm): make use of prev_state.
+ perfetto::base::ignore_result(prev_state);
+ } else {
+ // If the this events previous pid does not match the previous event's
+ // next pid, make a note of this.
+ context_->storage->IncrementStats(stats::mismatched_sched_switch_tids);
+ }
}
StringId name_id = GetThreadNameId(next_pid, next_comm);
auto utid =
context_->process_tracker->UpdateThread(timestamp, next_pid, name_id);
+ // TODO(lalitm): make use of next_priority.
+ perfetto::base::ignore_result(next_priority);
pending_slice->storage_index =
slices->AddSlice(cpu, timestamp, 0 /* duration */, utid);
pending_slice->pid = next_pid;
diff --git a/src/trace_processor/event_tracker.h b/src/trace_processor/event_tracker.h
index 7a60bc3..25c3d0f 100644
--- a/src/trace_processor/event_tracker.h
+++ b/src/trace_processor/event_tracker.h
@@ -44,9 +44,10 @@
virtual void PushSchedSwitch(uint32_t cpu,
int64_t timestamp,
uint32_t prev_pid,
- uint32_t prev_state,
+ int64_t prev_state,
uint32_t next_pid,
- base::StringView next_comm);
+ base::StringView next_comm,
+ int32_t next_priority);
// This method is called when a cpu freq event is seen in the trace.
virtual RowId PushCounter(int64_t timestamp,
diff --git a/src/trace_processor/event_tracker_unittest.cc b/src/trace_processor/event_tracker_unittest.cc
index 44d67c9..adcb4e8 100644
--- a/src/trace_processor/event_tracker_unittest.cc
+++ b/src/trace_processor/event_tracker_unittest.cc
@@ -43,18 +43,19 @@
uint32_t cpu = 3;
int64_t timestamp = 100;
uint32_t pid_1 = 2;
- uint32_t prev_state = 32;
+ int64_t prev_state = 32;
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
uint32_t pid_2 = 4;
+ int32_t next_prio = 1024;
const auto& timestamps = context.storage->slices().start_ns();
context.event_tracker->PushSchedSwitch(cpu, timestamp, pid_1, prev_state,
- pid_2, kCommProc1);
+ pid_2, kCommProc1, next_prio);
ASSERT_EQ(timestamps.size(), 1);
context.event_tracker->PushSchedSwitch(cpu, timestamp + 1, pid_2, prev_state,
- pid_1, kCommProc2);
+ pid_1, kCommProc2, next_prio);
ASSERT_EQ(timestamps.size(), 2ul);
ASSERT_EQ(timestamps[0], timestamp);
@@ -63,29 +64,31 @@
context.storage->GetThread(1).name_id)),
kCommProc1);
ASSERT_EQ(context.storage->slices().utids().front(), 1);
+ ASSERT_EQ(context.storage->slices().durations().front(), 1);
}
TEST_F(EventTrackerTest, InsertThirdSched_SameThread) {
uint32_t cpu = 3;
int64_t timestamp = 100;
- uint32_t prev_state = 32;
+ int64_t prev_state = 32;
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
+ int32_t next_prio = 1024;
const auto& timestamps = context.storage->slices().start_ns();
context.event_tracker->PushSchedSwitch(cpu, timestamp, /*tid=*/4, prev_state,
- /*tid=*/2, kCommProc1);
+ /*tid=*/2, kCommProc1, next_prio);
ASSERT_EQ(timestamps.size(), 1);
context.event_tracker->PushSchedSwitch(cpu, timestamp + 1, /*tid=*/2,
prev_state,
- /*tid=*/4, kCommProc1);
+ /*tid=*/4, kCommProc1, next_prio);
context.event_tracker->PushSchedSwitch(cpu, timestamp + 11, /*tid=*/4,
prev_state,
- /*tid=*/2, kCommProc2);
+ /*tid=*/2, kCommProc2, next_prio);
context.event_tracker->PushSchedSwitch(cpu, timestamp + 31, /*tid=*/4,
prev_state,
- /*tid=*/2, kCommProc1);
+ /*tid=*/2, kCommProc1, next_prio);
ASSERT_EQ(timestamps.size(), 4ul);
ASSERT_EQ(timestamps[0], timestamp);
diff --git a/src/trace_processor/process_tracker_unittest.cc b/src/trace_processor/process_tracker_unittest.cc
index 15e8856..50f5dd7 100644
--- a/src/trace_processor/process_tracker_unittest.cc
+++ b/src/trace_processor/process_tracker_unittest.cc
@@ -72,14 +72,16 @@
TEST_F(ProcessTrackerTest, UpdateThreadMatch) {
uint32_t cpu = 3;
int64_t timestamp = 100;
- uint32_t prev_state = 32;
+ int64_t prev_state = 32;
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
+ int32_t next_prio = 1024;
context.event_tracker->PushSchedSwitch(cpu, timestamp, /*tid=*/1, prev_state,
- /*tid=*/4, kCommProc1);
+ /*tid=*/4, kCommProc1, next_prio);
context.event_tracker->PushSchedSwitch(cpu, timestamp + 1, /*tid=*/4,
- prev_state, /*tid=*/1, kCommProc2);
+ prev_state, /*tid=*/1, kCommProc2,
+ next_prio);
context.process_tracker->UpdateProcess(2, "test");
context.process_tracker->UpdateThread(4, 2);
diff --git a/src/trace_processor/proto_trace_parser.cc b/src/trace_processor/proto_trace_parser.cc
index aaf0cfd..7a802d8 100644
--- a/src/trace_processor/proto_trace_parser.cc
+++ b/src/trace_processor/proto_trace_parser.cc
@@ -849,16 +849,17 @@
ProtoDecoder decoder(sswitch.data(), sswitch.length());
uint32_t prev_pid = 0;
- uint32_t prev_state = 0;
+ int64_t prev_state = 0;
base::StringView next_comm;
uint32_t next_pid = 0;
+ int32_t next_prio = 0;
for (auto fld = decoder.ReadField(); fld.id != 0; fld = decoder.ReadField()) {
switch (fld.id) {
case protos::SchedSwitchFtraceEvent::kPrevPidFieldNumber:
prev_pid = fld.as_uint32();
break;
case protos::SchedSwitchFtraceEvent::kPrevStateFieldNumber:
- prev_state = fld.as_uint32();
+ prev_state = fld.as_int64();
break;
case protos::SchedSwitchFtraceEvent::kNextPidFieldNumber:
next_pid = fld.as_uint32();
@@ -866,12 +867,15 @@
case protos::SchedSwitchFtraceEvent::kNextCommFieldNumber:
next_comm = fld.as_string();
break;
+ case protos::SchedSwitchFtraceEvent::kNextPrioFieldNumber:
+ next_prio = fld.as_int32();
+ break;
default:
break;
}
}
context_->event_tracker->PushSchedSwitch(cpu, timestamp, prev_pid, prev_state,
- next_pid, next_comm);
+ next_pid, next_comm, next_prio);
PERFETTO_DCHECK(decoder.IsEndOfBuffer());
}
diff --git a/src/trace_processor/proto_trace_parser_unittest.cc b/src/trace_processor/proto_trace_parser_unittest.cc
index 0da3f63..3612a34 100644
--- a/src/trace_processor/proto_trace_parser_unittest.cc
+++ b/src/trace_processor/proto_trace_parser_unittest.cc
@@ -43,13 +43,14 @@
MockEventTracker(TraceProcessorContext* context) : EventTracker(context) {}
virtual ~MockEventTracker() = default;
- MOCK_METHOD6(PushSchedSwitch,
+ MOCK_METHOD7(PushSchedSwitch,
void(uint32_t cpu,
int64_t timestamp,
uint32_t prev_pid,
- uint32_t prev_state,
+ int64_t prev_state,
uint32_t next_pid,
- base::StringView next_comm));
+ base::StringView next_comm,
+ int32_t next_priority));
MOCK_METHOD5(PushCounter,
RowId(int64_t timestamp,
@@ -128,9 +129,10 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName);
sched_switch->set_next_pid(100);
+ sched_switch->set_next_prio(1024);
EXPECT_CALL(*event_, PushSchedSwitch(10, 1000, 10, 32, 100,
- base::StringView(kProcName)));
+ base::StringView(kProcName), 1024));
Tokenize(trace);
}
@@ -272,6 +274,7 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName1);
sched_switch->set_next_pid(100);
+ sched_switch->set_next_prio(1024);
event = bundle->add_event();
event->set_timestamp(1001);
@@ -283,12 +286,13 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName2);
sched_switch->set_next_pid(10);
+ sched_switch->set_next_prio(512);
EXPECT_CALL(*event_, PushSchedSwitch(10, 1000, 10, 32, 100,
- base::StringView(kProcName1)));
+ base::StringView(kProcName1), 1024));
EXPECT_CALL(*event_, PushSchedSwitch(10, 1001, 100, 32, 10,
- base::StringView(kProcName2)));
+ base::StringView(kProcName2), 512));
Tokenize(trace);
}
@@ -309,6 +313,7 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName1);
sched_switch->set_next_pid(100);
+ sched_switch->set_next_prio(1024);
bundle = trace.add_packet()->mutable_ftrace_events();
bundle->set_cpu(10);
@@ -323,12 +328,13 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName2);
sched_switch->set_next_pid(10);
+ sched_switch->set_next_prio(512);
EXPECT_CALL(*event_, PushSchedSwitch(10, 1000, 10, 32, 100,
- base::StringView(kProcName1)));
+ base::StringView(kProcName1), 1024));
EXPECT_CALL(*event_, PushSchedSwitch(10, 1001, 100, 32, 10,
- base::StringView(kProcName2)));
+ base::StringView(kProcName2), 512));
Tokenize(trace);
}
@@ -345,6 +351,7 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName1);
sched_switch->set_next_pid(100);
+ sched_switch->set_next_prio(1024);
protos::Trace trace_2;
bundle = trace_2.add_packet()->mutable_ftrace_events();
@@ -358,13 +365,14 @@
sched_switch->set_prev_state(32);
sched_switch->set_next_comm(kProcName2);
sched_switch->set_next_pid(10);
+ sched_switch->set_next_prio(512);
EXPECT_CALL(*event_, PushSchedSwitch(10, 1000, 10, 32, 100,
- base::StringView(kProcName1)));
+ base::StringView(kProcName1), 1024));
Tokenize(trace_1);
EXPECT_CALL(*event_, PushSchedSwitch(10, 1001, 100, 32, 10,
- base::StringView(kProcName2)));
+ base::StringView(kProcName2), 512));
Tokenize(trace_2);
}
diff --git a/src/trace_processor/sched_slice_table_unittest.cc b/src/trace_processor/sched_slice_table_unittest.cc
index a979913..132cae3 100644
--- a/src/trace_processor/sched_slice_table_unittest.cc
+++ b/src/trace_processor/sched_slice_table_unittest.cc
@@ -65,18 +65,19 @@
uint32_t cpu = 3;
int64_t timestamp = 100;
uint32_t pid_1 = 2;
- uint32_t prev_state = 32;
+ int64_t prev_state = 32;
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
uint32_t pid_2 = 4;
+ int32_t next_prio = 1024;
context_.event_tracker->PushSchedSwitch(cpu, timestamp, pid_1, prev_state,
- pid_2, kCommProc1);
+ pid_2, kCommProc1, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 3, pid_2, prev_state,
- pid_1, kCommProc2);
+ pid_1, kCommProc2, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 4, pid_1, prev_state,
- pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu, timestamp + 10, pid_2,
- prev_state, pid_1, kCommProc2);
+ pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu, timestamp + 10, pid_2, prev_state, pid_1, kCommProc2, next_prio);
PrepareValidStatement(
"SELECT dur, ts, cpu FROM sched where dur != 0 ORDER BY dur");
@@ -105,22 +106,23 @@
uint32_t cpu_3 = 4;
int64_t timestamp = 100;
uint32_t pid_1 = 2;
- uint32_t prev_state = 32;
+ int64_t prev_state = 32;
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
uint32_t pid_2 = 4;
- context_.event_tracker->PushSchedSwitch(cpu_3, timestamp - 2, pid_1,
- prev_state, pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu_3, timestamp - 1, pid_2,
- prev_state, pid_1, kCommProc2);
+ int32_t next_prio = 1024;
+ context_.event_tracker->PushSchedSwitch(
+ cpu_3, timestamp - 2, pid_1, prev_state, pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_3, timestamp - 1, pid_2, prev_state, pid_1, kCommProc2, next_prio);
context_.event_tracker->PushSchedSwitch(cpu_1, timestamp, pid_1, prev_state,
- pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu_2, timestamp + 3, pid_2,
- prev_state, pid_1, kCommProc2);
- context_.event_tracker->PushSchedSwitch(cpu_1, timestamp + 4, pid_1,
- prev_state, pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu_2, timestamp + 10, pid_2,
- prev_state, pid_1, kCommProc2);
+ pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_2, timestamp + 3, pid_2, prev_state, pid_1, kCommProc2, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_1, timestamp + 4, pid_1, prev_state, pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_2, timestamp + 10, pid_2, prev_state, pid_1, kCommProc2, next_prio);
PrepareValidStatement(
"SELECT dur, ts, cpu FROM sched where dur != 0 ORDER BY dur desc");
@@ -152,14 +154,15 @@
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
uint32_t pid_2 = 4;
+ int32_t next_prio = 1024;
context_.event_tracker->PushSchedSwitch(cpu_1, timestamp, pid_1, prev_state,
- pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu_2, timestamp + 3, pid_2,
- prev_state, pid_1, kCommProc2);
- context_.event_tracker->PushSchedSwitch(cpu_1, timestamp + 4, pid_1,
- prev_state, pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu_2, timestamp + 10, pid_2,
- prev_state, pid_1, kCommProc2);
+ pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_2, timestamp + 3, pid_2, prev_state, pid_1, kCommProc2, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_1, timestamp + 4, pid_1, prev_state, pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu_2, timestamp + 10, pid_2, prev_state, pid_1, kCommProc2, next_prio);
PrepareValidStatement(
"SELECT dur, ts, cpu FROM sched WHERE dur != 0 and cpu = 3");
@@ -180,14 +183,15 @@
static const char kCommProc1[] = "process1";
static const char kCommProc2[] = "process2";
uint32_t pid_2 = 4;
+ int32_t next_prio = 1024;
context_.event_tracker->PushSchedSwitch(cpu, timestamp, pid_1, prev_state,
- pid_2, kCommProc1);
+ pid_2, kCommProc1, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 3, pid_2, prev_state,
- pid_1, kCommProc2);
+ pid_1, kCommProc2, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 4, pid_1, prev_state,
- pid_2, kCommProc1);
- context_.event_tracker->PushSchedSwitch(cpu, timestamp + 10, pid_2,
- prev_state, pid_1, kCommProc2);
+ pid_2, kCommProc1, next_prio);
+ context_.event_tracker->PushSchedSwitch(
+ cpu, timestamp + 10, pid_2, prev_state, pid_1, kCommProc2, next_prio);
PrepareValidStatement("SELECT utid FROM sched where dur != 0 ORDER BY utid");
@@ -208,17 +212,18 @@
uint32_t cpu_7 = 7;
uint32_t pid_1 = 1;
uint32_t pid_2 = 2;
- uint32_t prev_state = 32;
+ int64_t prev_state = 32;
+ int32_t next_prio = 1024;
// Fill |cpu_5| and |cpu_7) with one sched switch per time unit starting,
// respectively, @ T=50 and T=70.
for (int64_t i = 0; i <= 11; i++) {
context_.event_tracker->PushSchedSwitch(cpu_5, 50 + i, pid_1, prev_state,
- pid_1, "pid_1");
+ pid_1, "pid_1", next_prio);
}
for (int64_t i = 0; i <= 11; i++) {
context_.event_tracker->PushSchedSwitch(cpu_7, 70 + i, pid_2, prev_state,
- pid_2, "pid_2");
+ pid_2, "pid_2", next_prio);
}
auto query = [this](const std::string& where_clauses) {
diff --git a/src/trace_processor/thread_table_unittest.cc b/src/trace_processor/thread_table_unittest.cc
index c8136a0..cdb4316 100644
--- a/src/trace_processor/thread_table_unittest.cc
+++ b/src/trace_processor/thread_table_unittest.cc
@@ -69,11 +69,13 @@
uint32_t prev_state = 32;
static const char kThreadName1[] = "thread1";
static const char kThreadName2[] = "thread2";
+ int32_t next_prio = 1024;
context_.event_tracker->PushSchedSwitch(cpu, timestamp, /*tid=*/1, prev_state,
- /*tid=*/4, kThreadName1);
+ /*tid=*/4, kThreadName1, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 1, /*tid=*/4,
- prev_state, /*tid=*/1, kThreadName2);
+ prev_state, /*tid=*/1, kThreadName2,
+ next_prio);
context_.process_tracker->UpdateProcess(2, "test");
context_.process_tracker->UpdateThread(4 /*tid*/, 2 /*pid*/);
@@ -94,14 +96,16 @@
uint32_t prev_state = 32;
static const char kThreadName1[] = "thread1";
static const char kThreadName2[] = "thread2";
+ int32_t next_prio = 1024;
context_.event_tracker->PushSchedSwitch(cpu, timestamp, /*tid=*/1, prev_state,
- /*tid=*/4, kThreadName1);
+ /*tid=*/4, kThreadName1, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 1, /*tid=*/4,
prev_state,
- /*tid=*/1, kThreadName2);
+ /*tid=*/1, kThreadName2, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 2, /*tid=*/1,
- prev_state, /*tid=*/4, kThreadName1);
+ prev_state, /*tid=*/4, kThreadName1,
+ next_prio);
context_.process_tracker->UpdateProcess(2, "test");
context_.process_tracker->UpdateThread(4 /*tid*/, 2 /*pid*/);
@@ -124,12 +128,13 @@
uint32_t prev_state = 32;
static const char kThreadName1[] = "thread1";
static const char kThreadName2[] = "thread2";
+ int32_t next_prio = 1024;
context_.event_tracker->PushSchedSwitch(cpu, timestamp, /*tid=*/1, prev_state,
- /*tid=*/4, kThreadName1);
+ /*tid=*/4, kThreadName1, next_prio);
context_.event_tracker->PushSchedSwitch(cpu, timestamp + 1, /*tid=*/4,
prev_state,
- /*tid=*/1, kThreadName2);
+ /*tid=*/1, kThreadName2, next_prio);
// Also create a process for which we haven't seen any thread.
context_.process_tracker->UpdateProcess(7, "pid7");