Fixed

Bug

Status Update

No update yet.

Description

ml...@google.com

created issue #1

Jun 7, 2023 03:34PM

Macrobenchmark 1.2.0-alpha14

androidx.compose.runtime-tracing: 1.0.0-alpha03

Devices/Android versions reproduced on: userdebug Pixel 6 API 33

When using androidx.benchmark.fullTracing.enable=true instr argument, the benchmark crashes after the first iteration.

I'm running FrameTimingMetric benchmark with CompilationMode.Full() and StartupMode.WARM. The interactions with the app run correctly, but at the end of the first iteration, it crashes.

Reproduced in Now in Android in the separate branch.

Logcat

Result: Starting: Intent { act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10008000 pkg=com.google.samples.apps.nowinandroid.demo.benchmark cmp=com.google.samples.apps.nowinandroid.demo.benchmark/com.goog
Status: ok
LaunchState: WARM
Activity: com.google.samples.apps.nowinandroid.demo.benchmark/com.google.samples.apps.nowinandroid.MainActivity
TotalTime: 54
WaitTime: 55
Complete
0 Flags,FrameTimelineVsyncId,IntendedVsync,Vsync,InputEventId,HandleInputStart,AnimationStart,PerformTraversalsStart,DrawStart,FrameDeadline,FrameInterval,FrameStartTime,SyncQueued,SyncStart,IssueDrawCommandsStart,SwapBuffers,FrameC
[...... removed for brevity .... ]
UiAutomation.grantRuntimePermission() is more robust and should be used instead of 'pm grant'
Supported ABIs: arm64-v8a, armeabi-v7a, armeabi
Recording perfetto trace
Supported ABIs: arm64-v8a, armeabi-v7a, armeabi
A resource failed to call close. 
stopserver
Perfetto trace processor shell server stopped (pid=14628).
Killing process com.google.samples.apps.nowinandroid.demo.benchmark
failed: scrollFeedCompilationFull(com.google.samples.apps.nowinandroid.foryou.ScrollForYouFeedBenchmark)
----- begin exception -----
java.lang.IllegalStateException: Unable to locate libtracing_perfetto.so to enable Perfetto SDK. Tried inside /data/app/~~HsTXVzKVR4ZZmbWHpzJFzQ==/com.google.samples.apps.nowinandroid.benchmarks-uZ00VlDjJIBgg3FO2wEnyw==/base.apk.
	at androidx.tracing.perfetto.PerfettoHandshake$ExternalLibraryProvider.pushLibrary$tracing_perfetto_common(PerfettoHandshake.kt:156)
	at androidx.tracing.perfetto.PerfettoHandshake.enableTracing(PerfettoHandshake.kt:58)
	at androidx.benchmark.perfetto.PerfettoCapture.enableAndroidxTracingPerfetto(PerfettoCapture.kt:139)
	at androidx.benchmark.perfetto.PerfettoCaptureWrapper.start(PerfettoCaptureWrapper.kt:66)
	at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record(PerfettoCaptureWrapper.kt:128)
	at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record$default(PerfettoCaptureWrapper.kt:95)
	at androidx.benchmark.macro.MacrobenchmarkKt$macrobenchmark$measurements$1.invoke(Macrobenchmark.kt:215)
	at androidx.benchmark.macro.MacrobenchmarkKt$macrobenchmark$measurements$1.invoke(Macrobenchmark.kt:202)
	at androidx.benchmark.perfetto.PerfettoTraceProcessor$Companion.runServer(PerfettoTraceProcessor.kt:105)
	at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmark(Macrobenchmark.kt:202)
	at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmarkWithStartupMode(Macrobenchmark.kt:365)
	at androidx.benchmark.macro.junit4.MacrobenchmarkRule.measureRepeated(MacrobenchmarkRule.kt:107)
	at com.google.samples.apps.nowinandroid.foryou.ScrollForYouFeedBenchmark.scrollFeed(ScrollForYouFeedBenchmark.kt:44)
	at com.google.samples.apps.nowinandroid.foryou.ScrollForYouFeedBenchmark.scrollFeedCompilationFull(ScrollForYouFeedBenchmark.kt:42)
	at java.lang.reflect.Method.invoke(Native Method)
	at org.junit.runners.model.FrameworkMethod$1.runReflectiveCall(FrameworkMethod.java:59)
	at org.junit.internal.runners.model.ReflectiveCallable.run(ReflectiveCallable.java:12)
	at org.junit.runners.model.FrameworkMethod.invokeExplosively(FrameworkMethod.java:56)
	at org.junit.internal.runners.statements.InvokeMethod.evaluate(InvokeMethod.java:17)
	at androidx.benchmark.macro.junit4.MacrobenchmarkRule$applyInternal$1.evaluate(MacrobenchmarkRule.kt:133)
	at androidx.test.rule.GrantPermissionRule$RequestPermissionStatement.evaluate(GrantPermissionRule.java:136)
	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runners.Suite.runChild(Suite.java:128)
	at org.junit.runners.Suite.runChild(Suite.java:27)
	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:67)
	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:58)
	at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:446)
	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2322)
----- end exception -----
finished: scrollFeedCompilationFull(com.google.samples.apps.nowinandroid.foryou.ScrollForYouFeedBenchmark)
run finished: 1 tests, 1 failed, 0 ignored

Comments

cc...@google.com <cc...@google.com> Jun 7, 2023 03:36PM

Reassigned to jg...@google.com.

ml...@google.com <ml...@google.com> #2Jun 22, 2023 10:31AM

Project: platform/frameworks/support
Branch: androidx-main

commit 3283536a57f7caf087786f6030f6bf246489df85
Author: Chris Craik <ccraik@google.com>
Date: Fri Feb 02 16:27:30 2024

