iOS 8 - audio dropout when using openGL renderer

MacOSX and iOS
1

I've been getting this nasty audio dropout on iOS 8, it doesn't reproduce for me on iOS 7 at all. 

It happens every time I run my app. At approximately 1 minute into running, audio will dropout. This happens only once, then for the rest of the time I'm using the app, it doesn't reoccur! But it is completely consistent, every time I run the app it drops out, always between :50 and 1:10. It's totally maddening. 

I've been digging with Instruments trying to find something, but no luck. I promise I'm not doing anything obviously stupid like locking within the callback or allocating on the heap etc. The only thing happening during the dropout is a synth voice playing back and OpenGL rendering, there's no obvious (to me) event that would trigger the dropout, and no big CPU spikes etc. 

The only way I can get it to stop happening is to disable continuous repainting of the OpenGL context. I've tried completely bypassing everything I'm doing OpenGL-wise, and it doesn't prevent the dropout. So it seems to be something that Juce is doing (or maybe the OS is doing). 

Can anyone suggest what might be going wrong here? I'm about at the end of my rope on this one!

-Nick

2

Wow, sounds like a nasty one! You could try adding some timing code around your audio rendering functionality - e.g. in Tracktion we use a glitch-detector macro that is a locally scoped object which measures the time between its constructor and destructor, and asserts if it takes more than a fixed length of time. We pepper the code with these, so that if something blocks, we can track down roughly the area where it happened.

3

Ok, i took that advice and timed the synthesiser's renderNextBlock(). It normally only takes a couple ms to do its thing, but at around the 1 minute mark it jumps. So i set it up to hit a breakpoint when it does that, but I don't see anything that's obviously wrong. Do you mind taking a glance at the stack trace? Maybe you'll see something I don't. 

-n
 

Juce Message Thread (1)Queue : com.apple.main-thread (serial)

#0 0x34cd24f0 in mach_msg_trap ()

#1 0x34cd22e8 in mach_msg ()

#2 0x26bbc93a in __CFRunLoopServiceMachPort ()

#3 0x26bbaee0 in __CFRunLoopRun ()

#4 0x26b09210 in CFRunLoopRunSpecific ()

#5 0x26b09022 in CFRunLoopRunInMode ()

#6 0x2ded90a8 in GSEventRunModal ()

#7 0x2a1151d0 in UIApplicationMain ()

#8 0x002aa052 in juce::juce_iOSMain(int, char const**) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_gui_basics/native/juce_ios_Windowing.mm:95

#9 0x001889b4 in juce::JUCEApplicationBase::main(int, char const**) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_events/messages/juce_ApplicationBase.cpp:216

#10 0x000ad41a in main at /Users/nhdika/Code/photophore/Source/Main.cpp:168

 

Thread 5Queue : com.apple.libdispatch-manager (serial)

#0 0x34cd22a0 in kevent64 ()

#1 0x00e41678 in _dispatch_mgr_invoke ()

#2 0x00e3649a in _dispatch_mgr_thread ()

 

gputools.smt_poll.0x15d19f80 (6)

#0 0x34ce619c in __semwait_signal ()

#1 0x34c45a70 in nanosleep ()

#2 0x34c459c0 in usleep ()

#3 0x00e7eff8 in smt_poll_thread_entry(void*) ()

#4 0x34d62e92 in _pthread_body ()

#5 0x34d62e06 in _pthread_start ()

 

AVAudioSession Notify Thread (9)

#0 0x34cd24f0 in mach_msg_trap ()

#1 0x34cd22e8 in mach_msg ()

#2 0x26bbc93a in __CFRunLoopServiceMachPort ()

#3 0x26bbaee0 in __CFRunLoopRun ()

#4 0x26b09210 in CFRunLoopRunSpecific ()

#5 0x26b09022 in CFRunLoopRunInMode ()

#6 0x258133ee in GenericRunLoopThread::Entry(void*) ()

