Baseline profiles generated with a test flagged as syntactically incorrect during next builds [216508418]

Fixed

Feature Request

Status Update

No update yet.

Description

Te...@justin.tv

created issue #1

Jan 26, 2022 09:52PM

Hello, I've followed

the tutorials outlined here:

to generate and then use profiles for my app startup scenario.

Generation of the profiles went as planned - with baseline-prof generated on the emulator. When I copied the file to my app though, and tried to build it and run the tests that would measure the efficiency of those profiles, gradle complained about several syntax errors in the generated profiles (idk if they really are syntax errors).

The errors looked like this:

//    > A failure occurred while executing com.android.build.gradle.internal.tasks.CompileArtProfileTask$CompileArtProfileWorkAction
//    > Error parsing baseline-prof.txt : baseline-prof.txt:4833:97 error: Unexpected text:"+]Lcom/google/android/gms/measurement/internal/zzee;megamorphic_types" after the rule.
//    HSPLcom/google/android/gms/measurement/internal/zzeg;->zza(Ljava/lang/Object;)Ljava/lang/Object;+]Lcom/google/android/gms/measurement/internal/zzee;megamorphic_types

iirc, errors were also detected along the lines that started with '[', like this one: [Landroidx/appcompat/app/AppCompatDelegateImpl$PanelFeatureState;

I eventually went ahead and removed all patterns that resembled the failing ones (maybe removing too much), and the diff results were (unmodified profile diffed against one I edited manually:

576c576
< HSPLandroidx/constraintlayout/solver/ArrayLinkedVariables;->put(Landroidx/constraintlayout/solver/SolverVariable;F)V+]Landroidx/constraintlayout/solver/SolverVariable;Landroidx/constraintlayout/solver/SolverVariable;
---
> HSPLandroidx/constraintlayout/solver/ArrayLinkedVariables;->put(Landroidx/constraintlayout/solver/SolverVariable;F)V+]Landroidx/constraintlayout/solver/SolverVariable;
4833c4833
< HSPLcom/google/android/gms/measurement/internal/zzeg;->zza(Ljava/lang/Object;)Ljava/lang/Object;+]Lcom/google/android/gms/measurement/internal/zzee;megamorphic_types
---
> HSPLcom/google/android/gms/measurement/internal/zzeg;->zza(Ljava/lang/Object;)Ljava/lang/Object;
7322c7322
< HSPLcom/google/gson/internal/bind/TypeAdapters$7;->read(Lcom/google/gson/stream/JsonReader;)Ljava/lang/Number;+]Lcom/google/gson/stream/JsonReader;Lcom/google/gson/stream/JsonReader;
---
> HSPLcom/google/gson/internal/bind/TypeAdapters$7;->read(Lcom/google/gson/stream/JsonReader;)Ljava/lang/Number;
15176c15176
< HSPLtv/twitch/android/shared/experiments/MiniExperimentFetcher;->parseMiniExperimentModel(Ljava/lang/String;Lorg/json/JSONObject;)Ltv/twitch/android/provider/experiments/MiniExperimentModel;+]Lcom/google/gson/Gson;Lcom/google/gson/Gson;
---
> HSPLtv/twitch/android/shared/experiments/MiniExperimentFetcher;->parseMiniExperimentModel(Ljava/lang/String;Lorg/json/JSONObject;)Ltv/twitch/android/provider/experiments/MiniExperimentModel;
21921,22086c21921,22086
< [Landroidx/appcompat/app/AppCompatDelegateImpl$PanelFeatureState;
< [Landroidx/constraintlayout/solver/ArrayRow;
< [Landroidx/constraintlayout/solver/SolverVariable$Type;
< [Landroidx/constraintlayout/solver/SolverVariable;
(lot of lines starting with `[` - I just removed the initial `[`)

We'd really love to use the new baseline profiling feature - let me know if there's more I can share to confirm where the issue might be.

Component used/Version used: in the tests that generated the profile:

androidx.benchmark:benchmark-macro-junit4:1.1.0-beta01 in the app
androidx.profileinstaller:profileinstaller:1.2.0-alpha01"

Devices/Android versions reproduced on:

Gradle build using Gradle 7.3, AGP 7.1

If this is a bug in the library, we would appreciate if you could attach:

Sample project to trigger the issue.
A screenrecord or screenshots showing the issue (if UI related).

Comments

cc...@google.com <cc...@google.com> Jan 26, 2022 10:23PM

Reassigned to ra...@google.com.

Te...@justin.tv <Te...@justin.tv> #2Jan 27, 2022 05:09PM

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

ra...@google.com <ra...@google.com> #3Jan 27, 2022 05:50PM

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

ra...@google.com <ra...@google.com> #4Jan 28, 2022 08:45PM

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)

Message last modified on Jan 28, 2022 08:51PM

Te...@justin.tv <Te...@justin.tv> #5Jan 28, 2022 08:48PM

@ #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?

ra...@google.com <ra...@google.com> #6Jan 28, 2022 08:52PM

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

cc...@google.com <cc...@google.com> #7Feb 1, 2022 09:51PM

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")
}
```

ra...@google.com <ra...@google.com> Feb 10, 2022 07:31PM

Accepted by ra...@google.com.

ap...@google.com <ap...@google.com> #8Feb 11, 2022 06:08PM

Marked as fixed.

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