Speculative fix for Failed to stop [ProcessPid(processName=perfetto...

Bug: 323601788
Bug: 307649002
Relnote: "Adjusted data source timeouts to attempt to fix java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=...)]"

Test: ./gradlew bench:b-m:cC
Change-Id: I8dc7d5091ea1a8e68cb5effb21363f1c3196cf56

M benchmark/benchmark-common/src/main/java/androidx/benchmark/perfetto/PerfettoConfig.kt
M benchmark/benchmark-common/src/main/java/androidx/benchmark/perfetto/PerfettoHelper.kt

https://android-review.googlesource.com/2947370

Message last modified on Jun 22, 2023 10:31AM

jg...@google.com <jg...@google.com> #3Jun 23, 2023 04:33PM

This is expected to be fixed with the change above, which made it into 1.3.0-alpha01.

Please let us know if you still see this issue after updating to that version

ml...@google.com <ml...@google.com> #4Jun 30, 2023 02:08PM

Hey I'm still seeing this issue with 1.3.0-alpha01, this is the stack:

java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=2784)]
at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:596)
at androidx.benchmark.perfetto.PerfettoHelper.stopPerfetto(PerfettoHelper.kt:258)
at androidx.benchmark.perfetto.PerfettoHelper.stopCollecting(PerfettoHelper.kt:236)
at androidx.benchmark.perfetto.PerfettoCapture.stop(PerfettoCapture.kt:87)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper$stop$1.invoke(PerfettoCaptureWrapper.kt:91)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper$stop$1.invoke(PerfettoCaptureWrapper.kt:88)
at androidx.benchmark.Outputs.writeFile(Outputs.kt:136)
at androidx.benchmark.Outputs.writeFile$default(Outputs.kt:125)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.stop(PerfettoCaptureWrapper.kt:88)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record(PerfettoCaptureWrapper.kt:145)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record$default(PerfettoCaptureWrapper.kt:101)
at androidx.benchmark.macro.MacrobenchmarkKt$macrobenchmark$measurements$1.invoke(Macrobenchmark.kt:271)
at androidx.benchmark.macro.MacrobenchmarkKt$macrobenchmark$measurements$1.invoke(Macrobenchmark.kt:255)
at androidx.benchmark.perfetto.PerfettoTraceProcessor$Companion.runServer(PerfettoTraceProcessor.kt:108)
at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmark(Macrobenchmark.kt:255)
at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmarkWithStartupMode(Macrobenchmark.kt:438)
at androidx.benchmark.macro.junit4.MacrobenchmarkRule.measureRepeated(MacrobenchmarkRule.kt:107)
at com.meta.compose.macrobenchmark.scroll.HomeFeedScrollBenchmark.scroll(HomeFeedScrollBenchmark.kt:43)
at com.meta.compose.macrobenchmark.scroll.HomeFeedScrollBenchmark.noCompilation(HomeFeedScrollBenchmark.kt:35)

jg...@google.com <jg...@google.com> #5Jun 30, 2023 02:30PM

@ #comment4 - can you attach logcat of a scenario where this reproduces? If necessary, you can filter it to perfetto/PerfettoCapture/Benchmark tags.

How reproducible is this, and on which devices and OS versions?

ml...@google.com <ml...@google.com> Jul 21, 2023 09:57AM

Reassigned to ml...@google.com.

cc...@google.com <cc...@google.com> #6Jul 21, 2023 05:15PM

I'm facing the same issue. Device: Pixel 8 Pro Android 15 - Build Number: AP31.240426.023 Stack:

java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=11267)]
at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:612)
at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:581)
at androidx.benchmark.perfetto.PerfettoHelper$Companion.stopAllPerfettoProcesses(PerfettoHelper.kt:441)
at androidx.benchmark.perfetto.PerfettoHelper.startCollecting(PerfettoHelper.kt:91)
at androidx.benchmark.perfetto.PerfettoCapture.start(PerfettoCapture.kt:73)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.start(PerfettoCaptureWrapper.kt:80)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record(PerfettoCaptureWrapper.kt:136)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record$default(PerfettoCaptureWrapper.kt:101)
at androidx.benchmark.junit4.BenchmarkRule$applyInternal$$inlined$Statement$1.evaluate(BenchmarkRule.kt:442)
at androidx.test.rule.GrantPermissionRule$RequestPermissionStatement.evaluate(GrantPermissionRule.java:136)
at org.junit.rules.RunRules.evaluate(RunRules.java:20)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:162)
at org.junit.runners.Suite.runChild(Suite.java:128)
at org.junit.runners.Suite.runChild(Suite.java:27)
at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:67)
at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:58)
at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:446)
at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2594)

Log from Logcat:

2024-06-01 19:08:00.528 10362-10380 Benchmark               com.performance.benchmark.test       D  launching Benchmark IsolationActivity
2024-06-01 19:08:00.554 10362-10422 vulkan                  com.performance.benchmark.test       D  searching for layers in '/data/app/~~BWq1z3HXtczxQa9ZQjpLhA==/com.performance.benchmark.test-PKZxIOqbb6y3ykj-YzNhBA==/lib/arm64'
2024-06-01 19:08:00.554 10362-10422 vulkan                  com.performance.benchmark.test       D  searching for layers in '/data/app/~~BWq1z3HXtczxQa9ZQjpLhA==/com.performance.benchmark.test-PKZxIOqbb6y3ykj-YzNhBA==/base.apk!/lib/arm64-v8a'
2024-06-01 19:08:00.563 10362-10362 LifecycleMonitor        com.performance.benchmark.test       D  Lifecycle status change: androidx.benchmark.IsolationActivity@f8698f1 in: PRE_ON_CREATE
2024-06-01 19:08:00.572 10362-10362 .benchmark.test         com.performance.benchmark.test       E  Invalid resource ID 0x00000000.
2024-06-01 19:08:00.579 10362-10362 CompatChangeReporter    com.performance.benchmark.test       D  Compat change id reported: 309578419; UID 10004; state: DISABLED
2024-06-01 19:08:00.582 10362-10362 CompatChangeReporter    com.performance.benchmark.test       D  Compat change id reported: 210923482; UID 10004; state: ENABLED
2024-06-01 19:08:00.582 10362-10362 CompatChangeReporter    com.performance.benchmark.test       D  Compat change id reported: 63938206; UID 10004; state: DISABLED
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  Clocks not locked: online cores with min freq == min avail freq
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu0 CoreDir(path=/sys/devices/system/cpu/cpu7, online=true, availableFreqs=[402000, 578000, 697000, 712000, 910000, 1065000, 1221000, 1328000, 1418000, 1572000, 1836000, 1945000, 2130000, 2245000, 2367000], setSpeedKhz=402000, maxFreqKhz=2367000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu1 CoreDir(path=/sys/devices/system/cpu/cpu5, online=true, availableFreqs=[402000, 578000, 697000, 712000, 910000, 1065000, 1221000, 1328000, 1418000, 1572000, 1836000, 1945000, 2130000, 2245000, 2367000], setSpeedKhz=402000, maxFreqKhz=2367000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu2 CoreDir(path=/sys/devices/system/cpu/cpu3, online=true, availableFreqs=[324000, 610000, 820000, 955000, 1098000, 1197000, 1328000, 1425000, 1548000, 1704000], setSpeedKhz=324000, maxFreqKhz=1704000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu3 CoreDir(path=/sys/devices/system/cpu/cpu1, online=true, availableFreqs=[324000, 610000, 820000, 955000, 1098000, 1197000, 1328000, 1425000, 1548000, 1704000], setSpeedKhz=324000, maxFreqKhz=1704000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu4 CoreDir(path=/sys/devices/system/cpu/cpu8, online=true, availableFreqs=[500000, 880000, 1164000, 1298000, 1557000, 1745000, 1885000, 2049000, 2147000, 2294000, 2363000, 2556000, 2687000, 2850000, 2914000], setSpeedKhz=500000, maxFreqKhz=2914000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu5 CoreDir(path=/sys/devices/system/cpu/cpu6, online=true, availableFreqs=[402000, 578000, 697000, 712000, 910000, 1065000, 1221000, 1328000, 1418000, 1572000, 1836000, 1945000, 2130000, 2245000, 2367000], setSpeedKhz=402000, maxFreqKhz=2367000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu6 CoreDir(path=/sys/devices/system/cpu/cpu4, online=true, availableFreqs=[402000, 578000, 697000, 712000, 910000, 1065000, 1221000, 1328000, 1418000, 1572000, 1836000, 1945000, 2130000, 2245000, 2367000], setSpeedKhz=402000, maxFreqKhz=2367000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu7 CoreDir(path=/sys/devices/system/cpu/cpu2, online=true, availableFreqs=[324000, 610000, 820000, 955000, 1098000, 1197000, 1328000, 1425000, 1548000, 1704000], setSpeedKhz=324000, maxFreqKhz=1704000)
2024-06-01 19:08:01.357 10362-10362 Benchmark               com.performance.benchmark.test       D  cpu8 CoreDir(path=/sys/devices/system/cpu/cpu0, online=true, availableFreqs=[324000, 610000, 820000, 955000, 1098000, 1197000, 1328000, 1425000, 1548000, 1704000], setSpeedKhz=324000, maxFreqKhz=1704000)
2024-06-01 19:08:01.359 10362-10362 LifecycleMonitor        com.performance.benchmark.test       D  Lifecycle status change: androidx.benchmark.IsolationActivity@f8698f1 in: CREATED
2024-06-01 19:08:01.359 10362-10362 LifecycleMonitor        com.performance.benchmark.test       D  Lifecycle status change: androidx.benchmark.IsolationActivity@f8698f1 in: STARTED
2024-06-01 19:08:01.361 10362-10362 LifecycleMonitor        com.performance.benchmark.test       D  Lifecycle status change: androidx.benchmark.IsolationActivity@f8698f1 in: RESUMED
2024-06-01 19:08:01.365 10362-10362 CompatChangeReporter    com.performance.benchmark.test       D  Compat change id reported: 237531167; UID 10004; state: DISABLED
2024-06-01 19:08:01.426 10362-10380 GrantPermissionCallable com.performance.benchmark.test       I  Permission: android.permission.READ_EXTERNAL_STORAGE is already granted!
2024-06-01 19:08:01.426 10362-10380 GrantPermissionCallable com.performance.benchmark.test       I  Permission: android.permission.WRITE_EXTERNAL_STORAGE is already granted!
2024-06-01 19:08:01.426 10362-10380 Benchmark               com.performance.benchmark.test       D  -- Running com.performance.benchmark.ExampleBenchmark#log --
2024-06-01 19:08:01.427 10362-10380 PerfettoCapture         com.performance.benchmark.test       D  Supported ABIs: arm64-v8a
2024-06-01 19:08:01.427 10362-10380 PerfettoCapture         com.performance.benchmark.test       D  Recording perfetto trace
2024-06-01 19:08:01.446 10362-10380 PerfettoCapture         com.performance.benchmark.test       I  Cleanup perfetto before starting.
2024-06-01 19:08:01.558 10362-10380 Benchmark               com.performance.benchmark.test       D  kill -TERM command output - Output(stdout=, stderr=/storage/emulated/0/Android/media/com.performance.benchmark.test/temporaryScript5455895838492548174.tmp[2]: kill: 11267: Operation not permitted
                                                                                                    )
2024-06-01 19:08:01.725 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:01.759 10362-10572 InteractionJankMonitor  com.performance.benchmark.test       W  Initializing without READ_DEVICE_CONFIG permission. enabled=false, interval=1, missedFrameThreshold=3, frameTimeThreshold=64, package=com.performance.benchmark.test
2024-06-01 19:08:01.865 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.019 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.156 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.292 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.433 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.583 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.729 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:02.877 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.024 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.169 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.323 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.480 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.638 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.806 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:03.961 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:04.113 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:04.263 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:04.419 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:04.584 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:04.748 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:04.900 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:05.064 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:05.226 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:05.384 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:05.550 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:05.641 10362-10673 ProfileInstaller        com.performance.benchmark.test       D  Installing profile for com.performance.benchmark.test
2024-06-01 19:08:05.717 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:05.873 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:06.035 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:06.185 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:06.346 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:06.512 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:06.679 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:06.836 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.000 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.146 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.314 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.487 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.652 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.814 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:07.979 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:08.148 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:08.316 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:08.477 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:08.640 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:08.808 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:08.970 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:09.131 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:09.299 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:09.447 10362-10380 Benchmark               com.performance.benchmark.test       D  Waiting 100 ms for [ProcessPid(processName=perfetto, pid=11267)] to die
2024-06-01 19:08:09.496 10362-10380 TestRunner              com.performance.benchmark.test       E  failed: log(com.performance.benchmark.ExampleBenchmark)
2024-06-01 19:08:09.496 10362-10380 TestRunner              com.performance.benchmark.test       E  ----- begin exception -----
2024-06-01 19:08:09.500 10362-10380 TestRunner              com.performance.benchmark.test       E  java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=11267)] (Ask Gemini)
                                                                                                    	at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:612)
                                                                                                    	at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:581)
                                                                                                    	at androidx.benchmark.perfetto.PerfettoHelper$Companion.stopAllPerfettoProcesses(PerfettoHelper.kt:441)
                                                                                                    	at androidx.benchmark.perfetto.PerfettoHelper.startCollecting(PerfettoHelper.kt:91)
                                                                                                    	at androidx.benchmark.perfetto.PerfettoCapture.start(PerfettoCapture.kt:73)
                                                                                                    	at androidx.benchmark.perfetto.PerfettoCaptureWrapper.start(PerfettoCaptureWrapper.kt:80)
                                                                                                    	at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record(PerfettoCaptureWrapper.kt:136)
                                                                                                    	at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record$default(PerfettoCaptureWrapper.kt:101)
                                                                                                    	at androidx.benchmark.junit4.BenchmarkRule$applyInternal$$inlined$Statement$1.evaluate(BenchmarkRule.kt:442)
                                                                                                    	at androidx.test.rule.GrantPermissionRule$RequestPermissionStatement.evaluate(GrantPermissionRule.java:136)
                                                                                                    	at org.junit.rules.RunRules.evaluate(RunRules.java:20)
                                                                                                    	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
                                                                                                    	at org.junit.runners.BlockJUnit4ClassRunner$1.evaluate(BlockJUnit4ClassRunner.java:100)
                                                                                                    	at org.junit.runners.ParentRunner.runLeaf(ParentRunner.java:366)
                                                                                                    	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:103)
                                                                                                    	at org.junit.runners.BlockJUnit4ClassRunner.runChild(BlockJUnit4ClassRunner.java:63)
                                                                                                    	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
                                                                                                    	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
                                                                                                    	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
                                                                                                    	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
                                                                                                    	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
                                                                                                    	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
                                                                                                    	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
                                                                                                    	at androidx.test.ext.junit.runners.AndroidJUnit4.run(AndroidJUnit4.java:162)
                                                                                                    	at org.junit.runners.Suite.runChild(Suite.java:128)
                                                                                                    	at org.junit.runners.Suite.runChild(Suite.java:27)
                                                                                                    	at org.junit.runners.ParentRunner$4.run(ParentRunner.java:331)
                                                                                                    	at org.junit.runners.ParentRunner$1.schedule(ParentRunner.java:79)
                                                                                                    	at org.junit.runners.ParentRunner.runChildren(ParentRunner.java:329)
                                                                                                    	at org.junit.runners.ParentRunner.access$100(ParentRunner.java:66)
                                                                                                    	at org.junit.runners.ParentRunner$2.evaluate(ParentRunner.java:293)
                                                                                                    	at org.junit.runners.ParentRunner$3.evaluate(ParentRunner.java:306)
                                                                                                    	at org.junit.runners.ParentRunner.run(ParentRunner.java:413)
                                                                                                    	at org.junit.runner.JUnitCore.run(JUnitCore.java:137)
                                                                                                    	at org.junit.runner.JUnitCore.run(JUnitCore.java:115)
                                                                                                    	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:67)
                                                                                                    	at androidx.test.internal.runner.TestExecutor.execute(TestExecutor.java:58)
                                                                                                    	at androidx.test.runner.AndroidJUnitRunner.onStart(AndroidJUnitRunner.java:446)
                                                                                                    	at android.app.Instrumentation$InstrumentationThread.run(Instrumentation.java:2594)
2024-06-01 19:08:09.500 10362-10380 TestRunner              com.performance.benchmark.test       E  ----- end exception -----
2024-06-01 19:08:09.504 10362-10380 TestRunner              com.performance.benchmark.test       I  finished: log(com.performance.benchmark.ExampleBenchmark)
2024-06-01 19:08:09.514 10362-10362 MonitoringInstr         com.performance.benchmark.test       I  Finishing activity: androidx.benchmark.IsolationActivity@f8698f1
2024-06-01 19:08:09.515 10362-10380 TestRunner              com.performance.benchmark.test       I  run finished: 1 tests, 1 failed, 0 ignored
2024-06-01 19:08:09.519 10362-10362 MonitoringInstr         com.performance.benchmark.test       I  Finishing activity: androidx.benchmark.IsolationActivity@f8698f1

ml...@google.com <ml...@google.com> #7Jul 21, 2023 05:48PM

Same with 1.3.0-beta01
```
java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=19422)]
at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:617)
```

I am trying to use a wrapper rule that can do some postprocessing on the macrobenchmark json before it sends to our servers instead of doing this in CI though.
Wrapper rule is pretty trivial:
```

class StatsDtaMacrobenchmarkRule : TestRule {
val macrobenchmarkRule: MacrobenchmarkRule = MacrobenchmarkRule()

override fun apply(
base: Statement,
description: Description,
): Statement = object : Statement() {
@Throws(Throwable::class)
override fun evaluate() {
before()
try {
macrobenchmarkRule.apply(base, description).evaluate()
} finally {
after()
}
}
}

/**
* Forwards to [MacrobenchmarkRule.measureRepeated]
*/
@JvmOverloads
fun measureRepeated(
packageName: String,
metrics: List<Metric>,
compilationMode: CompilationMode = CompilationMode.DEFAULT,
startupMode: StartupMode? = null,
@IntRange(from = 1)
iterations: Int,
setupBlock: MacrobenchmarkScope.() -> Unit = {},
measureBlock: MacrobenchmarkScope.() -> Unit,
) {
macrobenchmarkRule.measureRepeated(
packageName,
metrics,
compilationMode,
startupMode,
iterations,
setupBlock,
measureBlock,
)
}

private fun before() {
// Custom code to run before the nested rules
}

private fun after() {
// Custom code to run after the nested rules
val logcat = captureLogcat()
val regex = Regex(".*/(.+\\.json)")
val matchResult = regex.find(logcat)
val filename = matchResult?.groups?.get(1)?.value
filename?.let {
logV { "Macrobenchmark Filename: $it" }
} ?: logE { "Unable to find macrobenchmark file in logs!" }
}

private fun captureLogcat(): String {
val logcatProcess = Runtime.getRuntime().exec("logcat -d")
val bufferedReader = BufferedReader(InputStreamReader(logcatProcess.inputStream))

val logcatOutput = StringBuilder()
bufferedReader.useLines { lines ->
lines.forEach { line ->
logcatOutput.append(line).append("\n")
}
}

return logcatOutput.toString()
}

private companion object : LogCompanion("StatsDtaMacrobenchmarkRule")
}
```

cc...@google.com <cc...@google.com> #8Jul 21, 2023 08:36PM

But even using just the MacrobenchmarkRule, it has the same issue w/ perfectto process not being killed...

jg...@google.com <jg...@google.com> #9Jul 24, 2023 11:20AM

Running killall in an adb shell doesn't work too:
```
$ killall perfetto
killall: pid 19422: Operation not permitted
killall: perfetto: Operation not permitted
```

Message last modified on Jul 24, 2023 11:21AM

ml...@google.com <ml...@google.com> #10Aug 22, 2023 12:49PM

restarting the device also doesn't seem to help

jg...@google.com <jg...@google.com> #11Aug 22, 2023 01:06PM

Forgot to mention my device: Pixel7 latest Android 15 beta, build API31.240517.031
Device is not rooted.

From the logs, it seems like the test doesn't have permissions needed to kill the perfetto process. It probably should send an IPC call to it to kill it (if perfectto has that capability).

di...@target.com <di...@target.com> #12Aug 22, 2023 01:11PM

Workaround for me was try a different device. Samsung S23 Ultra w/ Android 14 works w/o that perfetto kill permission error.

jg...@google.com <jg...@google.com> #13Aug 22, 2023 01:18PM

Experiencing the same issue.

Stacktrace:

java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=24965)]
at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:617)
at androidx.benchmark.Shell.terminateProcessesAndWait(Shell.kt:587)
at androidx.benchmark.perfetto.PerfettoHelper$Companion.stopAllPerfettoProcesses(PerfettoHelper.kt:470)
at androidx.benchmark.perfetto.PerfettoHelper.startCollecting(PerfettoHelper.kt:85)
at androidx.benchmark.perfetto.PerfettoCapture.start(PerfettoCapture.kt:69)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.start(PerfettoCaptureWrapper.kt:76)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record(PerfettoCaptureWrapper.kt:131)
at androidx.benchmark.perfetto.PerfettoCaptureWrapper.record$default(PerfettoCaptureWrapper.kt:95)
at androidx.benchmark.macro.MacrobenchmarkPhaseKt.runPhase(MacrobenchmarkPhase.kt:105)
at androidx.benchmark.macro.MacrobenchmarkKt$macrobenchmark$4.invoke(Macrobenchmark.kt:258)
at androidx.benchmark.macro.MacrobenchmarkKt$macrobenchmark$4.invoke(Macrobenchmark.kt:255)
at androidx.benchmark.perfetto.PerfettoTraceProcessor$Companion.runServer-VtjQ1oo(PerfettoTraceProcessor.kt:133)
at androidx.benchmark.perfetto.PerfettoTraceProcessor$Companion.runServer(PerfettoTraceProcessor.kt:108)
at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmark(Macrobenchmark.kt:255)
at androidx.benchmark.macro.MacrobenchmarkKt.macrobenchmarkWithStartupMode(Macrobenchmark.kt:392)
at androidx.benchmark.macro.junit4.MacrobenchmarkRule.measureRepeated(MacrobenchmarkRule.kt:108)
at com.example.baselineprofile.StartupBenchmarks.benchmark(StartupBenchmarks.kt:52)
at com.example.baselineprofile.StartupBenchmarks.startupCompilationNone(StartupBenchmarks.kt:44)

