Closed GayleDaVid closed 11 months ago
Thanks for the stack dump. This is very helpful.
I formatted it below so we can read it easier. It is using AudioTrack so this is Legacy, not MMAP. The ANR in #1216 was happening on MMAP streams.
Did you request a low-latency stream?
The order is: ~AudioStreamTrack() ~AudioTrack() releaseAudioSessionId() BInder waitForResponse()
The audioserver is hanging when releasing the audio session. This is related to Effects. Note that using Effects can lead to an increase in latency. What effects are you using? AEC?
these ANRs occur on Android 11 devices and so far zero reports on Android 12.
Do you have enough devices running 12 to suggest 12 is immune to the ANR? Or are there just so few devices running 12 that we haven't seen it? Any stats you can share would be helpful.
'''
'''
Hey Phil, thank you for your reply.
Did you request a low-latency stream?
Yes,
builder.setSharingMode(oboe::SharingMode::Exclusive);
builder.setPerformanceMode(oboe::PerformanceMode::LowLatency);
It is using AudioTrack so this is Legacy, not MMAP. The ANR in #1216 was happening on MMAP streams.
Yea, we are experiencing in on both legacy and MMAP, I will now share a formatted stack from when we try to open an audio stream
#00 pc 00000000000d68e4 /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
#00 pc 0000000000093590 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
#00 pc 00000000000529e4 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+296)
#00 pc 0000000000053e18 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
#00 pc 0000000000053b88 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+184)
#00 pc 000000000004c014 /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+152)
#00 pc 000000000003daa8 /system/lib64/libaaudio_internal.so (android::BpAAudioService::openStream(aaudio::AAudioStreamRequest const&, aaudio::AAudioStreamConfiguration&)+336)
#00 pc 0000000000039b98 /system/lib64/libaaudio_internal.so (aaudio::AAudioBinderClient::openStream(aaudio::AAudioStreamRequest const&, aaudio::AAudioStreamConfiguration&)+172)
#00 pc 000000000002f5a8 /system/lib64/libaaudio_internal.so (aaudio::AudioStreamInternal::open(aaudio::AudioStreamBuilder const&)+1512)
#00 pc 0000000000022ed8 /system/lib64/libaaudio_internal.so (aaudio::AudioStreamBuilder::build(aaudio::AudioStream**)+860)
#00 pc 00000000000037a8 /system/lib64/libaaudio.so (AAudioStreamBuilder_openStream.cfi+144)
#00 pc 0000000000cf64b4 /data/app/~~Um6ATemD3_MeeIBnjpFldg==/com.smule.singandroid-W3dttyx0f_YD2Mz0xX17MQ==/lib/arm64/libsing.so (oboe::AudioStreamAAudio::open()+704)
#00 pc 0000000000cef0a4 /data/app/~~Um6ATemD3_MeeIBnjpFldg==/com.smule.singandroid-W3dttyx0f_YD2Mz0xX17MQ==/lib/arm64/libsing.so (oboe::AudioStreamBuilder::openStream(oboe::AudioStream**)+704)
#00 pc 0000000000ceef10 /data/app/~~Um6ATemD3_MeeIBnjpFldg==/com.smule.singandroid-W3dttyx0f_YD2Mz0xX17MQ==/lib/arm64/libsing.so (oboe::AudioStreamBuilder::openStream(oboe::AudioStream**)+300)
#00 pc 0000000000cef944 /data/app/~~Um6ATemD3_MeeIBnjpFldg==/com.smule.singandroid-W3dttyx0f_YD2Mz0xX17MQ==/lib/arm64/libsing.so (oboe::AudioStreamBuilder::openStream(std::__ndk1::shared_ptr<oboe::AudioStream>&)+112)
ANR when starting a Stream
#00 pc 00000000000c54a4 /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
#00 pc 0000000000081db8 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
#00 pc 0000000000054a34 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+300)
#00 pc 0000000000055a78 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
#00 pc 00000000000557e8 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+184)
#00 pc 000000000004e098 /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+312)
#00 pc 000000000003ddd8 /system/lib64/libaaudio_internal.so (android::BpAAudioService::startStream(int)+308)
#00 pc 0000000000039d24 /system/lib64/libaaudio_internal.so (aaudio::AAudioBinderClient::startStream(int)+152)
#00 pc 000000000002e2b4 /system/lib64/libaaudio_internal.so (aaudio::AudioStreamInternal::requestStart()+568)
#00 pc 000000000002131c /system/lib64/libaaudio_internal.so (aaudio::AudioStream::systemStart()+336)
#00 pc 0000000000003c64 /system/lib64/libaaudio.so (AAudioStream_requestStart.cfi+148)
#00 pc 0000000000cfa994 /data/app/~~TVpXmh4F6jvGdmu5Gh31NQ==/com.smule.singandroid-k3Y_UesLxYVcgVwAWtZD4Q==/lib/arm64/libsing.so (oboe::AudioStreamAAudio::requestStart()+136)
snippet for starting stream
mAudioStream->requestStart();
mAudioStream->waitForStateChange(currentState, &nextState, nanoseconds);
ANR stopping a stream
#00 pc 00000000000d69d8 /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+8)
#00 pc 0000000000093664 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
#00 pc 00000000000529e4 /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+296)
#00 pc 0000000000053e18 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+60)
#00 pc 0000000000053b88 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+184)
#00 pc 000000000004c014 /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+152)
#00 pc 000000000003ddbc /system/lib64/libaaudio_internal.so (android::BpAAudioService::closeStream(int)+308)
#00 pc 0000000000039ec8 /system/lib64/libaaudio_internal.so (aaudio::AAudioBinderClient::closeStream(int)+152)
#00 pc 0000000000030b60 /system/lib64/libaaudio_internal.so (aaudio::AudioStreamInternal::release_l()+364)
#00 pc 0000000000022230 /system/lib64/libaaudio_internal.so (aaudio::AudioStream::safeReleaseClose()+280)
#00 pc 0000000000003ab8 /system/lib64/libaaudio.so (AAudioStream_close.cfi+140)
#00 pc 0000000000cfa5b4 /data/app/~~xoDdagjTzf7neIEG4P2eYw==/com.smule.singandroid-7aEa4QRYKlkGjxNDyhuhSw==/lib/arm64/libsing.so (oboe::AudioStreamAAudio::close()+180)
snippet for Stopping stream
mAudioStream->stop();
mAudioStream->close();
mAudioStream.reset();
Do you have enough devices running 12 to suggest 12 is immune to the ANR?
So far we have around 5% of all devices on Android 12. This value grows daily as users update to Android 12.
@philburk Thank you for taking a look. We have some instances of this ANR on Android 12 coming through, so it is not immune. I'm also seeing a handful of similar-looking stacks from users still on OpenSL. We don't use Oboe for our OpenSL implementation, but here is the stack in case it's informative:
0 libc.so __ioctl
1 libc.so ioctl
2 libbinder.so android::IPCThreadState::talkWithDriver(bool)
3 libbinder.so android::IPCThreadState::waitForResponse(android::Parcel*, int*)
4 libbinder.so android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
5 libbinder.so android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
6 libaudioclient.so android::BpAudioFlinger::registerClient(android::sp<android::IAudioFlingerClient> const&)
7 libaudioclient.so android::AudioSystem::get_audio_flinger() (.cfi)
8 libaudioclient.so android::AudioSystem::releaseAudioSessionId(audio_session_t, int) (.cfi)
9 libaudioclient.so android::AudioTrack::~AudioTrack()
10 libaudioclient.so android::AudioTrack::~AudioTrack()
11 libutils.so android::RefBase::decStrong(void const*) const
12 libaudioclient.so android::TrackPlayerBase::doDestroy()
13 libaudioclient.so android::TrackPlayerBase::destroy()
14 libwilhelm.so android_audioPlayer_destroy(CAudioPlayer_struct*)
15 libwilhelm.so CAudioPlayer_Destroy(void*)
16 libwilhelm.so IObject_Destroy(SLObjectItf_ const* const*)
With respect to effects, we aren't intentionally enabling any. We use the VoiceRecognition input preset to avoid them.
It is significant that you are seeing ANRs on Legacy AudioFlinger streams, MMAP streams, and also on OpenSL ES streams (not using Oboe). And it happens on Android 11 and 12.
The devices reported and their SOCs are:
I see that there are devices with Qualcomm, MediaTek and Exynos SOCs. So it is probably not a HAL issue unless it is in the common HAL code, or in TinyALSA.
Do you have any idea of how often this occurs? Also how many reports are you seeing on the phones above? If it is just 1 or 2 then other phones may be affected but we just don't catch an ANR. If you get 100 reports on one phone and zero reports on another, equally popular, phone then that would suggest a problem more specific to the phone.
Vivo 1920
Qualcomm SM6125
Redmi Note 8 Pro
Mediatek MT6785T
Vivo V2039 - ???
Qualcomm SDM439
Vivo V2022 - ???
Qualcomm SM6125
Do you have any idea of how often this occurs?
On a daily basis this occurs ~63- 130 times
Also how many reports are you seeing on the phones above?
Thank you for continuing looking into this,
If you get 100 reports on one phone and zero reports on another, equally popular, phone then that would suggest a problem more specific to the phone.
The issues is present across a wide variety of the popular device
I am tracking this with internal bug b/219050228
The OpenSL ES trace is interesting. It seems to be doing some unnecessary work. But that is probably not the root cause.
I don't think we've specifically highlighted this before, but for the past week our most frequent ANR of this kind has been when opening streams, and we have about 3x as many reports as users impacted.
We analyzed this bug in our morning bug triage meeting. Your OpenSL ES trace was very helpful. That could only occur after the audioserver had died.
We think what happens is that the audioserver dies for some reason. A watchdog will detect this and restart the audioserver. On some devices it may take a long time to restart, maybe 10 seconds or longer. If an audio call was made from the Android UI thread then the UI will be hung waiting for the audioserver to respond. In that case Android will issue an ANR and ask the user if they want to "Close app".
We will try to figure out why the audioserver is crashing. The app can protect itself by making all of its audio calls from another thread that is not the UI thread. It could use an AsyncTask. Or it might be better to implement a single threaded command queue. I will post some docs explaining this in more detail and add some examples to Oboe.
@GayleDaVid - Thanks for sending the additional information and statistics. We are tracking them internally in b/219958414
More logging and statistics has been added with ag/17414565 and ag/17492239
We analyzed this bug in our morning bug triage meeting. Your OpenSL ES trace was very helpful. That could only occur after the audioserver had died.
We think what happens is that the audioserver dies for some reason. A watchdog will detect this and restart the audioserver. On some devices it may take a long time to restart, maybe 10 seconds or longer. If an audio call was made from the Android UI thread then the UI will be hung waiting for the audioserver to respond. In that case Android will issue an ANR and ask the user if they want to "Close app".
We will try to figure out why the audioserver is crashing. The app can protect itself by making all of its audio calls from another thread that is not the UI thread. It could use an AsyncTask. Or it might be better to implement a single threaded command queue. I will post some docs explaining this in more detail and add some examples to Oboe.
I was wondering if there is a way for us to check if the audioserver is in a valid, running state before calling Oboe functions. My app is having big problems with these ANR's and going async is a major undertaking, to say the least.
@svenoaks - There are functions you can call but they will also stall and you will still need the Asynchronous calls. So you might as well just call Oboe from an AsyncTask.
This might be an ANR due to an audioserver crash. See example of background operation in https://github.com/google/oboe/pull/1669 Please try this technique.
We cannot move forward on this because we do not have enough information. If you can reproduce the ANR then please take a bugreport immediately after and attach it to a Buganizer bug on https://issuetracker.google.com Then add a link here.
We are actively seeking out all sources of ANRs and audioserver crashes. But any fixes will go into a future release. It is very unlikely that any fixes will go into Android 11 or even 12. So the only thing you can do as a workaround is to do all your Audio calls in an AsyncTask or a CommandQueue.
Closing now as infeasible.
Android version(s): 11 Android device(s): Google Pixel 5, Vivo 1920, Samsung Galaxy S20 5G, Samsung Galaxy A12, Redmi Note 8 Pro, Oppo A53s, OnePlus 6T, Redmi Note 10 Pro Max, Vivo V2039, Samsung Galaxy M21, Samsung Galaxy M31, vivo V2022 Oboe version: 1.6.1 App name used for testing: Smule
Short description When the app tries to open or stop an Audio Stream, the app hangs and creates ANR, below is a sample ANR report from a Google Pixel 5 Android 11. ` #00 pc 00000000000d6a94 /apex/com.android.runtime/lib64/bionic/libc.so (__ioctl+4)
00 pc 00000000000935c4 /apex/com.android.runtime/lib64/bionic/libc.so (ioctl+156)
00 pc 0000000000051a7c /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+296)
00 pc 0000000000052a68 /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel, int)+60)
00 pc 00000000000527d8 /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+184)
00 pc 000000000004b01c /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+188)
00 pc 000000000008fd58 /system/lib64/libaudioclient.so (android::BpAudioFlinger::releaseAudioSessionId(audio_session_t, int)+316)
00 pc 0000000000066e60 /system/lib64/libaudioclient.so (android::AudioSystem::releaseAudioSessionId(audio_session_t, int) (.cfi)+120)
00 pc 0000000000073a2c /system/lib64/libaudioclient.so (android::AudioTrack::~AudioTrack()+1796)
00 pc 0000000000074114 /system/lib64/libaudioclient.so (android::AudioTrack::~AudioTrack()+16)
00 pc 00000000000109f4 /system/lib64/libutils.so (android::RefBase::decStrong(void const*) const+112)
00 pc 00000000000284ec /system/lib64/libaaudio_internal.so (aaudio::AudioStreamTrack::~AudioStreamTrack()+180)
00 pc 000000000002853c /system/lib64/libaaudio_internal.so (aaudio::AudioStreamTrack::~AudioStreamTrack()+16)
00 pc 0000000000003b90 /system/lib64/libaaudio.so (AAudioStream_close.cfi+356)
00 pc 0000000000cf6734 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (oboe::AudioStreamAAudio::close()+180)
00 pc 0000000000cefeb0 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (oboe::FilterAudioStream::close()+28)
00 pc 0000000000c0cc70 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (Smule::Audio::SmuleOboe::StreamDelegate::stopStream()+116)
00 pc 0000000000c10260 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (Smule::Audio::SmuleOboe::OboeDuplexStream::stop()+164)
00 pc 00000000005dbb38 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (Smule::Audio::DuplexStreamOboeAudioWrapper::stop()+28)
00 pc 00000000004310c8 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (SingAudio::tearDown()+28)
00 pc 0000000000408f04 /data/app/~~LeAv2dkjEGmWXtsY22kr7w==/com.smule.singandroid-YZL656_GsYSRIoR_Gmi8FA==/lib/arm64/libsing.so (Java_com_smule_singandroid_audio_AudioInterface_stopAndShutdown+60)
at com.smule.singandroid.audio.AudioInterface.stopAndShutdown (AudioInterface.java) at com.smule.singandroid.audio.AudioController$6.doWork (AudioController.java:329) at com.smule.singandroid.audio.AudioSystemStateMachine$BasicWorker.doWork (AudioSystemStateMachine.java:544) at com.smule.singandroid.audio.AudioSystemStateMachine$BasicWorker.doWork (AudioSystemStateMachine.java:540) at com.smule.singandroid.audio.AudioSystemStateMachine$CommandWorker.execute (AudioSystemStateMachine.java:488) at com.smule.singandroid.audio.AudioSystemStateMachine$BasicWorker.execute (AudioSystemStateMachine.java:549) at com.smule.singandroid.audio.AudioSystemStateMachine.execute (AudioSystemStateMachine.java:570) at com.smule.singandroid.audio.AudioController.execute (AudioController.java:208) at com.smule.singandroid.audio.AudioController.stopAndShutdown (AudioController.java:326) at com.smule.singandroid.singflow.pre_sing.PreSingVideoSelectionFragment.suspendAudio (PreSingVideoSelectionFragment.java:2788) at com.smule.singandroid.singflow.pre_sing.PreSingVideoSelectionFragment.onPause (PreSingVideoSelectionFragment.java:1965) at androidx.fragment.app.Fragment.performPause (Fragment.java:3168) at androidx.fragment.app.FragmentStateManager.pause (FragmentStateManager.java:632) at androidx.fragment.app.FragmentStateManager.moveToExpectedState (FragmentStateManager.java:314) at androidx.fragment.app.FragmentStore.moveToExpectedState (FragmentStore.java:112) at androidx.fragment.app.FragmentManager.moveToState (FragmentManager.java:1647) at androidx.fragment.app.FragmentManager.dispatchStateChange (FragmentManager.java:3126) at androidx.fragment.app.FragmentManager.dispatchPause (FragmentManager.java:3088) at androidx.fragment.app.FragmentController.dispatchPause (FragmentController.java:284) at androidx.fragment.app.FragmentActivity.onPause (FragmentActivity.java:390) at com.smule.singandroid.BaseActivity.onPause (BaseActivity.java:304) at com.smule.singandroid.singflow.pre_sing.PreSingActivity.onPause (PreSingActivity.java:395) at android.app.Activity.performPause (Activity.java:8342) at android.app.Instrumentation.callActivityOnPause (Instrumentation.java:1511) at android.app.ActivityThread.performPauseActivityIfNeeded (ActivityThread.java:4856) at android.app.ActivityThread.performPauseActivity (ActivityThread.java:4812) at android.app.ActivityThread.handlePauseActivity (ActivityThread.java:4760) at android.app.servertransaction.PauseActivityItem.execute (PauseActivityItem.java:46) at android.app.servertransaction.TransactionExecutor.executeLifecycleState (TransactionExecutor.java:176) at android.app.servertransaction.TransactionExecutor.execute (TransactionExecutor.java:97) at android.app.ActivityThread$H.handleMessage (ActivityThread.java:2135) at android.os.Handler.dispatchMessage (Handler.java:106) at android.os.Looper.loop (Looper.java:236) at android.app.ActivityThread.main (ActivityThread.java:8059) at java.lang.reflect.Method.invoke (Native method) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:656) at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:967)`
Steps to reproduce
Expected behavior App should transition to next activity
Actual behavior App hangs (ANR experienced)
Any additional context
We were unable to reproduce this in house on various devices, hence unable to get tombstones. Google Play Console reports that these ANRs occur on Android 11 devices and so far zero reports on Android 12.
There has also been an issue reported in the issue tracker and can be found here. Some popular device chips