#7 0x2580590a in CAPThread::Entry(CAPThread*) ()

#8 0x34d62e92 in _pthread_body ()

#9 0x34d62e06 in _pthread_start ()

 

com.apple.CFSocket.private (10)

#0 0x34ce608c in __select ()

#1 0x26bc1106 in __CFSocketManager ()

#2 0x34d62e92 in _pthread_body ()

#3 0x34d62e06 in _pthread_start ()

 

us.audiob.listener (11)

#0 0x34cd24f0 in mach_msg_trap ()

#1 0x34cd22e8 in mach_msg ()

#2 0x26bbc93a in __CFRunLoopServiceMachPort ()

#3 0x26bbaee0 in __CFRunLoopRun ()

#4 0x26b09210 in CFRunLoopRunSpecific ()

#5 0x26b51e7a in CFRunLoopRun ()

#6 0x0034341e in -[DBLocalEndpointListenerThread main] ()

#7 0x27905b5a in __NSThread__main__ ()

#8 0x34d62e92 in _pthread_body ()

#9 0x34d62e06 in _pthread_start ()

 

AURemoteIO::IOThread (12)

#0 0x000e2d16 in Synth::renderNextBlock(juce::AudioSampleBuffer&, juce::MidiBuffer const&, int, int) at /Users/nhdika/Code/photophore/Source/Synth.cpp:230

#1 0x000e1262 in SynthAudioSource::getNextAudioBlock(juce::AudioSourceChannelInfo const&) at /Users/nhdika/Code/photophore/Source/SynthAudioSource.cpp:55

#2 0x0010df4c in juce::AudioSourcePlayer::audioDeviceIOCallback(float const**, int, float**, int, int) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_audio_devices/sources/juce_AudioSourcePlayer.cpp:142

#3 0x0010afec in juce::AudioDeviceManager::audioDeviceIOCallbackInt(float const**, int, float**, int, int) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_audio_devices/audio_io/juce_AudioDeviceManager.cpp:727

#4 0x0011a604 in juce::AudioDeviceManager::CallbackHandler::audioDeviceIOCallback(float const**, int, float**, int, int) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_audio_devices/audio_io/juce_AudioDeviceManager.cpp:56

#5 0x00110256 in juce::iOSAudioIODevice::process(unsigned long*, AudioTimeStamp const*, unsigned long, AudioBufferList*) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_audio_devices/native/juce_ios_Audio.mm:573

#6 0x001133a6 in juce::iOSAudioIODevice::processStatic(void*, unsigned long*, AudioTimeStamp const*, unsigned long, unsigned long, AudioBufferList*) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_audio_devices/native/juce_ios_Audio.h:129

#7 0x26384118 in AUInputElement::PullInput(unsigned long&, AudioTimeStamp const&, unsigned long, unsigned long) ()

#8 0x2637caea in AUInputFormatConverter2::InputProc(OpaqueAudioConverter*, unsigned long*, AudioBufferList*, AudioStreamPacketDescription**, void*) ()

#9 0x262abbe4 in AudioConverterChain::CallInputProc(unsigned long) ()

#10 0x262ab954 in AudioConverterChain::FillBufferFromInputProc(unsigned long*, CABufferList*) ()

#11 0x262ab8f2 in BufferedAudioConverter::GetInputBytes(unsigned long, unsigned long&, CABufferList const*&) ()

#12 0x262ab7fc in CBRConverter::RenderOutput(CABufferList*, unsigned long, unsigned long&, AudioStreamPacketDescription*) ()

#13 0x262ab6a2 in BufferedAudioConverter::FillBuffer(unsigned long&, AudioBufferList&, AudioStreamPacketDescription*) ()

#14 0x262ab776 in AudioConverterChain::RenderOutput(CABufferList*, unsigned long, unsigned long&, AudioStreamPacketDescription*) ()

#15 0x262ab6a2 in BufferedAudioConverter::FillBuffer(unsigned long&, AudioBufferList&, AudioStreamPacketDescription*) ()