Versions:

androidx.benchmark:benchmark-macro-junit4:1.3.0
AGP: 8.6.0
Android Studio: Android Studio Koala Feature Drop | 2024.1.2

Device:

Google Pixel 6 Pro
Android 15
Android security update: August 5, 2024
Google Play system update: July 1, 2024
Kernel version:
5.10.210-android13-4-03254-g38965378c80a-ab11958173
#1 Wed Jun 12 03:24:21 UTC 2024
Build number: AP41.240726.010
Not rooted

The full logs of two test runs can be found in the attachments of the previous comment.

This section in the logs seems interesting:

09-03 11:09:10.873 10922 10942 D PerfettoCapture: Supported ABIs: arm64-v8a, armeabi-v7a, armeabi
09-03 11:09:10.873 10922 10942 D PerfettoCapture: Recording perfetto trace
09-03 11:09:10.873 27764 10817 I NetworkScheduler.Stats: (REDACTED) Task %s/%s started execution. cause:%s exec_start_elapsed_seconds: %s
09-03 11:09:10.876 27764 10713 I NetworkScheduler.Stats: (REDACTED) Task %s/%s finished executing. cause:%s result: %s elapsed_millis: %s uptime_millis: %s exec_start_elapsed_seconds: %s
09-03 11:09:10.890  4184  5455 W MediaProvider: isAppCloneUserPair for user 0: false
09-03 11:09:10.895 10922 10942 I PerfettoCapture: Cleanup perfetto before starting.
09-03 11:09:10.934 27764 10817 I NetworkScheduler.Stats: (REDACTED) Task %s/%s started execution. cause:%s exec_start_elapsed_seconds: %s
09-03 11:09:10.938 27764 11369 I NetworkScheduler.Stats: (REDACTED) Task %s/%s finished executing. cause:%s result: %s elapsed_millis: %s uptime_millis: %s exec_start_elapsed_seconds: %s
09-03 11:09:10.966  4184 30886 W MediaProvider: isAppCloneUserPair for user 0: false
09-03 11:09:11.003  1109  1109 I WifiHAL : Creating message to get link statistics; iface = 47
09-03 11:09:11.019 27764 10817 I NetworkScheduler.Stats: (REDACTED) Task %s/%s started execution. cause:%s exec_start_elapsed_seconds: %s
09-03 11:09:11.023 27764 10820 I NetworkScheduler.Stats: (REDACTED) Task %s/%s finished executing. cause:%s result: %s elapsed_millis: %s uptime_millis: %s exec_start_elapsed_seconds: %s
09-03 11:09:11.045  4184 30886 W MediaProvider: Ignoring param:deletedata post U for external apps
09-03 11:09:11.048  4184 30886 I MediaProvider: Invalidating LocalCallingIdentity cache for package com.example.baselineprofile. Reason: owned_database_row_deleted:/storage/emulated/0/Android/media/com.example.baselineprofile/temporaryScript3723391827797421641.tmp
09-03 11:09:11.051  4184 30886 I MediaProvider: Deleted 1 0 0 0 0 0 0 items on external_primary due to com.android.shell
09-03 11:09:11.054 10922 10942 D Benchmark: kill -TERM command output - Output(stdout=, stderr=/storage/emulated/0/Android/media/com.example.baselineprofile/temporaryScript3723391827797421641.tmp[2]: kill: 24965: Operation not permitted
09-03 11:09:11.054 10922 10942 D Benchmark: )

