D/AudioFlinger(221): mixer(0xab804098) throttle end: throttle time(25)

[ands...@gmail.com]

Maybe a little off topic for this group but I know Google audio developers visits it so I'm asking my question here.

My app is using OpenSLES for audio and thus is using JNI/NDK.
 
Starting with Android 6, the audio glitches when the app is brougth to background by pushing the "home" button.
This doesn't happen with devices running Android 5.1.1 or 4.4.2.
I've checked everything in my playback engine and as far I can tell everything there works OK, no buffer problem etc.

The console logs as below and the line

D/AudioFlinger(221): mixer(0xab804098) throttle end: throttle time(25)

seems to be related to the audio glitch.

This line is never displayed when entering background on Android 4 or 5 (where there isn't any audio glitches).

Below is the complete log when entering background:

02-28 11:17:44.420: I/ActivityManager(602): START u0 {act=com.android.systemui.recents.SHOW_RECENTS flg=0x10804000 cmp=com.android.systemui/.recents.RecentsActivity} from uid 10020 on display 0
02-28 11:17:44.506: I/Keyboard.Facilitator(3507): onFinishInput()
02-28 11:17:44.559: I/MemoryTrimmer(26774): Trimming objects from memory, since app is in the background.
02-28 11:17:44.560: D/AudioFlinger(221): mixer(0xab804098) throttle end: throttle time(10)
02-28 11:17:44.637: I/art(602): Background partial concurrent mark sweep GC freed 51492(2MB) AllocSpace objects, 14(340KB) LOS objects, 29% free, 37MB/53MB, paused 1.159ms total 194.541ms
02-28 11:17:44.667: D/AudioFlinger(221): mixer(0xab804098) throttle end: throttle time(25)
02-28 11:17:44.731: D/AudioFlinger(221): mixer(0xab804098) throttle end: throttle time(10)

Any idea why this is happening?

[Glenn Kasten]

Is your audio running in a foreground service?  If not, it may be given background priority

which could cause glitching.

Other questions:

 - does this happen on all device models, or just some ones?

 - are you playing using PCM buffer queues or URI/file descriptor?

 - what sample rate and buffer size do you use?

[ands...@gmail.com]

Yes, I'm running in a foreground service but I wasn't clear enough. The glitch occurs only in the transition moment between foreground and background.

When the app is backgrounded it plays fine. There is no audio glitch when going "back" into foreground.

I'm using PCM buffer queues, two buffers with 2048 frames each. My app is an audio file player so I set up the buffer queue to use the sample rate of the file.

This is a Nexus 9 device and AudioManager.PROPERTY_OUTPUT_FRAMES_PER_BUFFER is 128 and I uses a buffer size of 2048 frames which is 16 * audioManager.PROPERTY_OUTPUT_FRAMES_PER_BUFFER.

I've tried to use more buffers and large buffer sizes but this doesn't change anything and I always have about 500 milliseconds of data in my internal ringbuffer so it's not a buffer underrun problem.

AudioManager.PROPERTY_OUTPUT_SAMPLE_RATE for this device is 48000 Hz and I just found out when I play files with sample rate 48000 or 96000 Hz, the problem disappears.

So it seems to be a sample rate conversion problem?

This is the only device I have with Android 6 (6.0.1) and I don't recall that I noticed this problem when it was running Android 5.

[Glenn Kasten]

You mentioned that when the sample rate is 48000 or 96000 there is no problem.

Which sample rate were you using that did have the problem?

(and yes, it is usually better to use the native sample rate when possible)

You will also usually get better performance with a buffer that is sized for the native frame count, rather than a larger buffer.

But it sound like in this case the only problem was the sample rate.

[ands...@gmail.com]

I tried to use AudioManager.PROPERTY_OUTPUT_FRAMES_PER_BUFFER, 128 for this device, but as expected this doesn't change anything.

Since my audio player doesn't need any low latency I would assume a larger buffer size would reduce the processor usage and as long as it's an even multiple of AudioManager.PROPERTY_OUTPUT_FRAMES_PER_BUFFER that should be OK.

The problem occurs for any sample rate lower than AudioManager.PROPERTY_OUTPUT_SAMPLE_RATE (48000 Hz), in fact I'm downsampling 96000 Hz myself to 48000 Hz so I can't any longer say what really happens for 96000 Hz audio.

I did a test with a 44100 Hz audio file and monitored the average number of audio frames that the OpenSLES callback is asking for.

When playing normally this always is (as expected) around 44100 audio frames per second, during the foreground to background transition it goes down for a brief moment to around 42-43000 frames per second, then stabilizes again to 44100.

This means the OpenSLES callback stops being called during foreground to background transition.

To me this explains the gap in audio. For some reason none audio threads interrupts the audio callback thread. To me this seems as a bug/problem somewhere in Android.

[ands...@gmail.com]

I made some further tests with the various Android devices I have at hand.

None of these devices produces any audio glitches during the transition from foreground to background when playing audio at a lower sample rate than what AudioManager.PROPERTY_OUTPUT_SAMPLE_RATE reports.

Nexus 4 Phone

Android 5.1.1

PROPERTY_OUTPUT_SAMPLE_RATE 48000 Hz

PROPERTY_OUTPUT_FRAMES_PER_BUFFER 240

Nexus 10 Tablet

Android 5.1.1

PROPERTY_OUTPUT_SAMPLE_RATE 44100 Hz

PROPERTY_OUTPUT_FRAMES_PER_BUFFER 256

Samsung Intel Tablet (GT-P5210)

Android 4.4.2

PROPERTY_OUTPUT_SAMPLE_RATE 48000 Hz

PROPERTY_OUTPUT_FRAMES_PER_BUFFER 1024

The problematic Nexus 9 device running Android 6.0.1 has a 64-bit processor but my app is a 32-bit build, could that be a problem?

[Glenn Kasten]

> Since my audio player doesn't need any low latency ...

Given that lower latency is not a requirement for you, there is really no need to use the OpenSL ES API;

it should be easier to work with the android.media.AudioTrack API.

But if you still want to use OpenSL ES APIs even though you don't care about lower latency,

I'd recommend at least disabling the "fast path" by adding some output effect interface and not using it.

This keeps the system from attempting to enable fast path though you don't want it.

[ands...@gmail.com]

My playback engine is written in C++ and is cross platform between Mac, Windows, iOS and Android and the only difference between the various platforms is the "Audio Output" class.

So I need to use OpenSL ES and besides this problem it works perfect.

I added "SL_IID_EQUALIZER" when I call CreateAudioPlayer() and the EQ works fine so I assume that would disable the "fast path" but it doesn't change anything, same audio glitch in the transition moment when moving from foreground to background.

I asked a customer with a Nexus 5 running Android 6.0.1 and the problem doesn't appear there. As far as I know that device has a 32-bit processor, my problematic Nexus 9 device has a 64-bit processor but my app is 32-bit, could that be the problem?

I could try to build my JNI stuff with APP_ABI := arm64-v8a but it's not simple since I also use NEON code that isn't 64-bit compatible.

Hm...

[Ian Ni-Lewis]

ART switches out the GC model when the app is backgrounded, which causes several locks to be held, but that shouldn't affect a pure C++ thread. Are you holding a mutex in the audio processing callback?

Ian

[ands...@gmail.com]

Thanks for chiming in.

I'm using a lock free ringbuffer that is filed in secondary thread. The only thing that happens in my audio callback is fast memcpy(), no locks/mutexes, no file I/O.

And the buffer isn't running dry when the audio glitch is happening.

As I explained before this problem only occurs on a Nexus 9 64-bit tablet running Android 6.0.1, no problems with devices running Android 5.1.1 or 4.4.2.

And no reports from customers which doesn't mean that it doesn't happens on their devices. The problem isn't a showstopper since it only ever appears in the transition moment from foreground to background,

else playback is super stable.

[ands...@gmail.com]

Ian Ni-Lewis: I Think your comment "ART switches out the GC model when the app is backgrounded, which causes several locks to be held," could possibly explain the problem but the problem is not with my app but depper down in the Android audio stack.

When playing files that have the same sample rate as the audio system reports - PROPERTY_OUTPUT_SAMPLE_RATE - for this device 48000 Hz,

then there is no audio glitch, only for files with another sample rate, for example 44100 Hz.

Here are two logs from the system when changing from foreground to background, first when playing a 48000 Hz file, second for a 44100 Hz file:

48000 Hz file:

04-16 09:55:33.045: I/ActivityManager(612): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0
04-16 09:55:33.108: I/GEL(27237): handleIntent(Intent { act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10600000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras) })
04-16 09:55:33.180: I/MicroDetectionWorker(27030): Micro detection mode: [mDetectionMode: [1]].
04-16 09:55:33.196: W/LocationOracle(27030): Best location was null
04-16 09:55:33.208: I/MicroRecognitionRunner(27030): Starting detection.
04-16 09:55:33.213: I/MicrophoneInputStream(27030): mic_starting com.google.android.apps.gsa.speech.audio.ah@86a198a
04-16 09:55:33.219: I/SoundTriggerHwService::Module(219): void android::SoundTriggerHwService::Module::onCallbackEvent(const android::sp<android::SoundTriggerHwService::CallbackEvent>&) mClient == 0

