search

google / oboe

Oboe is a C++ library that makes it easy to build high-performance audio apps on Android.
Apache License 2.0
3.69k stars 563 forks source link

Higher latency due to bigger buffer sizes when using Oboe (compared to using OpenSLES) #1048

Closed ruurdadema closed 3 years ago

ruurdadema commented 3 years ago

When we upgraded our JUCE based application from JUCE 5 to JUCE 6 we noticed an increase in processing latency. This seems to be tied to the usage of Oboe which is being used by JUCE 6 by default. The previous version was using OpenSLES directly using the JUCE native abstraction.

With OpenSLES we are able to choose buffer sizes from 192 samples and up, but when using Oboe the smallest available buffersize is 962 samples. I confirmed this by comparing a JUCE 5 based DemoRunner with a JUCE 6 based DemoRunner.

When looking through the logs from our app I noticed a couple of things:

AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client, not shared buffer and transfer = TRANSFER_SYNC W/AudioStreamTrack: open() perfMode changed from 12 to 10 (10 = oboe::PerformanceMode::None)

I've read all the FAQs and guides to get the most optimal performance, but so far I have been unable to find the cause of this problem.

We're seeing this problem on Nokia 5 and Xiaomi Redmi 8.

What might be going on here?

2020-10-20 16:21:28.650 12860-12860/com.company.androidapp I/JUCE: Preparing Oboe stream with params:
    AAudio supported = 1
    API = Unspecified
    DeviceId = 0
    Direction = Output
    SharingMode = Exclusive
    ChannelCount = 2
    Format = Float
    SampleRate = 48000
    PerformanceMode = LowLatency
2020-10-20 16:21:28.650 12860-12860/com.company.androidapp I/OboeAudio: openStream() OUTPUT -------- OboeVersion1.4.2 --------
2020-10-20 16:21:28.650 12860-12860/com.company.androidapp D/AAudio: AAudioStreamBuilder_openStream() called ----------------------------------------
2020-10-20 16:21:28.650 12860-12860/com.company.androidapp D/AudioStreamBuilder: build() EXCLUSIVE sharing mode not supported. Use SHARED.
2020-10-20 16:21:28.651 12860-12860/com.company.androidapp I/AAudioStream: open() rate   = 48000, channels    = 2, format   = 0, sharing = SH, dir = OUTPUT
2020-10-20 16:21:28.651 12860-12860/com.company.androidapp I/AAudioStream: open() device = 0, sessionId   = 0, perfMode = 12, callback: OFF with frames = 0
2020-10-20 16:21:28.651 12860-12860/com.company.androidapp I/AAudioStream: open() usage  = 1, contentType = 2, inputPreset = 6
2020-10-20 16:21:28.651 12860-12860/com.company.androidapp D/AudioStreamTrack: open(), request notificationFrames = 0, frameCount = 0
2020-10-20 16:21:28.651 12860-12860/com.company.androidapp W/AudioTrack: AUDIO_OUTPUT_FLAG_FAST denied by client, not shared buffer and transfer = TRANSFER_SYNC
2020-10-20 16:21:28.656 12860-12860/com.company.androidapp W/AudioStreamTrack: open() flags changed from 0x00000104 to 0x00000100
2020-10-20 16:21:28.656 12860-12860/com.company.androidapp W/AudioStreamTrack: open() perfMode changed from 12 to 10
2020-10-20 16:21:28.656 12860-12860/com.company.androidapp D/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for (0x7d65bfc900) ----------------
2020-10-20 16:21:28.658 12860-12860/com.company.androidapp D/OboeAudio: AudioStreamAAudio.open() format=2, sampleRate=48000, capacity = 1924
2020-10-20 16:21:28.658 12860-12860/com.company.androidapp D/OboeAudio: AudioStreamAAudio.open: AAudioStream_Open() returned AAUDIO_OK
2020-10-20 16:21:28.658 12860-12860/com.company.androidapp I/JUCE: Building Oboe stream with result: OK
    Stream state = Open
2020-10-20 16:21:28.658 12860-12860/com.company.androidapp I/JUCE: Setting the bufferSizeInFrames to 192
2020-10-20 16:21:28.658 12860-12860/com.company.androidapp I/JUCE: Stream details:
    Uses AAudio = 1
    DeviceId = 3
    Direction = Output
    SharingMode = Shared
    ChannelCount = 2
    Format = Float
    SampleRate = 48000
    BufferSizeInFrames = 962
    BufferCapacityInFrames = 1924
    FramesPerBurst = 962
    FramesPerCallback = 0
    BytesPerFrame = 8
    BytesPerSample = 4
    PerformanceMode = None