It looks like PerfettoCapture is trying to kill an already running instance of perfetto, but it doesn't have the rights to do so (last log line).

Listing running perfetto processes on the device after the test run shows:

adb -d shell ps | grep perfetto
statsd       15678     1   10846896   4480 0                   0 S perfetto
statsd       24965     1   10814128   3208 0                   0 S perfetto

The process ID of the second process matches the ID in the Stacktrace above. So PerfettoCapture tried to stop this one, but didn't have permission to do so.

Trying to kill these process via adb is also not permitted:

$ adb -d shell kill 24965
/system/bin/sh: kill: 24965: Operation not permitted

$ adb -d shell kill 15678
/system/bin/sh: kill: 15678: Operation not permitted

The user that owns the process seems to be statsd. This looks like the Statsd module. It seems to be responsible for running the perfetto process that can't be killed.

This is likely what comment #9 is also pointing at.

I don't have any other hardware devices with me for comparison runs.

When running the test on an Emulator, the log shows this:

09-03 12:06:55.431 10498 10516 D PerfettoCapture: Supported ABIs: arm64-v8a
09-03 12:06:55.431 10498 10516 D PerfettoCapture: Recording perfetto trace
09-03 12:06:55.435  1479  8742 W MediaProvider: isAppCloneUserPair for user 0: false
09-03 12:06:55.436 10498 10516 I PerfettoCapture: Cleanup perfetto before starting.
09-03 12:06:55.445  1285 10327 I NetworkScheduler.Stats: (REDACTED) Task %s/%s started execution. cause:%s exec_start_elapsed_seconds: %s
09-03 12:06:55.446  1285 10578 I NetworkScheduler.Stats: (REDACTED) Task %s/%s finished executing. cause:%s result: %s elapsed_millis: %s uptime_millis: %s exec_start_elapsed_seconds: %s
09-03 12:06:55.453  1479  8742 W MediaProvider: isAppCloneUserPair for user 0: false
09-03 12:06:55.464  1285 10327 I NetworkScheduler.Stats: (REDACTED) Task %s/%s started execution. cause:%s exec_start_elapsed_seconds: %s
09-03 12:06:55.466  1285  3618 I NetworkScheduler.Stats: (REDACTED) Task %s/%s finished executing. cause:%s result: %s elapsed_millis: %s uptime_millis: %s exec_start_elapsed_seconds: %s
09-03 12:06:55.474  1479  2128 I MediaProvider: Invalidating LocalCallingIdentity cache for package com.example.baselineprofile. Reason: owned_database_row_deleted:/storage/emulated/0/Android/media/com.example.baselineprofile/temporaryScript2502516040961053018.tmp
09-03 12:06:55.474  1479  2128 I MediaProvider: Deleted 1 0 0 0 0 0 0 items on external_primary due to com.android.shell
09-03 12:06:55.475 10498 10516 I PerfettoCapture: Starting perfetto tracing with cmd: cat /storage/emulated/0/Android/media/com.example.baselineprofile/trace_config.pb | perfetto --background-wait -c - -o /data/misc/perfetto-traces/trace_output.pb
09-03 12:06:55.478  1479  8742 W MediaProvider: isAppCloneUserPair for user 0: false
09-03 12:06:55.484  1285 10327 I NetworkScheduler.Stats: (REDACTED) Task %s/%s started execution. cause:%s exec_start_elapsed_seconds: %s
09-03 12:06:55.486  1285  3618 I NetworkScheduler.Stats: (REDACTED) Task %s/%s finished executing. cause:%s result: %s elapsed_millis: %s uptime_millis: %s exec_start_elapsed_seconds: %s
09-03 12:06:55.484 11210 11210 W perfetto: type=1400 audit(0.0:455): avc:  denied  { write } for  path="/data/local/tmp/temporaryScript4626443941097950496.tmp_stderr" dev="dm-39" ino=65625 scontext=u:r:perfetto:s0 tcontext=u:object_r:shell_data_file:s0 tclass=file permissive=0
09-03 12:06:55.493 11211 11211 I perfetto:    perfetto_cmd.cc:1053 Connected to the Perfetto traced service, starting tracing
09-03 12:06:55.493   444   444 I perfetto: ng_service_impl.cc:1042 Configured tracing session 22, #sources:9, duration:0 ms, #buffers:2, total buffer size:36864 KB, total sessions:1, uid:2000 session name: ""
09-03 12:06:55.493   432   432 I perfetto:  probes_producer.cc:141 Ftrace setup (target_buf=43)
09-03 12:06:55.492   432   432 W traced_probes: type=1400 audit(0.0:456): avc:  denied  { read } for  name="current_tracer" dev="tracefs" ino=9295 scontext=u:r:traced_probes:s0 tcontext=u:object_r:debugfs_tracing_debug:s0 tclass=file permissive=0
09-03 12:06:55.493   432   432 I perfetto:    ftrace_procfs.cc:445 disabled ftrace in /sys/kernel/tracing/
09-03 12:06:55.708   432   432 W traced_probes: type=1400 audit(0.0:457): avc:  denied  { read } for  name="format" dev="tracefs" ino=8233 scontext=u:r:traced_probes:s0 tcontext=u:object_r:debugfs_tracing_debug:s0 tclass=file permissive=0
09-03 12:06:55.710   432   432 I perfetto:    ftrace_procfs.cc:442 enabled ftrace in /sys/kernel/tracing/
09-03 12:06:55.751  1479  6378 I MediaProvider: Invalidating LocalCallingIdentity cache for package com.example.baselineprofile. Reason: owned_database_row_deleted:/storage/emulated/0/Android/media/com.example.baselineprofile/temporaryScript4626443941097950496.tmp
09-03 12:06:55.753  1479  6378 I MediaProvider: Deleted 1 0 0 0 0 0 0 items on external_primary due to com.android.shell
09-03 12:06:55.754 10498 10516 I PerfettoCapture: Perfetto output - 11211
09-03 12:06:55.754 10498 10516 I PerfettoCapture: EXITCODE=0