#16 0x262b9188 in AudioConverterFillComplexBuffer ()

#17 0x2637c9ca in AUInputFormatConverter2::PullAndConvertInput(AudioTimeStamp const&, unsigned long&, AudioBufferList&, AudioStreamPacketDescription*, bool&) ()

#18 0x2637c534 in AUConverterBase::RenderBus(unsigned long&, AudioTimeStamp const&, unsigned long, unsigned long) ()

#19 0x262ad9d6 in AUBase::DoRenderBus(unsigned long&, AudioTimeStamp const&, unsigned long, AUOutputElement*, unsigned long, AudioBufferList&) ()

#20 0x262ad86a in AUBase::DoRender(unsigned long&, AudioTimeStamp const&, unsigned long, unsigned long, AudioBufferList&) ()

#21 0x2637169c in AURemoteIO::PerformIO(unsigned long, unsigned int, unsigned int, AudioTimeStamp const&, AudioTimeStamp const&, AudioBufferList const*, AudioBufferList*, int&) ()

#22 0x26372766 in AURIOCallbackReceiver_PerformIO ()

#23 0x2636a972 in _XPerformIO ()

#24 0x262cc286 in mshMIGPerform ()

#25 0x263444d0 in MSHMIGDispatchMessage ()

#26 0x263719ac in AURemoteIO::IOThread::Run() ()

#27 0x26375098 in AURemoteIO::IOThread::Entry(void*) ()

#28 0x262a99e4 in CAPThread::Entry(CAPThread*) ()

#29 0x34d62e92 in _pthread_body ()

#30 0x34d62e06 in _pthread_start ()

 

Thread 13

#0 0x34cd24f0 in mach_msg_trap ()

#1 0x34cd22e8 in mach_msg ()

#2 0x27306cca in XServerMachPort::ReceiveMessage(int&, void*, int&) ()

#3 0x27321294 in MIDIProcess::RunMIDIInThread() ()

#4 0x27307e4a in XThread::RunHelper(void*) ()

#5 0x273078a2 in CAPThread::Entry(CAPThread*) ()

#6 0x34d62e92 in _pthread_body ()

#7 0x34d62e06 in _pthread_start ()

 

OpenGL Rendering (14)

#0 0x34ce619c in __semwait_signal ()

#1 0x34c45a70 in nanosleep ()

#2 0x34c459c0 in usleep ()

#3 0x29be4e52 in native_window_begin_iosurface(_EAGLNativeWindowObject*) ()

#4 0x295cc450 in gliGetNewIOSurfaceES ()

#5 0x2557d388 in sgxResolveDeferredFramebufferOffset ()

#6 0x25572a60 in sgxPatchDeferredFramebufferOffsets ()

#7 0x2557871c in sgxEndRender ()

#8 0x255703aa in glrFlushContextToken ()

#9 0x295cc388 in gliPresentViewES_Exec ()

#10 0x295cc2ba in gliPresentViewES ()

#11 0x295d7064 in -[EAGLContext presentRenderbuffer:] ()

#12 0x00da5fc6 in EAGLContext_presentRenderbuffer(EAGLContext*, objc_selector*, unsigned int) ()

#13 0x00311afe in juce::OpenGLContext::NativeContext::swapBuffers() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/native/juce_OpenGL_ios.h:158

#14 0x003100d4 in juce::OpenGLContext::swapBuffers() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:745

#15 0x003178ac in juce::OpenGLContext::CachedImage::renderFrame() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:191

#16 0x0031747c in juce::OpenGLContext::CachedImage::run() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:359

#17 0x0031751c in non-virtual thunk to juce::OpenGLContext::CachedImage::run() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:366

#18 0x0014ca9c in juce::Thread::threadEntryPoint() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:101

#19 0x0014cdbe in juce::juce_threadEntryPoint(void*) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:113

#20 0x0015a1f2 in threadEntryProc at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:850

#21 0x34d62e92 in _pthread_body ()

#22 0x34d62e06 in _pthread_start ()

 

Juce Timer (15)

#0 0x34ce5b38 in __psynch_cvwait ()

#1 0x34d623f8 in _pthread_cond_wait ()

#2 0x34d6331c in pthread_cond_timedwait ()

#3 0x0014bd08 in juce::WaitableEvent::wait(int) const at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:97

#4 0x0014d3c4 in juce::Thread::wait(int) const at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:246

#5 0x001904fa in juce::Timer::TimerThread::run() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_events/timers/juce_Timer.cpp:106

#6 0x0014ca9c in juce::Thread::threadEntryPoint() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:101

#7 0x0014cdbe in juce::juce_threadEntryPoint(void*) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:113

#8 0x0015a1f2 in threadEntryProc at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:850

#9 0x34d62e92 in _pthread_body ()

#10 0x34d62e06 in _pthread_start ()

 

Thread 16

#0 0x34cd2654 in mach_wait_until ()

#1 0x0016dfaa in juce::HighResolutionTimer::Pimpl::Clock::wait() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:1242

#2 0x0016dea0 in juce::HighResolutionTimer::Pimpl::timerThread() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:1214

#3 0x0016ddf2 in juce::HighResolutionTimer::Pimpl::timerThread(void*) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:1203

#4 0x34d62e92 in _pthread_body ()

#5 0x34d62e06 in _pthread_start ()

 

4

Well, it looks like something in your synth rendering that's glitching. Add more finely-grained tests to track it down.

5