philburk commented 3 years ago

From that log I see that JUCE is not using OpenSL ES.

The reason you are not getting a FAST track is because JUCE is not requesting a callback.

AAudioStream: open() device = 0, sessionId   = 0, perfMode = 12, callback: OFF with frames = 0

Can you request a callback?

ruurdadema commented 3 years ago

Many thanks Phil! This gave me enough hints to pinpoint the problem!

Whats happening is JUCE opens a temporary stream to verify a certain (ideal) buffer size. This temporary stream however is not given a callback. Because of this, as you mentioned, the underlying api comes back with a buffer size much higher than the requested ideal one.

After changing the JUCE code to pass a dummy audio callback to the temporary stream I'm now able to use low buffer sizes (in my case 192 frames is the lowest).

For cross reference: https://forum.juce.com/t/bigger-buffer-sizes-when-using-oboe-compared-to-opensles/42306/4?u=ruurdadema

philburk commented 3 years ago

Ah! That makes sense. Thank you so much for figuring it out.

I see that you reported this to the JUCE folks and they say they will fix it. That is awesome. This is one reason I love community open-source software.

I will close this.

Xavier-gl commented 3 years ago

Hello !! I also encountered this problem on my OnePlus 7T (android 10) using Oboe whereas the same code runs like a charm on Huawei P30 Lite (android 9).

I have set my stream as below:

oboe::AudioStreamBuilder builder;
builder.setFormat(oboe::AudioFormat::Float)
    ->setChannelConversionAllowed(true)
    ->setChannelCount(2)
    ->setFormatConversionAllowed(true)
    ->setSampleRate(44100)
    ->setSampleRateConversionQuality(oboe::SampleRateConversionQuality::High)
    ->setPerformanceMode(oboe::PerformanceMode::LowLatency)
    ->setSharingMode(oboe::SharingMode::Exclusive)
    ->setUsage(oboe::Usage::Game)
    ->setCallback(this);

auto result = builder.openStream(&stream);

First, I get in the Logcat "AAudioService: openStream(), could not open in EXCLUSIVE mode" and then "AUDIO_OUTPUT_FLAG_FAST denied by server" causing the current buffer to be way too large. The numFrames is 960 according to the spy put in the onAudioReady callback... vs 240 in the case of the Huawei which works fine.

What can I do to fix the problem ? Do you think the solution developed in this thread could help me ? Maybe the next release of Oboe will handle the problem.

Thank you very much in advance for your support :)

The logs read:

2020-11-07 16:44:52.185 14870-14870/? I/OboeAudio: openStream() OUTPUT -------- OboeVersion1.4.3 -------- 2020-11-07 16:44:52.186 14870-14870/? D/OboeAudio: AAudioLoader(): dlopen(libaaudio.so) returned 0xde3be43c3beebfe1 2020-11-07 16:44:52.186 14870-14870/? I/AAudio: AAudioStreamBuilder_openStream() called ---------------------------------------- 2020-11-07 16:44:52.186 14870-14870/? I/AudioStreamBuilder: rate = 0, channels = 2, format = 5, sharing = EX, dir = OUTPUT 2020-11-07 16:44:52.186 14870-14870/? I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0 2020-11-07 16:44:52.186 14870-14870/? I/AudioStreamBuilder: usage = 14, contentType = 2, inputPreset = 6, allowedCapturePolicy = 0 2020-11-07 16:44:52.188 1007-14417/? I/AudioPolicyManagerCustom: VR mode is 0, switch to primary output if request is for fast|raw 2020-11-07 16:44:52.188 1007-14417/? D/AudioPolicyManagerCustom: non offloadable effect is enabled, try with non direct output 2020-11-07 16:44:52.188 1007-14417/? D/AAudioServiceEndpointMMAP: open() mMapClient.uid = 10348, pid = 14870 => portHandle = 0 2020-11-07 16:44:52.188 1007-14417/? D/AAudioServiceEndpointMMAP: open() - openMmapStream() returned status -38 2020-11-07 16:44:52.188 1007-14417/? W/AAudioService: openStream(), could not open in EXCLUSIVE mode 2020-11-07 16:44:52.192 1007-14417/? I/AudioPolicyManagerCustom: VR mode is 0, switch to primary output if request is for fast|raw 2020-11-07 16:44:52.192 1007-14417/? D/AudioPolicyManagerCustom: non offloadable effect is enabled, try with non direct output 2020-11-07 16:44:52.192 1007-14417/? D/AAudioServiceEndpointMMAP: open() mMapClient.uid = 1041, pid = 1007 => portHandle = 0 2020-11-07 16:44:52.192 1007-14417/? D/AAudioServiceEndpointMMAP: open() - openMmapStream() returned status -38 2020-11-07 16:44:52.192 1007-14417/? W/AAudioService: openStream(), could not open in EXCLUSIVE mode 2020-11-07 16:44:52.193 14870-14870/? D/AudioStreamTrack: open(), request notificationFrames = -8, frameCount = 0 2020-11-07 16:44:52.193 14870-14870/? D/AudioTrack: set(): streamType -1, sampleRate 0, format 0x5, channelMask 0x3, frameCount 0, flags #104, notificationFrames -8, sessionId 0, transferType 1, uid -1, pid -1 2020-11-07 16:44:52.193 14870-14870/? I/AudioTrack: ull 2 ll! 2020-11-07 16:44:52.194 1007-14417/? D/AudioFlinger: setParameters(): io 0, keyvalue Use_Game_Ecns=off, calling pid 14870 calling uid 10348 2020-11-07 16:44:52.197 1007-14417/? I/AudioPolicyManagerCustom: VR mode is 0, switch to primary output if request is for fast|raw 2020-11-07 16:44:52.198 1007-14417/? I/AudioFlinger: AUDIO_OUTPUT_FLAGS denied by effect, session=0 old=0x4 new=0 2020-11-07 16:44:52.198 1007-14417/? D/AudioFlinger: Client defaulted notificationFrames to 960 for frameCount 1924 2020-11-07 16:44:52.198 1007-14417/? I/AudioFlinger: latencyMs:48, frameCount:1924. 2020-11-07 16:44:52.198 1007-14417/? D/AudioFlinger: the framecount(1920) should be the tims of 960 2020-11-07 16:44:52.198 1007-14417/? D/AudioFlinger: AudioOut_D createTrack_l() stmType 3,typeVolume 0.016687,mute 0,fc 1920,sId 217, flags 0 2020-11-07 16:44:52.200 1007-14417/? D/AF::TrackHandle: OpPlayAudio: track:67 usage:14 not muted 2020-11-07 16:44:52.201 14870-14870/? W/AudioTrack: createTrack_l(-1): AUDIO_OUTPUT_FLAG_FAST denied by server; frameCount 0 -> 1920 2020-11-07 16:44:52.201 14870-14870/? D/AudioTrack: Uid 10348 AudioTrack::setVolume left 1.000000 right 1.000000 2020-11-07 16:44:52.201 14870-14870/? W/AudioStreamTrack: open() sampleRate changed from 0 to 48000 2020-11-07 16:44:52.201 14870-14870/? W/AudioStreamTrack: open() flags changed from 0x00000104 to 0x00000000 2020-11-07 16:44:52.201 14870-14870/? W/AudioStreamTrack: open() perfMode changed from 12 to 10 2020-11-07 16:44:52.202 14870-14870/? I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#2 ---------------- 2020-11-07 16:44:52.202 14870-14870/? D/OboeAudio: AudioStreamAAudio.open() format=2, sampleRate=48000, capacity = 1920 2020-11-07 16:44:52.202 14870-14870/? D/OboeAudio: AudioStreamAAudio.open: AAudioStream_Open() returned AAUDIO_OK 2020-11-07 16:44:52.202 14870-14870/? I/OboeAudio: openStream() create a FilterAudioStream for data conversion. 2020-11-07 16:44:52.202 14870-14870/? I/OboeAudio: configure() flowgraph converts channels: 2 to 2, format: 2 to 2, rate: 44100 to 48000, qual = 4 2020-11-07 16:44:52.862 14870-14870/? D/AAudio: AAudioStream_requestStart(s#2) called -------------- 2020-11-07 16:44:52.862 14870-14870/? D/AudioTrack: ClientUid 10348 AudioTrack::start 2020-11-07 16:44:52.866 1007-1133/? D/APM_AudioPolicyManager: startOutput() output 13, stream 3, session 217, portId 35 2020-11-07 16:44:52.867 14870-14938/? E/SPY: onAudioReady... 2020-11-07 16:44:52.867 14870-14889/? D/AudioStreamLegacy: onAudioDeviceUpdate() devId 3 => 3 2020-11-07 16:44:52.867 14870-14938/? E/SPY: Audio: numFrames: 960 2020-11-07 16:44:52.867 14870-14870/? D/AAudio: AAudioStream_requestStart(s#2) returned 0 --------- 2020-11-07 16:44:52.867 14870-14938/? E/SPY: onAudioReady... 2020-11-07 16:44:52.867 14870-14938/? E/SPY: Audio: numFrames: 960