Emulator info:

Pixel 6 AVD
Android 14
Android security update: September 5, 2023
Google Play system update: July 1, 2023
Kernel version:
6.1.23-android14-4-00257-g7e35917775b8-ab9964412
#1 Mon Apr 17 20:50:58 UTC 2023
Build number: UE1A.230829.036.A1 dev-keys

It seems like PerfettoCapture doesn't try to kill a perfetto process, and it seems to be able to start a perfetto trace.

Querying for an existing perfetto process on the emulator shows that no perfetto processes are running.

Hypothesis based on information in this thread:

On Pixel (maybe others too) devices with Android 15, the Statsd module is starting a perfetto process. This process can't be killed by PerfettoCapture when running a test, which produces the crash.

Edit 1: Seems like I hit a shortcut that sends the comment and deleted the text 🙈. Now I have to type it all again 😫. Hope I don't hit it again. Well, here we go 🤞.

Edit 2: Comment text got removed when posting the comment — and of course I didn't save it somewhere else. On to try number 3 🏇. Different browser...

di...@target.com <di...@target.com> #14Aug 22, 2023 02:16PM

Checked on a Pixel 6 Pro with Android 14 today. The crash did not occur.

I tried restarting the problematic device running 15, it did not resolve the issue. After a restart, the perfetto processes owned by statsd are also present again.