That's the most obvious explanation. However I did a ton of testing of the synth code and it still doesn't add up.  Basically, I can bypass all of my synth rendering code entirely and just fill the buffer with noise and I still get the dropout. I just have to be using a good amount of CPU (like above 60%, which isn't hard since this is iPad) and I get a 100+ millisecond dropout between :50 and 1:10. There are no CPU spikes or memory allocations before the dropout or anything like that, everything seems steady. It's like there's something else blocking the audio thread but hell if i know what it is. 

6

Maybe you run out of physical memory and it's a virtual memory paging glitch. (Hard to measure that though)

7

Memory usage stays the same, and it's not excessive (about 20mb). iOS only sort of uses virtual memory. iOS doesn't have a backing store, so nothing should be written out to virtual memory. However from what I understand, iOS can choose to keep read-only data on disk instead of loading it into memory. So maybe there's a bottleneck there that I don't know about. But according to Apple "Writable data is never removed from memory by the operating system."

The only way for me to avoid the glitch is to turn off setContinuousRepainting(). So maybe it's some weirdness with OpenGL changes in iOS8 (again). 

Here's where the OpenGL rendering thread is when the dropout happens (always in the same place):


OpenGL Rendering (13)

#0    0x34ce619c in __semwait_signal ()
#1    0x34c45a70 in nanosleep ()
#2    0x34c459c0 in usleep ()
#3    0x29be4e52 in native_window_begin_iosurface(_EAGLNativeWindowObject*) ()
#4    0x295cc450 in gliGetNewIOSurfaceES ()
#5    0x2557d388 in sgxResolveDeferredFramebufferOffset ()
#6    0x25572a60 in sgxPatchDeferredFramebufferOffsets ()
#7    0x2557871c in sgxEndRender ()
#8    0x255703aa in glrFlushContextToken ()
#9    0x295cc388 in gliPresentViewES_Exec ()
#10    0x295cc2ba in gliPresentViewES ()
#11    0x295d7064 in -[EAGLContext presentRenderbuffer:] ()
#12    0x00d32fc6 in EAGLContext_presentRenderbuffer(EAGLContext*, objc_selector*, unsigned int) ()
#13    0x0029dab6 in juce::OpenGLContext::NativeContext::swapBuffers() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/native/juce_OpenGL_ios.h:158
#14    0x0029c08c in juce::OpenGLContext::swapBuffers() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:745
#15    0x002a3864 in juce::OpenGLContext::CachedImage::renderFrame() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:191
#16    0x002a3434 in juce::OpenGLContext::CachedImage::run() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:359
#17    0x002a34d4 in non-virtual thunk to juce::OpenGLContext::CachedImage::run() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_opengl/opengl/juce_OpenGLContext.cpp:366
#18    0x000d8924 in juce::Thread::threadEntryPoint() at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:101
#19    0x000d8c46 in juce::juce_threadEntryPoint(void*) at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/threads/juce_Thread.cpp:113
#20    0x000e6092 in threadEntryProc at /Users/nhdika/Code/photophore/JuceLibraryCode/modules/juce_core/native/juce_posix_SharedCode.h:850
#21    0x34d62e92 in _pthread_body ()
#22    0x34d62e06 in _pthread_start ()

 

 

8

Ah, well if it's deep inside the system's GL library, I'm afraid I really don't have anything to suggest. There may be a handful of engineers at Apple who could give more insight about that stack trace, but it's beyond me!

9

Well, I'm going to try apple developer support on this one. I also know an ex-Apple engineer/software architect who has OpenGL experience, so maybe he'll have some insight. 

10

Well, I guess Apple dev support won't let you use a support ticket unless your product is already on the store. o_O

I've now made a new little test project from scratch with Juce, and the problem repros there, so at least I feel a bit vindicated that I haven't done something really dumb. I've also learned the bug seems to change behavior depending on what thread OpenGL repainting is triggered from.

If I turn continuous repainting off and manually call triggerRepaint(), I get different results depending on whether I use a normal Timer or a HighResolutionTimer. If I use a normal timer, it takes about 3:20 before I get a dropout. Using a Hi Res timer, it takes about 50 seconds. In the first case, the renderbuffer gets presented to the native context about 12000 times. In the second case about 3000 times. 

So my rather amateurish guess is that this is some threading related issue.

11

The GL rendering will allocate and free textures - perhaps internally the GPU memory is getting fragmented by this and after a certain number of iterations it has to stop and de-fragment or garbage collect it internally..

12

i was thinking along those lines until this recent test. If that were the case, why would the glitch happen at different times when rendering is triggered from different threads? I would expect the glitch to be related to the number of swaps in that case. 

When using a normal timer (at 60fps), rendering happens 12000 times before a glitch. When using a high res timer (at 60fps), or using continous repainting, it happens after only rendering 3000 times. 

13

Ah, I see. Sorry, really no idea how we can psychically guess what iOS is doing in there!

14

Well I was pretty convinced this was an OpenGL problem, but it's actually more general than that. OpenGL rendering will cause the dropout to happen sooner, however it's not the only way to make it happen. 

Using a High Res Timer in the project (with no OpenGL renderer or context) will cause the same dropout, it just happens later (3:00 instead of 1:00). You don't have to do anything in the timer callback in order to make the dropout happen. 

So I guess this is some thread-related problem? 

15

Bizarre. Is it a java garbage-collection pause?

16

well, this is iOS, so probably not right ??

17

(Sorry! Answering multiple questions at once and getting the context confused in my head!)

Well, I'm out of ideas!

18

The only clue I have is that changing the rate of the High Resolution Timer causes the dropout to happen at a different time. Like I said, there's nothing happening in the timer callback, so I'm pretty sure this is either Juce or the OS. Are you sure you're not doing something in your thread code that could block the audio callback somewhere? 

I have a little test project I can send if you want to take a look. This won't repro in the simulator, but at this point I'll fedex you an iPad with a return label if it will help. 

19

Problem reproduces when using a normal timer as well (takes slightly longer to happen). In both cases if I never start the timer the dropout never happens. 

20

A normal timer does nothing other than launch a thread and send messages for each timer event. Unless the OS is doing some kind of thread management, I've really no idea.