Merge "tp: add metrics for lock contention on main thread during app startup"
diff --git a/protos/perfetto/metrics/android/startup_metric.proto b/protos/perfetto/metrics/android/startup_metric.proto
index aef7c10..a52e36c 100644
--- a/protos/perfetto/metrics/android/startup_metric.proto
+++ b/protos/perfetto/metrics/android/startup_metric.proto
@@ -45,7 +45,7 @@
// Timing information spanning the intent received by the
// activity manager to the first frame drawn.
- // Next id: 31.
+ // Next id: 33.
message ToFirstFrame {
// The duration between the intent received and first frame.
optional int64 dur_ns = 1;
@@ -104,7 +104,18 @@
// Time spent on garbage collection.
optional Slice time_gc_total = 29;
optional Slice time_gc_on_cpu = 30;
- // Deprecated was other_process_to_activity_cpu_ratio
+
+ // Time spent in lock contention on the main thread of the process being
+ // started up. This includes *all* types of lock contention not just monitor
+ // contention.
+ optional Slice time_lock_contention_thread_main = 31;
+
+ // Time spent in monitor lock contention on the main thread of the
+ // process being started up. This will be a subset of the time counted by
+ // |time_lock_contention_thread_main|.
+ optional Slice time_monitor_contention_thread_main = 32;
+
+ // Removed: was other_process_to_activity_cpu_ratio.
reserved 12;
// Removed: was uint32 versions of to_post_fork, to_activity_thread_main and
diff --git a/protos/perfetto/metrics/perfetto_merged_metrics.proto b/protos/perfetto/metrics/perfetto_merged_metrics.proto
index 6425b3d..58571a9 100644
--- a/protos/perfetto/metrics/perfetto_merged_metrics.proto
+++ b/protos/perfetto/metrics/perfetto_merged_metrics.proto
@@ -1245,7 +1245,7 @@
// Timing information spanning the intent received by the
// activity manager to the first frame drawn.
- // Next id: 31.
+ // Next id: 33.
message ToFirstFrame {
// The duration between the intent received and first frame.
optional int64 dur_ns = 1;
@@ -1304,7 +1304,18 @@
// Time spent on garbage collection.
optional Slice time_gc_total = 29;
optional Slice time_gc_on_cpu = 30;
- // Deprecated was other_process_to_activity_cpu_ratio
+
+ // Time spent in lock contention on the main thread of the process being
+ // started up. This includes *all* types of lock contention not just monitor
+ // contention.
+ optional Slice time_lock_contention_thread_main = 31;
+
+ // Time spent in monitor lock contention on the main thread of the
+ // process being started up. This will be a subset of the time counted by
+ // |time_lock_contention_thread_main|.
+ optional Slice time_monitor_contention_thread_main = 32;
+
+ // Removed: was other_process_to_activity_cpu_ratio.
reserved 12;
// Removed: was uint32 versions of to_post_fork, to_activity_thread_main and
diff --git a/python/perfetto/trace_processor/metrics.descriptor b/python/perfetto/trace_processor/metrics.descriptor
index 77c159a..85358ba 100644
--- a/python/perfetto/trace_processor/metrics.descriptor
+++ b/python/perfetto/trace_processor/metrics.descriptor
Binary files differ
diff --git a/src/trace_processor/metrics/sql/android/android_startup.sql b/src/trace_processor/metrics/sql/android/android_startup.sql
index e6556fb..eb2dd7a 100644
--- a/src/trace_processor/metrics/sql/android/android_startup.sql
+++ b/src/trace_processor/metrics/sql/android/android_startup.sql
@@ -164,12 +164,12 @@
MAIN_THREAD_TIME_FOR_LAUNCH_AND_STATE(launches.id, 'S'), 0
)
),
- 'mcycles_by_core_type', AndroidStartupMetric_McyclesByCoreType(
+ 'mcycles_by_core_type', NULL_IF_EMPTY(AndroidStartupMetric_McyclesByCoreType(
'little', MCYCLES_FOR_LAUNCH_AND_CORE_TYPE(launches.id, 'little'),
'big', MCYCLES_FOR_LAUNCH_AND_CORE_TYPE(launches.id, 'big'),
'bigger', MCYCLES_FOR_LAUNCH_AND_CORE_TYPE(launches.id, 'bigger'),
'unknown', MCYCLES_FOR_LAUNCH_AND_CORE_TYPE(launches.id, 'unknown')
- ),
+ )),
'to_post_fork',
LAUNCH_TO_MAIN_THREAD_SLICE_PROTO(launches.id, 'PostFork'),
'to_activity_thread_main',
@@ -214,6 +214,16 @@
slice_name GLOB "*concurrent copying GC"
)
),
+ 'time_lock_contention_thread_main',
+ DUR_SUM_MAIN_THREAD_SLICE_PROTO_FOR_LAUNCH(
+ launches.id,
+ 'Lock contention on*'
+ ),
+ 'time_monitor_contention_thread_main',
+ DUR_SUM_MAIN_THREAD_SLICE_PROTO_FOR_LAUNCH(
+ launches.id,
+ 'Lock contention on a monitor*'
+ ),
'time_before_start_process', (
SELECT STARTUP_SLICE_PROTO(ts - launches.ts)
FROM ZYGOTE_FORK_FOR_LAUNCH(launches.id)
diff --git a/src/trace_processor/metrics/sql/android/startup/launches_minsdk33.sql b/src/trace_processor/metrics/sql/android/startup/launches_minsdk33.sql
index 25ea8cd..9160bee 100644
--- a/src/trace_processor/metrics/sql/android/startup/launches_minsdk33.sql
+++ b/src/trace_processor/metrics/sql/android/startup/launches_minsdk33.sql
@@ -22,9 +22,9 @@
SUBSTR(name, 19) id
FROM slice
WHERE
- name GLOB 'launchingActivity#*'
- AND dur != 0
- AND INSTR(name, ':') = 0;
+ name GLOB 'launchingActivity#*' AND
+ dur != 0 AND
+ INSTR(name, ':') = 0;
DROP VIEW IF EXISTS launch_complete_events;
CREATE VIEW launch_complete_events AS
@@ -35,7 +35,9 @@
FROM (
SELECT ts, SUBSTR(name, 19) completed
FROM slice
- WHERE dur = 0 AND name GLOB 'launchingActivity#*:completed:*'
+ WHERE
+ dur = 0 AND
+ name GLOB 'launchingActivity#*:completed:*'
)
GROUP BY 1, 2;
@@ -46,4 +48,5 @@
ts + dur ts_end,
dur,
package_name
-FROM launch_async_events JOIN launch_complete_events USING (id);
+FROM launch_async_events
+JOIN launch_complete_events USING (id);
diff --git a/src/trace_processor/metrics/sql/android/startup/slice_functions.sql b/src/trace_processor/metrics/sql/android/startup/slice_functions.sql
index 571bebd..7ee083c 100644
--- a/src/trace_processor/metrics/sql/android/startup/slice_functions.sql
+++ b/src/trace_processor/metrics/sql/android/startup/slice_functions.sql
@@ -45,7 +45,8 @@
-- Given a launch id and GLOB for a slice name, returns columns for matching slices.
SELECT CREATE_VIEW_FUNCTION(
'SLICES_FOR_LAUNCH_AND_SLICE_NAME(launch_id INT, slice_name STRING)',
- 'slice_name STRING, slice_ts INT, slice_dur INT, thread_name STRING, arg_set_id INT', '
+ 'slice_name STRING, slice_ts INT, slice_dur INT, thread_name STRING, arg_set_id INT',
+ '
SELECT slice_name, slice_ts, slice_dur, thread_name, arg_set_id
FROM thread_slices_for_all_launches
WHERE launch_id = $launch_id AND slice_name GLOB $slice_name
@@ -56,18 +57,32 @@
-- summing the slice durations across the whole startup.
SELECT CREATE_FUNCTION(
'DUR_SUM_SLICE_PROTO_FOR_LAUNCH(launch_id LONG, slice_name STRING)',
- 'PROTO', '
+ 'PROTO',
+ '
SELECT NULL_IF_EMPTY(STARTUP_SLICE_PROTO(SUM(slice_dur)))
FROM thread_slices_for_all_launches
WHERE launch_id = $launch_id AND slice_name GLOB $slice_name
'
);
+-- Same as |DUR_SUM_SLICE_PROTO_FOR_LAUNCH| except only counting slices happening
+-- on the main thread.
+SELECT CREATE_FUNCTION(
+ 'DUR_SUM_MAIN_THREAD_SLICE_PROTO_FOR_LAUNCH(launch_id LONG, slice_name STRING)',
+ 'PROTO',
+ '
+ SELECT NULL_IF_EMPTY(STARTUP_SLICE_PROTO(SUM(slice_dur)))
+ FROM thread_slices_for_all_launches
+ WHERE launch_id = $launch_id AND slice_name GLOB $slice_name AND is_main_thread
+ '
+);
+
-- Given a launch id and GLOB for a slice name, returns the startup slice proto by
-- taking the duration between the start of the launch and start of the slice.
SELECT CREATE_FUNCTION(
'LAUNCH_TO_MAIN_THREAD_SLICE_PROTO(launch_id INT, slice_name STRING)',
- 'PROTO', '
+ 'PROTO',
+ '
SELECT STARTUP_SLICE_PROTO(slice_ts - launch_ts)
FROM thread_slices_for_all_launches
WHERE slice_name GLOB $slice_name AND launch_id = $launch_id AND is_main_thread
diff --git a/test/trace_processor/startup/android_startup.out b/test/trace_processor/startup/android_startup.out
index 5d323e4..bbb5d45 100644
--- a/test/trace_processor/startup/android_startup.out
+++ b/test/trace_processor/startup/android_startup.out
@@ -32,8 +32,6 @@
dur_ns: 8
dur_ms: 8e-06
}
- mcycles_by_core_type {
- }
time_activity_start {
dur_ns: 2
dur_ms: 2e-06
diff --git a/test/trace_processor/startup/android_startup_attribution.out b/test/trace_processor/startup/android_startup_attribution.out
index 3c74145..8d18b5e 100644
--- a/test/trace_processor/startup/android_startup_attribution.out
+++ b/test/trace_processor/startup/android_startup_attribution.out
@@ -30,8 +30,6 @@
dur_ns: 40
dur_ms: 4e-05
}
- mcycles_by_core_type {
- }
jit_compiled_methods: 2
time_jit_thread_pool_on_cpu {
dur_ns: 20
diff --git a/test/trace_processor/startup/android_startup_lock_contention.out b/test/trace_processor/startup/android_startup_lock_contention.out
new file mode 100644
index 0000000..89455a6
--- /dev/null
+++ b/test/trace_processor/startup/android_startup_lock_contention.out
@@ -0,0 +1,54 @@
+android_startup {
+ startup {
+ startup_id: 1
+ package_name: "com.google.android.calendar"
+ process_name: "com.google.android.calendar"
+ zygote_new_process: false
+ to_first_frame {
+ dur_ns: 100
+ main_thread_by_task_state {
+ running_dur_ns: 0
+ runnable_dur_ns: 0
+ uninterruptible_sleep_dur_ns: 0
+ interruptible_sleep_dur_ns: 0
+ }
+ other_processes_spawned_count: 0
+ time_bind_application {
+ dur_ns: 3
+ dur_ms: 3e-06
+ }
+ dur_ms: 0.0001
+ to_bind_application {
+ dur_ns: 2
+ dur_ms: 2e-06
+ }
+ time_lock_contention_thread_main {
+ dur_ns: 20
+ dur_ms: 2e-05
+ }
+ time_monitor_contention_thread_main {
+ dur_ns: 10
+ dur_ms: 1e-05
+ }
+ }
+ activity_hosting_process_count: 1
+ process {
+ name: "com.google.android.calendar"
+ uid: 10001
+ package {
+ package_name: "com.google.android.calendar"
+ apk_version_code: 123
+ debuggable: false
+ }
+ packages_for_uid {
+ package_name: "com.google.android.calendar"
+ apk_version_code: 123
+ debuggable: false
+ }
+ }
+ event_timestamps {
+ intent_received: 110
+ first_frame: 210
+ }
+ }
+}
diff --git a/test/trace_processor/startup/android_startup_lock_contention.py b/test/trace_processor/startup/android_startup_lock_contention.py
new file mode 100644
index 0000000..acc082c
--- /dev/null
+++ b/test/trace_processor/startup/android_startup_lock_contention.py
@@ -0,0 +1,76 @@
+#!/usr/bin/env python3
+# Copyright (C) 2022 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 at
+#
+# 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 os import sys
+
+import synth_common
+
+trace = synth_common.create_trace()
+trace.add_packet()
+trace.add_process(1, 0, 'init')
+trace.add_process(2, 1, 'system_server')
+trace.add_process(3, 1, 'com.google.android.calendar', 10001)
+trace.add_thread(4, 3, 'Binder')
+
+trace.add_package_list(
+ ts=1, name='com.google.android.calendar', uid=10001, version_code=123)
+
+trace.add_ftrace_packet(cpu=0)
+trace.add_atrace_async_begin(ts=110, tid=2, pid=2, buf='launchingActivity#1')
+trace.add_atrace_async_end(ts=210, tid=2, pid=2, buf='launchingActivity#1')
+
+# Required so we know this process is the one being started up.
+trace.add_atrace_begin(ts=112, tid=3, pid=3, buf='bindApplication')
+trace.add_atrace_end(ts=115, tid=3, pid=3)
+
+# Add some non-monitor lock contention.
+trace.add_atrace_begin(
+ ts=120,
+ tid=3,
+ pid=3,
+ buf='Lock contention on thread list lock (owner tid: 2)')
+trace.add_atrace_end(ts=130, tid=3, pid=3)
+
+# Add monitor contention
+trace.add_atrace_begin(
+ ts=140,
+ tid=3,
+ pid=3,
+ buf='Lock contention on a monitor lock (owner tid: 2)')
+trace.add_atrace_end(ts=150, tid=3, pid=3)
+
+# Lock contention on non-main thread should not be counted.
+trace.add_atrace_begin(
+ ts=155,
+ tid=4,
+ pid=3,
+ buf='Lock contention on a monitor lock (owner tid: 3)')
+trace.add_atrace_end(ts=160, tid=4, pid=3)
+
+# Lock contention in other process should not be counted.
+trace.add_atrace_begin(
+ ts=175,
+ tid=2,
+ pid=2,
+ buf='Lock contention on a monitor lock (owner tid: 3)')
+trace.add_atrace_end(ts=180, tid=2, pid=2)
+
+trace.add_atrace_instant(
+ ts=211,
+ tid=2,
+ pid=2,
+ buf='launchingActivity#1:completed:com.google.android.calendar')
+
+sys.stdout.buffer.write(trace.trace.SerializeToString())
diff --git a/test/trace_processor/startup/android_startup_minsdk33.out b/test/trace_processor/startup/android_startup_minsdk33.out
index e7022b5..a6b1b06 100644
--- a/test/trace_processor/startup/android_startup_minsdk33.out
+++ b/test/trace_processor/startup/android_startup_minsdk33.out
@@ -13,8 +13,6 @@
}
other_processes_spawned_count: 0
dur_ms: 0.0001
- mcycles_by_core_type {
- }
}
activity_hosting_process_count: 0
event_timestamps {
diff --git a/test/trace_processor/startup/android_startup_process_track.out b/test/trace_processor/startup/android_startup_process_track.out
index 7a8ae0f..e0f6011 100644
--- a/test/trace_processor/startup/android_startup_process_track.out
+++ b/test/trace_processor/startup/android_startup_process_track.out
@@ -20,8 +20,6 @@
dur_ns: 2
dur_ms: 2e-06
}
- mcycles_by_core_type {
- }
time_bind_application {
dur_ns: 1
dur_ms: 1e-06
@@ -59,8 +57,6 @@
dur_ns: 2
dur_ms: 2e-06
}
- mcycles_by_core_type {
- }
time_bind_application {
dur_ns: 1
dur_ms: 1e-06
diff --git a/test/trace_processor/startup/index b/test/trace_processor/startup/index
index ee6003e..afdfdf5 100644
--- a/test/trace_processor/startup/index
+++ b/test/trace_processor/startup/index
@@ -7,6 +7,9 @@
android_startup_process_track.py android_startup android_startup_process_track.out
android_startup_attribution.py android_startup android_startup_attribution.out
+# Test lock contention is correctly attributed.
+android_startup_lock_contention.py android_startup android_startup_lock_contention.out
+
# Other metrics associated with startup.
android_startup_battery.py android_batt android_batt_counters.out
android_startup_cpu.py android_cpu android_startup_cpu.out
diff --git a/tools/diff_test_trace_processor.py b/tools/diff_test_trace_processor.py
index 2c34ae6..6a0c5f4 100755
--- a/tools/diff_test_trace_processor.py
+++ b/tools/diff_test_trace_processor.py
@@ -264,7 +264,7 @@
sys.stderr.write(f"Rebasing {expected_path}\n")
with open(expected_path, 'w') as f:
f.write(result.actual)
- rebase += 1
+ rebased += 1
else:
sys.stderr.write(
f"Rebase failed for {expected_path} as query failed\n")
@@ -418,6 +418,7 @@
f"[==========] {len(tests)} tests ran. ({test_time_ms} ms total)\n")
sys.stderr.write(f"[ PASSED ] {len(tests) - test_failures} tests.\n")
if args.rebase:
+ sys.stderr.write('\n')
sys.stderr.write(f"{rebased} tests rebased.\n")
if test_failures == 0:
