tp: match android framework process start/death by start_seq Add a start_seq field to AndroidProcessStartEvent, AndroidProcessDiedEvent and AndroidBinderDiedEvent, and use it in the android_framework_track_event plugin to match a process instance's start and death events (robust to pid reuse). Handle AndroidProcessDiedEvent to associate an exit reason with the process: the order of process_died and binder_died is not guaranteed, so whichever arrives first ends the process, and process_died records the AppExit reason/sub_reason even if the process was already ended by binder_died. Change-Id: I116ec07334e2f194635299cf44620e7c2dfd7b1c
diff --git a/protos/third_party/android/frameworks/base/proto/tracing/frameworks_base_track_event.proto b/protos/third_party/android/frameworks/base/proto/tracing/frameworks_base_track_event.proto index 2217fcd..6db2350 100644 --- a/protos/third_party/android/frameworks/base/proto/tracing/frameworks_base_track_event.proto +++ b/protos/third_party/android/frameworks/base/proto/tracing/frameworks_base_track_event.proto
@@ -650,6 +650,10 @@ // Whether the process was spawned from the native or legacy zygote variant. optional HostingZygoteVariant hosting_zygote_variant = 9; + + // Sequence number of the process start; matches the start/death events of + // the same process instance even across pid reuse. + optional int64 start_seq = 10; } // This can be delayed for up to 15s in some cases. It should typically @@ -678,6 +682,10 @@ // Whether or not this process is hosting one or more foreground services. optional int32 has_foreground_services = 8; + + // Sequence number of the process start; matches the start/death events of + // the same process instance even across pid reuse. + optional int64 start_seq = 9; } // This is expected to come earlier than AndroidProcessDiedEvent. @@ -691,6 +699,10 @@ // The process name of the dying process. optional string process_name = 3; + + // Sequence number of the process start; matches the start/death events of + // the same process instance even across pid reuse. + optional int64 start_seq = 4; } message AndroidProcessStateChangedEvent {
diff --git a/src/trace_processor/plugins/android_framework_track_event/android_framework_track_event.cc b/src/trace_processor/plugins/android_framework_track_event/android_framework_track_event.cc index cb3f764..033b526 100644 --- a/src/trace_processor/plugins/android_framework_track_event/android_framework_track_event.cc +++ b/src/trace_processor/plugins/android_framework_track_event/android_framework_track_event.cc
@@ -44,10 +44,13 @@ ::com::android::internal::pbzero::AndroidProcessStartEvent; using AndroidBinderDiedEvent = ::com::android::internal::pbzero::AndroidBinderDiedEvent; +using AndroidProcessDiedEvent = + ::com::android::internal::pbzero::AndroidProcessDiedEvent; using AndroidTrackEventProcessTable = tables::AndroidTrackEventProcessTable; -// Records AndroidProcessStartEvent and AndroidBinderDiedEvent into -// __intrinsic_android_track_event_process. +// Records AndroidProcessStartEvent, AndroidProcessDiedEvent and +// AndroidBinderDiedEvent into __intrinsic_android_track_event_process. A +// process instance's start and death events are matched by |start_seq|. class Parser : public TrackEventExtensionParser { public: Parser(TrackEventExtensionParserContext* extension_parser_context, @@ -57,6 +60,7 @@ trace_context_(context), table_(table) { RegisterTrackEventExtension(FBTE::kProcessStartEventFieldNumber); + RegisterTrackEventExtension(FBTE::kProcessDiedEventFieldNumber); RegisterTrackEventExtension(FBTE::kBinderDiedEventFieldNumber); } ~Parser() override = default; @@ -68,6 +72,9 @@ case FBTE::kProcessStartEventFieldNumber: HandleProcessStart(field.Cast<FBTE::kProcessStartEvent>(), ts); break; + case FBTE::kProcessDiedEventFieldNumber: + HandleProcessDied(field.Cast<FBTE::kProcessDiedEvent>(), ts); + break; case FBTE::kBinderDiedEventFieldNumber: HandleBinderDied(field.Cast<FBTE::kBinderDiedEvent>(), ts); break; @@ -91,27 +98,52 @@ } } - AndroidTrackEventProcessTable::RowReference GetOrInsertRow(UniquePid upid) { - auto it_and_ins = - upid_to_row_.Insert(upid, AndroidTrackEventProcessTable::Id{0}); - if (it_and_ins.second) { + // Returns (creating if needed) the row for process instance |start_seq|. + AndroidTrackEventProcessTable::RowReference GetOrInsertRow(int64_t start_seq, + UniquePid upid) { + auto ins = + seq_to_row_.Insert(start_seq, AndroidTrackEventProcessTable::Id{0}); + if (ins.second) { AndroidTrackEventProcessTable::Row row; row.upid = upid; - *it_and_ins.first = table_->Insert(row).id; + row.start_seq = start_seq; + *ins.first = table_->Insert(row).id; } - return (*table_)[*it_and_ins.first]; + return (*table_)[*ins.first]; + } + + // Returns the existing row for |start_seq|, or nullopt if its start was + // not seen. + std::optional<AndroidTrackEventProcessTable::RowReference> FindRow( + int64_t start_seq) { + auto* id = seq_to_row_.Find(start_seq); + if (!id) { + return std::nullopt; + } + return (*table_)[*id]; + } + + // Ends the process instance at |ts| if it has not already been ended. + void CloseProcess(AndroidTrackEventProcessTable::RowReference row, + int64_t ts, + uint32_t pid) { + if (row.fw_end_ts().has_value()) { + return; + } + row.set_fw_end_ts(ts); + trace_context_->process_tracker->EndThread(ts, pid); } void HandleProcessStart(protozero::ConstBytes data, int64_t ts) { AndroidProcessStartEvent::Decoder evt(data); - if (!evt.has_pid()) { + if (!evt.has_pid() || !evt.has_start_seq()) { return; } UniquePid upid = trace_context_->process_tracker->GetOrCreateProcess( static_cast<uint32_t>(evt.pid())); SetProcessMetadata(upid, data); - auto row = GetOrInsertRow(upid); + auto row = GetOrInsertRow(evt.start_seq(), upid); if (!row.fw_start_ts().has_value()) { row.set_fw_start_ts(ts); } @@ -137,26 +169,39 @@ } } + // Binder died carries no exit reason: just end the instance if still active. void HandleBinderDied(protozero::ConstBytes data, int64_t ts) { AndroidBinderDiedEvent::Decoder evt(data); - if (!evt.has_pid()) { + if (!evt.has_pid() || !evt.has_start_seq()) { return; } + if (auto row = FindRow(evt.start_seq())) { + CloseProcess(*row, ts, static_cast<uint32_t>(evt.pid())); + } + } - std::optional<UniqueTid> utid = - trace_context_->process_tracker->GetThreadOrNull( - static_cast<uint32_t>(evt.pid())); - if (!utid) { + // Process died carries the exit reason: record it even if the instance was + // already ended (e.g. by a binder-died), and end the instance if active. + void HandleProcessDied(protozero::ConstBytes data, int64_t ts) { + AndroidProcessDiedEvent::Decoder evt(data); + if (!evt.has_pid() || !evt.has_start_seq()) { return; } - std::optional<UniquePid> upid = - trace_context_->storage->thread_table()[*utid].upid(); - if (!upid) { + auto row = FindRow(evt.start_seq()); + if (!row) { return; } - GetOrInsertRow(*upid).set_fw_end_ts(ts); - trace_context_->process_tracker->EndThread( - ts, static_cast<uint32_t>(evt.pid())); + if (evt.has_reason()) { + row->set_reason(InternEnum(reason_cache_, + ".com.android.internal.AppExitReasonCode", + static_cast<int32_t>(evt.reason()))); + } + if (evt.has_sub_reason()) { + row->set_sub_reason(InternEnum( + sub_reason_cache_, ".com.android.internal.AppExitSubReasonCode", + static_cast<int32_t>(evt.sub_reason()))); + } + CloseProcess(*row, ts, static_cast<uint32_t>(evt.pid())); } StringId InternEnum(DescriptorPool::CachedDescriptor& cache, @@ -171,8 +216,10 @@ TraceProcessorContext* trace_context_; DescriptorPool::CachedDescriptor trigger_type_cache_; DescriptorPool::CachedDescriptor hosting_type_cache_; + DescriptorPool::CachedDescriptor reason_cache_; + DescriptorPool::CachedDescriptor sub_reason_cache_; AndroidTrackEventProcessTable* table_; - base::FlatHashMap<UniquePid, AndroidTrackEventProcessTable::Id> upid_to_row_; + base::FlatHashMap<int64_t, AndroidTrackEventProcessTable::Id> seq_to_row_; }; class AndroidFrameworkTrackEventPlugin
diff --git a/src/trace_processor/plugins/android_framework_track_event/tables.py b/src/trace_processor/plugins/android_framework_track_event/tables.py index c2e82b2..eeb6030 100644 --- a/src/trace_processor/plugins/android_framework_track_event/tables.py +++ b/src/trace_processor/plugins/android_framework_track_event/tables.py
@@ -50,6 +50,15 @@ C('process_start_delay_ms', CppOptional(CppInt64()), cpp_access=CppAccess.READ_AND_HIGH_PERF_WRITE), + C('start_seq', + CppOptional(CppInt64()), + cpp_access=CppAccess.READ_AND_HIGH_PERF_WRITE), + C('reason', + CppOptional(CppString()), + cpp_access=CppAccess.READ_AND_HIGH_PERF_WRITE), + C('sub_reason', + CppOptional(CppString()), + cpp_access=CppAccess.READ_AND_HIGH_PERF_WRITE), ], tabledoc=TableDoc( doc='Per-process lifecycle from Android framework TrackEvents.', @@ -71,6 +80,12 @@ 'Milliseconds to reach bind application.', 'process_start_delay_ms': 'Milliseconds to finish starting the process.', + 'start_seq': + 'Framework start sequence matching this instance.', + 'reason': + 'AppExitReasonCode from AndroidProcessDiedEvent.', + 'sub_reason': + 'AppExitSubReasonCode from AndroidProcessDiedEvent.', }, ), )
diff --git a/test/trace_processor/diff_tests/parser/android/android_framework_track_event.textproto b/test/trace_processor/diff_tests/parser/android/android_framework_track_event.textproto index e85414c..d79e8ea 100644 --- a/test/trace_processor/diff_tests/parser/android/android_framework_track_event.textproto +++ b/test/trace_processor/diff_tests/parser/android/android_framework_track_event.textproto
@@ -25,6 +25,7 @@ uid: 10001 pid: 100 process_name: "com.example.app" + start_seq: 1 } } } @@ -41,6 +42,7 @@ uid: 10001 pid: 100 process_name: "com.example.app" + start_seq: 1 } } } @@ -56,6 +58,7 @@ uid: 10001 pid: 100 process_name: "com.example.app" + start_seq: 1 } } }
diff --git a/test/trace_processor/diff_tests/parser/android/android_framework_track_event_process_death.textproto b/test/trace_processor/diff_tests/parser/android/android_framework_track_event_process_death.textproto new file mode 100644 index 0000000..9eea17a --- /dev/null +++ b/test/trace_processor/diff_tests/parser/android/android_framework_track_event_process_death.textproto
@@ -0,0 +1,69 @@ +# Exercises process-death matching in the android_framework_track_event plugin. +# start / binder_died / process_died are matched by start_seq, in either order; +# whichever death comes first ends the process, and process_died always records +# the exit reason (even if already ended by binder_died). +packet { + trusted_packet_sequence_id: 1 + timestamp: 0 + incremental_state_cleared: true + track_descriptor { uuid: 2 thread { pid: 100 tid: 100 thread_name: "procA" } } +} +packet { + trusted_packet_sequence_id: 1 + timestamp: 1 + track_descriptor { uuid: 3 thread { pid: 200 tid: 200 thread_name: "procB" } } +} +# Exit-reason enums so reason/sub_reason resolve to names. +packet { + trusted_packet_sequence_id: 1 + timestamp: 2 + extension_descriptor { + extension_set { + file { + package: "com.android.internal" + name: "fbte_exit_enums.proto" + enum_type { + name: "AppExitReasonCode" + value { name: "APP_EXIT_REASON_CRASH" number: 4 } + value { name: "APP_EXIT_REASON_ANR" number: 6 } + } + enum_type { + name: "AppExitSubReasonCode" + value { name: "APP_EXIT_SUBREASON_TOO_MANY_CACHED" number: 2 } + } + } + } + } +} +# A: start (seq 1). +packet { trusted_packet_sequence_id: 1 timestamp: 1000 track_event { + type: TYPE_INSTANT track_uuid: 2 name: "start_A" + [com.android.internal.FrameworksBaseTrackEvent.process_start_event] { + uid: 10001 pid: 100 process_name: "com.example.a" start_seq: 1 } } } +# B: start (seq 2). +packet { trusted_packet_sequence_id: 1 timestamp: 1500 track_event { + type: TYPE_INSTANT track_uuid: 3 name: "start_B" + [com.android.internal.FrameworksBaseTrackEvent.process_start_event] { + uid: 10002 pid: 200 process_name: "com.example.b" start_seq: 2 } } } +# A: binder_died FIRST -> ends the process. +packet { trusted_packet_sequence_id: 1 timestamp: 2000 track_event { + type: TYPE_INSTANT track_uuid: 2 name: "binder_died_A" + [com.android.internal.FrameworksBaseTrackEvent.binder_died_event] { + uid: 10001 pid: 100 process_name: "com.example.a" start_seq: 1 } } } +# B: process_died FIRST -> ends + records reason. +packet { trusted_packet_sequence_id: 1 timestamp: 2500 track_event { + type: TYPE_INSTANT track_uuid: 3 name: "process_died_B" + [com.android.internal.FrameworksBaseTrackEvent.process_died_event] { + uid: 10002 pid: 200 process_name: "com.example.b" start_seq: 2 + reason: 6 } } } +# A: process_died LATER -> already ended, but still records the exit reason. +packet { trusted_packet_sequence_id: 1 timestamp: 3000 track_event { + type: TYPE_INSTANT track_uuid: 2 name: "process_died_A" + [com.android.internal.FrameworksBaseTrackEvent.process_died_event] { + uid: 10001 pid: 100 process_name: "com.example.a" start_seq: 1 + reason: 4 sub_reason: 2 } } } +# B: binder_died LATER -> already ended, so skipped. +packet { trusted_packet_sequence_id: 1 timestamp: 3500 track_event { + type: TYPE_INSTANT track_uuid: 3 name: "binder_died_B" + [com.android.internal.FrameworksBaseTrackEvent.binder_died_event] { + uid: 10002 pid: 200 process_name: "com.example.b" start_seq: 2 } } }
diff --git a/test/trace_processor/diff_tests/parser/android/tests.py b/test/trace_processor/diff_tests/parser/android/tests.py index 329c800..52151b3 100644 --- a/test/trace_processor/diff_tests/parser/android/tests.py +++ b/test/trace_processor/diff_tests/parser/android/tests.py
@@ -304,6 +304,22 @@ 100,"com.example.app",10001,2000,5000 """)) + def test_android_framework_track_event_process_death(self): + return DiffTestBlueprint( + trace=Path('android_framework_track_event_process_death.textproto'), + query=""" + SELECT p.pid, t.start_seq, t.fw_start_ts, t.fw_end_ts, t.reason, + t.sub_reason + FROM __intrinsic_android_track_event_process t + JOIN process p USING (upid) + ORDER BY t.start_seq; + """, + out=Csv(""" + "pid","start_seq","fw_start_ts","fw_end_ts","reason","sub_reason" + 100,1,1000,2000,"APP_EXIT_REASON_CRASH","APP_EXIT_SUBREASON_TOO_MANY_CACHED" + 200,2,1500,2500,"APP_EXIT_REASON_ANR","[NULL]" + """)) + def test_android_framework_track_event_enum(self): return DiffTestBlueprint( trace=TextProto(r""" @@ -343,6 +359,7 @@ type: TYPE_INSTANT [com.android.internal.FrameworksBaseTrackEvent.process_start_event] { pid: 100 + start_seq: 1 trigger_type: TRIGGER_TYPE_JOB hosting_type: HOSTING_TYPE_SERVICE }