I also encountered this issue with the problematic Pixel 6 Pro running Android 15: https://issuetracker.google.com/issues/239897826. It also couldn't be resolved with a restart. On the Pixel 6 Pro with Android 14, recording a trace was possible.
Maybe the problem described in that issue could also be triggered by the perfetto process which can't be killed. The logs posted in this issue hint that the cause might also be a failure to run perfetto on the device.

jg...@google.com <jg...@google.com> #15Aug 22, 2023 02:17PM

I was able to occasionally reproduce this with my Pixel 5 with ToT on ScrollerBenchmark as well as TrivialKotlinBenchmark. Unfortunately I can't seem to reproduce this anymore, but here are some details anyway:

Device:

Google Pixel 5
Android 14

cc...@google.com <cc...@google.com> #16Sep 5, 2023 08:43PM

Reassigned to jg...@google.com.

Nice work debugging in #13.
I can confirm I have the same issue on a Pixel 6 running Android 15. Same steps...same error. perfetto process can't be killed.
This seems like a bug in macrobenchmark? Or the Pixel 6 perfetto statsd autostartup.

Given this is a pretty popular test device, it should be easily reproducible...

jg...@google.com <jg...@google.com> #17Sep 8, 2023 06:30PM

Experiencing the same issue.

Stacktrace:

----- begin exception -----
01-23 21:15:05.513 938 964 E TestRunner: java.lang.IllegalStateException: Failed to stop [ProcessPid(processName=perfetto, pid=5165)]
Device:
Pixel 9 Pro XL | Android 15

ap...@google.com <ap...@google.com> #18Sep 8, 2023 07:13PM

Project: platform/frameworks/support
Branch: androidx-main
Author: Chris Craik <ccraik@google.com>
Link: https://android-review.googlesource.com/3463345

Avoid crashes from external perfetto trace capture

Expand for full commit details

Avoid crashes from external perfetto trace capture 
 
Fixes: 323601788 
Test: ShellTest#killProcessesAndWait_failure 
Relnote: "Speculative fix for crashes: 'Failed to stop [ProcessPid(processName=perfetto, pid=...)]'. Now Benchmark will log a message instead of crashing when a backgroudn Perfetto process isn't able to be stopped before running the benchmark." 
 
From bugreport details, it appears that background perfetto traces are 
often triggered which cannot be terminated by shell. Log an error 
rather than crashing the benchmark. 
 
Change-Id: I37d3e254f7f3e49c53387dae89bb5bed7d2c9bf5

Files:

M benchmark/benchmark-common/src/androidTest/java/androidx/benchmark/PerfettoHelperTest.kt
M benchmark/benchmark-common/src/androidTest/java/androidx/benchmark/ShellTest.kt
M benchmark/benchmark-common/src/main/java/androidx/benchmark/Shell.kt
M benchmark/benchmark-common/src/main/java/androidx/benchmark/perfetto/PerfettoHelper.kt
M benchmark/benchmark-macro/src/androidTest/java/androidx/benchmark/macro/perfetto/AndroidxTracingTraceTest.kt
M benchmark/benchmark-macro/src/androidTest/java/androidx/benchmark/macro/perfetto/PerfettoCaptureSweepTest.kt

Hash: a1d00d7f334608a7d4975b209b4569cfdadb2539
Date: Thu Jan 23 16:10:27 2025

cc...@google.com <cc...@google.com> #19Sep 8, 2023 09:51PM

The following release(s) address this bug.It is possible this bug has only been partially addressed:

androidx.benchmark:benchmark-common:1.4.0-alpha08
androidx.benchmark:benchmark-macro:1.4.0-alpha08

ml...@google.com <ml...@google.com> #20Sep 11, 2023 08:06AM

I kind of agree as well DAC is the right place for this. We have some error messages / misconfiguration for Macrobenchmark on DAC around build variants and multi-module setup. But these errors are a good fit, because the libraries can't do it in any away and it's a form of guidance to properly configure your project.

Regarding configuration matrix for dependencies. We're having more and more dependencies that are compatible only with certain versions, maybe it's time to rethink having a compatibility matrix?

You need to have proper versions of:

AGP
Macrobenchmark
Profile Installer
(potentially) Baseline Profile Gradle Plugin
(and now) Perfetto

If misconfiguration crashes with some reasonable message (we could ask/answer that on StackOverflow), that SG to me. It's worse when it just doesn't work.

jg...@google.com <jg...@google.com> #21Sep 11, 2023 04:25PM

Crashing with some reasonable message (we could ask/answer that on StackOverflow) is what we now moved to - changes will go out in the next Benchmark+Tracing release.

Both possible crash scenarios described below.

NoClassDefFoundError

java.lang.NoClassDefFoundError: Failed resolution of: Landroidx/tracing/perfetto/Tracing; means the app is using an old version of compose-runtime-tracing. Updating to the latest version fixes the issue.

If we try to detect a failed classload, we'd have to release a newer version with this logic, which defeats the point of the change, as the fix is to simply use a newer version. And since we're now in Beta, the name of the class won't change.

RuntimeException

RuntimeException: Issue while enabling Perfetto SDK tracing in ${perfettoSdkConfig.targetPackage}: Perfetto SDK binary dependencies missing. Required version: [...] To fix, declare the following dependency [...] will be thrown from the next Benchmark release whenever we fail to resolve tracing-perfetto-binary in the benchmark. The error message is very descriptive (see in full).

Simplifying the workflow