Xavier-gl commented 3 years ago

I have just tested the last oboe-master which has been updated 3 days ago and used a shared-pointer to hold the stream reference. The logs are cleaner. No more "could not open in EXCLUSIVE mode" but still "AUDIO_OUTPUT_FLAG_FAST denied by server" and in the end a huge numFrames leading to a major glitch in the game.

I'm struggling for days with that problem. What could I test to move forward ?

Thanks in advance for your support.

2020-11-07 18:36:55.936 18554-18554/com.id3ations.nativegame I/OboeAudio: openStream() OUTPUT -------- OboeVersion1.4.3 -------- 2020-11-07 18:36:55.936 18554-18554/com.id3ations.nativegame I/AAudio: AAudioStreamBuilder_openStream() called ---------------------------------------- 2020-11-07 18:36:55.936 18554-18554/com.id3ations.nativegame I/AudioStreamBuilder: rate = 0, channels = 2, format = 5, sharing = EX, dir = OUTPUT 2020-11-07 18:36:55.936 18554-18554/com.id3ations.nativegame I/AudioStreamBuilder: device = 0, sessionId = -1, perfMode = 12, callback: ON with frames = 0 2020-11-07 18:36:55.936 18554-18554/com.id3ations.nativegame I/AudioStreamBuilder: usage = 14, contentType = 2, inputPreset = 6, allowedCapturePolicy = 0 2020-11-07 18:36:55.939 18554-18554/com.id3ations.nativegame D/AudioStreamTrack: open(), request notificationFrames = -8, frameCount = 0 2020-11-07 18:36:55.940 18554-18554/com.id3ations.nativegame D/AudioTrack: set(): streamType -1, sampleRate 0, format 0x5, channelMask 0x3, frameCount 0, flags #104, notificationFrames -8, sessionId 0, transferType 1, uid -1, pid -1 2020-11-07 18:36:55.940 18554-18554/com.id3ations.nativegame I/AudioTrack: ull 2 ll! 2020-11-07 18:36:55.947 18554-18554/com.id3ations.nativegame W/AudioTrack: createTrack_l(-1): AUDIO_OUTPUT_FLAG_FAST denied by server; frameCount 0 -> 1920 2020-11-07 18:36:55.947 18554-18554/com.id3ations.nativegame D/AudioTrack: Uid 10348 AudioTrack::setVolume left 1.000000 right 1.000000 2020-11-07 18:36:55.947 18554-18554/com.id3ations.nativegame W/AudioStreamTrack: open() sampleRate changed from 0 to 48000 2020-11-07 18:36:55.947 18554-18554/com.id3ations.nativegame W/AudioStreamTrack: open() flags changed from 0x00000104 to 0x00000000 2020-11-07 18:36:55.948 18554-18554/com.id3ations.nativegame W/AudioStreamTrack: open() perfMode changed from 12 to 10 2020-11-07 18:36:55.948 18554-18554/com.id3ations.nativegame I/AAudio: AAudioStreamBuilder_openStream() returns 0 = AAUDIO_OK for s#2 ---------------- 2020-11-07 18:36:55.948 18554-18554/com.id3ations.nativegame I/OboeAudio: openStream() create a FilterAudioStream for data conversion. 2020-11-07 18:36:55.948 18554-18554/com.id3ations.nativegame I/OboeAudio: configure() flowgraph converts channels: 2 to 2, format: 2 to 2, rate: 44100 to 48000, cbsize: 0 to 0, qual = 4 2020-11-07 18:36:56.581 18554-18554/com.id3ations.nativegame D/AAudio: AAudioStream_requestStart(s#2) called -------------- 2020-11-07 18:36:56.581 18554-18554/com.id3ations.nativegame D/AudioTrack: ClientUid 10348 AudioTrack::start 2020-11-07 18:36:56.585 18554-18586/com.id3ations.nativegame D/AudioStreamLegacy: onAudioDeviceUpdate() devId 3 => 3 2020-11-07 18:36:56.585 18554-18554/com.id3ations.nativegame D/AAudio: AAudioStream_requestStart(s#2) returned 0 ---------