04-16 09:55:33.226: I/AudioFlinger(219): AudioFlinger's thread 0xab3bce10 ready to run
04-16 09:55:33.227: I/MicrophoneInputStream(27030): mic_started com.google.android.apps.gsa.speech.audio.ah@86a198a
04-16 09:55:33.296: E/LocationReceiver(27030): Received bad location: null
04-16 09:55:33.313: I/art(612): Background partial concurrent mark sweep GC freed 14085(723KB) AllocSpace objects, 7(240KB) LOS objects, 33% free, 29MB/43MB, paused 1.932ms total 240.884ms

04-16 09:55:33.314: I/Keyboard.Facilitator(1141): onFinishInput()
04-16 09:55:33.338: W/LocationOracle(27030): Best location was null
04-16 09:55:33.346: W/LocationOracle(27030): Best location was null
04-16 09:55:33.416: I/MicroDetectionWorker(27030): onReady 

44100 Hz file:

04-16 09:49:49.952: I/ActivityManager(612): START u0 {act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10200000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras)} from uid 1000 on display 0
04-16 09:49:50.011: I/GEL(27237): handleIntent(Intent { act=android.intent.action.MAIN cat=[android.intent.category.HOME] flg=0x10600000 cmp=com.google.android.googlequicksearchbox/com.google.android.launcher.GEL (has extras) })
04-16 09:49:50.085: I/MicroDetectionWorker(27030): Micro detection mode: [mDetectionMode: [1]].