From the user's perspective, the easiest would be to just use the latest version of compose-runtime-tracing. I'll try to get it to 1.0.0 stable ASAP to encourage users to upgrade (currently they're using an Alpha). If they need to supply tracing-perfetto-binary dependency, Benchmark will inform them how to do that (through the RuntimeException described above). Does that sound reasonable?

jg...@google.com <jg...@google.com> #22Sep 11, 2023 04:28PM

Marked as fixed.

I'm going to close the bug as IMO http://aosp/2743602 fixed the issue, but please re-open if you think more work is required here.

na...@google.com <na...@google.com> #23Sep 20, 2023 07:15PM

The following release(s) address this bug.It is possible this bug has only been partially addressed:

androidx.benchmark:benchmark-common:1.2.0-rc01
androidx.benchmark:benchmark-macro:1.2.0-rc01

ml...@google.com <ml...@google.com> #24Sep 22, 2023 03:19PM

Something's wrong, I think.

When I use

androidx.compose.runtime.runtime-tracing-1.0.0-alpha04 # in app (target)
androidx.tracing.tracing-perfetto-1.0.0-rc01 # in benchmark
androidx.tracing.tracing-perfetto-binary-1.0.0-rc01 # in benchmark

androidx.benchmark:benchmark-macro-juni4:1.2.0-rc01 #in benchmark

It fails with

java.lang.RuntimeException: Issue while enabling Perfetto SDK tracing in com.google.composeviewbenchmarks.target: Perfetto SDK binary verification failed. Required version: 1.0.0-beta02. Error: androidx.tracing.perfetto.security.IncorrectChecksumException: Invalid checksum for file: /data/user/0/com.google.composeviewbenchmarks.target/code_cache/libtracing_perfetto.so. Ensure you are using correct version of the library and clear local caches.. If working with an unreleased snapshot, ensure all modules are built against the same snapshot (e.g. clear caches and rebuild).

Should we check only older versions? Or does this need to be an exact version?

Adding

version {
   strictly("1.0.0-beta02")
}

resolves the problem

Message last modified on Sep 22, 2023 03:19PM

ml...@google.com <ml...@google.com> Sep 25, 2023 07:30AM

Status: Assigned (reopened)

jg...@google.com <jg...@google.com> #25Sep 29, 2023 01:01PM

Marked as fixed.

Re comment#24, error message from compose-runtime-tracing (the target app) is saying it requires tracing-perfetto-binary beta02, so that's what should be set in benchmark. Not sure why strict keyword is required. This is a separate issue (from what the bug was originally opened for), and since we now track SLO, let's open a new one for new issues instead of reusing this one as a grab-all. For issue from comment#24 I've created b/302672687.

jg...@google.com <jg...@google.com> #26Sep 29, 2023 01:02PM

(marking as fixed as the original issue was fixed, for comment#24, please follow b/302672687)

IssueTracker

Crash after first iteration when using fullTracing

Status Update

Description

Comments

cc...@google.com <cc...@google.com> Jun 7, 2023 03:36PM

ml...@google.com <ml...@google.com> #2Jun 22, 2023 10:31AM

jg...@google.com <jg...@google.com> #3Jun 23, 2023 04:33PM

ml...@google.com <ml...@google.com> #4Jun 30, 2023 02:08PM

jg...@google.com <jg...@google.com> #5Jun 30, 2023 02:30PM

ml...@google.com <ml...@google.com> Jul 21, 2023 09:57AM

cc...@google.com <cc...@google.com> #6Jul 21, 2023 05:15PM

ml...@google.com <ml...@google.com> #7Jul 21, 2023 05:48PM

cc...@google.com <cc...@google.com> #8Jul 21, 2023 08:36PM

jg...@google.com <jg...@google.com> #9Jul 24, 2023 11:20AM

ml...@google.com <ml...@google.com> #10Aug 22, 2023 12:49PM

jg...@google.com <jg...@google.com> #11Aug 22, 2023 01:06PM

di...@target.com <di...@target.com> #12Aug 22, 2023 01:11PM

jg...@google.com <jg...@google.com> #13Aug 22, 2023 01:18PM

di...@target.com <di...@target.com> #14Aug 22, 2023 02:16PM

jg...@google.com <jg...@google.com> #15Aug 22, 2023 02:17PM

cc...@google.com <cc...@google.com> #16Sep 5, 2023 08:43PM

jg...@google.com <jg...@google.com> #17Sep 8, 2023 06:30PM

ap...@google.com <ap...@google.com> #18Sep 8, 2023 07:13PM

cc...@google.com <cc...@google.com> #19Sep 8, 2023 09:51PM

ml...@google.com <ml...@google.com> #20Sep 11, 2023 08:06AM

jg...@google.com <jg...@google.com> #21Sep 11, 2023 04:25PM

NoClassDefFoundError

RuntimeException

Simplifying the workflow

jg...@google.com <jg...@google.com> #22Sep 11, 2023 04:28PM

na...@google.com <na...@google.com> #23Sep 20, 2023 07:15PM

ml...@google.com <ml...@google.com> #24Sep 22, 2023 03:19PM

ml...@google.com <ml...@google.com> Sep 25, 2023 07:30AM

jg...@google.com <jg...@google.com> #25Sep 29, 2023 01:01PM

jg...@google.com <jg...@google.com> #26Sep 29, 2023 01:02PM

Issue 286228781

Description

Issue summary

Comments

cc...@google.com <cc...@google.com> Jun 7, 2023 03:36PM

ml...@google.com <ml...@google.com> #2Jun 22, 2023 10:31AM

jg...@google.com <jg...@google.com> #3Jun 23, 2023 04:33PM

ml...@google.com <ml...@google.com> #4Jun 30, 2023 02:08PM

jg...@google.com <jg...@google.com> #5Jun 30, 2023 02:30PM

ml...@google.com <ml...@google.com> Jul 21, 2023 09:57AM

cc...@google.com <cc...@google.com> #6Jul 21, 2023 05:15PM

ml...@google.com <ml...@google.com> #7Jul 21, 2023 05:48PM

cc...@google.com <cc...@google.com> #8Jul 21, 2023 08:36PM

jg...@google.com <jg...@google.com> #9Jul 24, 2023 11:20AM

ml...@google.com <ml...@google.com> #10Aug 22, 2023 12:49PM

jg...@google.com <jg...@google.com> #11Aug 22, 2023 01:06PM

di...@target.com <di...@target.com> #12Aug 22, 2023 01:11PM

jg...@google.com <jg...@google.com> #13Aug 22, 2023 01:18PM

di...@target.com <di...@target.com> #14Aug 22, 2023 02:16PM

jg...@google.com <jg...@google.com> #15Aug 22, 2023 02:17PM

cc...@google.com <cc...@google.com> #16Sep 5, 2023 08:43PM

jg...@google.com <jg...@google.com> #17Sep 8, 2023 06:30PM

ap...@google.com <ap...@google.com> #18Sep 8, 2023 07:13PM

cc...@google.com <cc...@google.com> #19Sep 8, 2023 09:51PM

ml...@google.com <ml...@google.com> #20Sep 11, 2023 08:06AM

jg...@google.com <jg...@google.com> #21Sep 11, 2023 04:25PM

NoClassDefFoundError

RuntimeException

Simplifying the workflow

jg...@google.com <jg...@google.com> #22Sep 11, 2023 04:28PM

na...@google.com <na...@google.com> #23Sep 20, 2023 07:15PM

ml...@google.com <ml...@google.com> #24Sep 22, 2023 03:19PM

ml...@google.com <ml...@google.com> Sep 25, 2023 07:30AM

jg...@google.com <jg...@google.com> #25Sep 29, 2023 01:01PM

jg...@google.com <jg...@google.com> #26Sep 29, 2023 01:02PM

Add comment

Issue metadata