StackSampling Profiling Issue - SimplePerf Fails to Start [236109374]

Fixed

Bug

Status Update

No update yet.

Description

al...@google.com

created issue #1

Jun 15, 2022 11:19AM

Component used: androidx.benchmark

Version used: built from HEAD (master) on 6th June 2022

Devices/Android versions reproduced on: Google Pixel 5 (redfin-userdebug) running UpsideDownCake built from HEAD (master) on 6th June 2022

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

Sample project to trigger the issue: uploaded at http://ag/18910949 (after cloning, run with atest cts/common/device-side/bedstead/nene/src/test/java/com/android/bedstead/nene/benchmarking/NeneBenchmarksTest.java)

arm64-v8a NeneTest
------------------
com.android.bedstead.nene.test (1 Test)
[1/1] com.android.bedstead.nene.benchmarking.NeneBenchmarksTest#benchmarkAddingNumbers: FAILED (1.697s)

STACKTRACE:
java.lang.Error: failed to receive simpleperf start flag
	at androidx.benchmark.simpleperf.ProfileSession.startSimpleperfRecording(ProfileSession.java:368)
	at androidx.benchmark.simpleperf.ProfileSession.startRecording(ProfileSession.java:142)
	at androidx.benchmark.simpleperf.ProfileSession.startRecording(ProfileSession.java:127)
	at androidx.benchmark.StackSamplingSimpleperf.start(Profiler.kt:233)
	at androidx.benchmark.BenchmarkState.beginRunningStage(BenchmarkState.kt:236)
	at androidx.benchmark.BenchmarkState.startNextRepeat(BenchmarkState.kt:306)
	at androidx.benchmark.BenchmarkState.keepRunningInternal(BenchmarkState.kt:403)
	at androidx.benchmark.BenchmarkState.keepRunning(BenchmarkState.kt:360)
	at com.android.bedstead.nene.benchmarking.NeneBenchmarksTest.benchmarkAddingNumbers(NeneBenchmarksTest.java:44)


Summary (Test executed with 1 devices.)
-------
arm64-v8a NeneTest: Passed: 0, Failed: 1, Ignored: 0, Assumption Failed: 0

Comments

al...@google.com <al...@google.com> #2Jun 15, 2022 11:22AM

StackSampling profiling throws an error on this line http://cs/aosp-androidx/benchmark/benchmark-common/src/main/java/androidx/benchmark/simpleperf/ProfileSession.java;l=368;rcl=9033158677d14de794b2b26aabfcace560feef34

The issue is 100% reproducible on my end.

ra...@google.com <ra...@google.com> #3Jun 15, 2022 03:52PM

Can you attach your logs with the log tag Benchmark ? They will have some more useful information.

al...@google.com <al...@google.com> #4Jun 17, 2022 12:41PM

These are the logs I got whilst running the benchmark:

aleksbgbg@aleksbgbg-1:~/2android$ adb logcat -s Benchmark
--------- beginning of main
06-17 13:41:02.629 23616 23633 D Benchmark: Usable output directory: /storage/emulated/0/Android/media/com.android.bedstead.nene.test
06-17 13:41:02.640 23616 23633 D Benchmark: Profiler StackSamplingSimpleperf, freq 1000, duration 5
06-17 13:41:02.640 23616 23633 D Benchmark: Output Directory: /storage/emulated/0/Android/media/com.android.bedstead.nene.test
06-17 13:41:02.713 23616 23633 D Benchmark: launching Benchmark IsolationActivity
06-17 13:41:02.835 23616 23616 D Benchmark: cpu0 CoreDir(path=/sys/devices/system/cpu/cpu7, online=true, availableFreqs=[806400, 1094400, 1401600, 1766400, 1996800, 2188800, 2304000, 2400000], setSpeedKhz=2400000, maxFreqKhz=2400000)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu1 CoreDir(path=/sys/devices/system/cpu/cpu5, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu2 CoreDir(path=/sys/devices/system/cpu/cpu3, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu3 CoreDir(path=/sys/devices/system/cpu/cpu1, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu4 CoreDir(path=/sys/devices/system/cpu/cpu6, online=true, availableFreqs=[652800, 940800, 1094400, 1478400, 1728000, 1900800, 2092800, 2208000], setSpeedKhz=2208000, maxFreqKhz=2208000)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu5 CoreDir(path=/sys/devices/system/cpu/cpu4, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu6 CoreDir(path=/sys/devices/system/cpu/cpu2, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:02.836 23616 23616 D Benchmark: cpu7 CoreDir(path=/sys/devices/system/cpu/cpu0, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:03.825 23737 23754 D Benchmark: Usable output directory: /storage/emulated/0/Android/media/com.android.bedstead.nene.test
06-17 13:41:03.840 23737 23754 D Benchmark: Profiler StackSamplingSimpleperf, freq 1000, duration 5
06-17 13:41:03.840 23737 23754 D Benchmark: Output Directory: /storage/emulated/0/Android/media/com.android.bedstead.nene.test
06-17 13:41:03.911 23737 23754 D Benchmark: launching Benchmark IsolationActivity
06-17 13:41:04.046 23737 23737 D Benchmark: cpu0 CoreDir(path=/sys/devices/system/cpu/cpu7, online=true, availableFreqs=[806400, 1094400, 1401600, 1766400, 1996800, 2188800, 2304000, 2400000], setSpeedKhz=2400000, maxFreqKhz=2400000)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu1 CoreDir(path=/sys/devices/system/cpu/cpu5, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu2 CoreDir(path=/sys/devices/system/cpu/cpu3, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu3 CoreDir(path=/sys/devices/system/cpu/cpu1, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu4 CoreDir(path=/sys/devices/system/cpu/cpu6, online=true, availableFreqs=[652800, 940800, 1094400, 1478400, 1728000, 1900800, 2092800, 2208000], setSpeedKhz=2208000, maxFreqKhz=2208000)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu5 CoreDir(path=/sys/devices/system/cpu/cpu4, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu6 CoreDir(path=/sys/devices/system/cpu/cpu2, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:04.046 23737 23737 D Benchmark: cpu7 CoreDir(path=/sys/devices/system/cpu/cpu0, online=true, availableFreqs=[300000, 576000, 614400, 864000, 902400, 1363200, 1516800, 1651200, 1804800], setSpeedKhz=1804800, maxFreqKhz=1804800)
06-17 13:41:04.291 23737 23754 D Benchmark: -- Running com.android.bedstead.nene.benchmarking.NeneBenchmarksTest#installTestApp --
06-17 13:41:04.664 23737 23870 W Benchmark: 
06-17 13:41:04.664 23737 23870 W Benchmark: WARNING: Using profiler=StackSamplingSimpleperf, results will be affected. 
06-17 13:41:04.664 23737 23870 W Benchmark: 
06-17 13:41:04.667 23737 23870 D Benchmark: Set 23870 (Bench thread) to priority -20. Was 0, now -20
06-17 13:41:04.667 23737 23870 D Benchmark: Set 23745 (Jit) to priority -15. Was 9, now -15
06-17 13:42:01.126 23737 23754 D Benchmark: kill -TERM command output - 
06-17 13:42:01.268 23737 23754 D Benchmark: Waiting 100 ms for [ProcessPid(processName=perfetto, pid=23847)] to die
06-17 13:42:01.408 23737 23754 D Benchmark: Waiting 100 ms for [ProcessPid(processName=perfetto, pid=23847)] to die
06-17 13:42:01.545 23737 23754 D Benchmark: Waiting 100 ms for [ProcessPid(processName=perfetto, pid=23847)] to die
06-17 13:42:01.686 23737 23754 D Benchmark: Waiting 100 ms for [ProcessPid(processName=perfetto, pid=23847)] to die
06-17 13:42:01.826 23737 23754 D Benchmark: Waiting 100 ms for [ProcessPid(processName=perfetto, pid=23847)] to die

cc...@google.com <cc...@google.com> Sep 29, 2022 11:14PM

Reassigned to cc...@google.com.

ap...@google.com <ap...@google.com> #5Sep 30, 2022 01:55AM

Marked as fixed.

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

commit a6e57c90b1ea38232e3149e6f47b68c5fffc6769
Author: Chris Craik <ccraik@google.com>
Date: Mon Sep 26 16:50:11 2022

Switch to cpu-clock event in simpleperf sampled profiling

Fixes: 236109374
Test: ./gradlew benchmark:b-c:cC -P android.testInstrumentationRunnerArguments.class=androidx.benchmark.ProfilerTest

Relnote: "Fixes SampledProfiling crash on API 33+."

Also updated/rebased androidx.benchmark.simpleperf files from api_profiling.

Change-Id: I40743831d240327bbf3d89d09f510d9db09e67c0

M benchmark/benchmark-common/src/main/java/androidx/benchmark/simpleperf/ProfileSession.java
M benchmark/benchmark-common/src/main/java/androidx/benchmark/simpleperf/RecordOptions.java
M benchmark/benchmark-common/src/main/java/androidx/benchmark/Profiler.kt

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

na...@google.com <na...@google.com> #6Oct 24, 2022 01:36PM

The following release(s) address this bug:

androidx.benchmark:benchmark-common:1.2.0-alpha06

Issue 236109374