04-16 09:49:50.096: I/Keyboard.Facilitator(1141): onFinishInput()
04-16 09:49:50.098: W/LocationOracle(27030): Best location was null

04-16 09:49:50.134: D/AudioFlinger(219): mixer(0xab24b0a8) throttle end: throttle time(20)
04-16 09:49:50.134: I/MicroRecognitionRunner(27030): Starting detection.
04-16 09:49:50.138: I/MicrophoneInputStream(27030): mic_starting com.google.android.apps.gsa.speech.audio.ah@d9d878f
04-16 09:49:50.147: I/SoundTriggerHwService::Module(219): void android::SoundTriggerHwService::Module::onCallbackEvent(const android::sp<android::SoundTriggerHwService::CallbackEvent>&) mClient == 0

04-16 09:49:50.154: I/AudioFlinger(219): AudioFlinger's thread 0xab3bce10 ready to run
04-16 09:49:50.156: I/MicrophoneInputStream(27030): mic_started com.google.android.apps.gsa.speech.audio.ah@d9d878f
04-16 09:49:50.200: E/LocationReceiver(27030): Received bad location: null
04-16 09:49:50.213: W/LocationOracle(27030): Best location was null
04-16 09:49:50.215: I/art(612): Background partial concurrent mark sweep GC freed 8117(435KB) AllocSpace objects, 1(20KB) LOS objects, 33% free, 29MB/43MB, paused 1.087ms total 235.323ms
04-16 09:49:50.232: W/LocationOracle(27030): Best location was null

04-16 09:49:50.240: D/AudioFlinger(219): mixer(0xab24b0a8) throttle end: throttle time(20)
04-16 09:49:50.304: D/AudioFlinger(219): mixer(0xab24b0a8) throttle end: throttle time(10)

04-16 09:49:50.346: I/MicroDetectionWorker(27030): onReady
04-16 09:49:55.899: I/art(612): Background partial concurrent mark sweep GC freed 10403(503KB) AllocSpace objects, 2(60KB) LOS objects, 33% free, 29MB/43MB, paused 1.216ms total 136.761ms
04-16 09:49:56.534: D/AudioFlinger(219): mixer(0xab24b0a8) throttle end: throttle time(10)