mixerResume NOT work probably on Android with Cocos2d-x 3.3 in some extreme case

We area testing our game that using fmod studio API recently.We found that in some cases, mixerResume not resume correctly and may even cause ANR(Application Not Responding).

System:MIUI 7 (Android 6.0.1)
Hardware: XIAOMI 3W
Detail:I wrote some code like API’s example does.In activity static block load fmod and fmodstudio library. do org.fmod.FMOD.init in activity’s onCreate event.Call mixerSuspend on onPause event and mixerResume on onResume event. Everything work’s fine, music can be pause and resume correctly when I switch application to background and foreground, except following.

If I first install application, and open it in the install complete dialog(NOT from launcher, that’s important), and then I switch application to background, and from background to foreground, system will create a new activity and then call onCreate->onResume, fmod’s Init function will call again in state of mixerSuspend and call mixerResume in onResume event.Than background music will not resume any more, if I switch to background again, the application will ANR.

I first thought maybe I call org.fmod.init, while I suspend the mixer, cause document said any API call during mixerSuspend may cause deadlock.And then I tried add org.fmod.FMOD.checkInit check to init, it doesn’t work.Even I comment the init code, things still work like that(I was quite surprise that music still can play even I don’t call org.fmod.FMOD.init).I try to comment the mixerSuspend call and Let the music play background, application work fine, in activity recreated(as I mention before).So I am quite sure it’s mixerSuspend and mixerResume’s problem.

Further, I enable the debug log by calling “FMOD::Debug_Initialize(0xFFFFFFF4);”, comparing to normal case(no recreated activity), mixer thread is destroy and create correctly, but after thread was created, no more File::read log while normal case does.I checked log carefully, and no api was call with interface call log and fmod’s owned log.I can’t do any further analysis without fmod api source code, so I have to put the question here.
Is there any thing I was missed or doing wrong? Sorry for I can’t put all codes here NDA.But I could paste some code fragment here if you need.

Here is some log fragment:

**********************NOT resume normal case ********************

02-29 18:55:03.319 21612 21612 D Cocos2dxActivity: onResume()

02-29 18:55:03.320 21612 21786 D cocos2d-x debug info: [LUA-print] onEnterForeground

02-29 18:55:03.320 21612 21786 D cocos2d-x debug info: [LUA-print] [INFO] SoundMgr::handleEnterForeground

02-29 18:55:03.320 21612 21786 D cocos2d-x debug info: Pause

02-29 18:55:03.320 21612 21786 I fmod    : ../../src/fmod_systemi.cpp(3625)                             : TID -1656166096 :    18320 ms +2178 : [LOG] SystemI::mixerResume                     : Resuming output.

02-29 18:55:03.321 21612 21786 I fmod    : AudioDevice::init : Min buffer size: 7744 bytes

02-29 18:55:03.321 21612 21786 I fmod    : AudioDevice::init : Actual buffer size: 16384 bytes

02-29 18:55:03.327 21612 21794 I EnvironmentSDK: http get:http://optsdk.gameyw.netease.com/g41

02-29 18:55:03.328 21612 21796 I EnvironmentSDK: download data file start

02-29 18:55:03.331   275  2267 V EffectDiracSound: DiracSound_command() start, cmdCode=9

02-29 18:55:03.331   275  2267 V EffectDiracSound: DiracSound_Command EFFECT_CMD_SET_DEVICE: 0x00000002

02-29 18:55:03.331   275  2267 D audio_hw_primary: out_set_parameters: enter: usecase(0: deep-buffer-playback) kvpairs: routing=2

02-29 18:55:03.331   275  2267 I msm8974_platform: platform_get_output_snd_device: enter: output devices(0x2)

02-29 18:55:03.331   275  2267 I msm8974_platform: platform_get_output_snd_device: exit: snd_device(speaker)

02-29 18:55:03.331   275  2267 D audio_hw_extn: audio_extn_set_anc_parameters: anc_enabled:0

02-29 18:55:03.331   275  2267 V audio_hw_primary: out_set_parameters: exit: code(0)

02-29 18:55:03.341   275  2267 D audio_hw_primary: out_set_parameters: enter: usecase(0: deep-buffer-playback) kvpairs: fm_volume=0.5308851600

02-29 18:55:03.341   275  2267 D audio_hw_extn: audio_extn_set_anc_parameters: anc_enabled:0

02-29 18:55:03.341   275  2267 D audio_hw_fm: audio_extn_fm_set_parameters: set_fm_volume usecase

02-29 18:55:03.341   275  2267 D audio_hw_fm: fm_set_volume: (0.530885)

02-29 18:55:03.341   275  2267 V audio_hw_primary: out_set_parameters: exit: code(0)

02-29 18:55:03.346  1781  3581 I Timeline: Timeline: App_transition_ready time:11387839

02-29 18:55:03.349  1781  3581 I Timeline: Timeline: App_transition_ready time:11387842

02-29 18:55:03.351   275  2267 D audio_hw_primary: out_set_parameters: enter: usecase(0: deep-buffer-playback) kvpairs: fm_volume=0.5308851600

02-29 18:55:03.351   275  2267 D audio_hw_extn: audio_extn_set_anc_parameters: anc_enabled:0

02-29 18:55:03.351   275  2267 D audio_hw_fm: audio_extn_fm_set_parameters: set_fm_volume usecase

02-29 18:55:03.351   275  2267 D audio_hw_fm: fm_set_volume: (0.530885)

02-29 18:55:03.351   275  2267 V audio_hw_primary: out_set_parameters: exit: code(0)

02-29 18:55:03.352   275  4111 E AudioFlinger: open /proc/21612/cmdline error

02-29 18:55:03.352   275  4111 I AudioFlinger: setAppName(), name=[], active=[1]

02-29 18:55:03.340  4111  4111 W Binder_3: type=1400 audit(0.0:1097): avc: denied { search } for name="21612" dev="proc" ino=207902 scontext=u:r:mediaserver:s0 tcontext=u:r:untrusted_app:s0:c512,c768 tclass=dir permissive=0

02-29 18:55:03.353   275  4111 V EffectDiracSound: DiracSound_command() start, cmdCode=23

02-29 18:55:03.353   275  4111 V EffectDiracSound: DiracSound_Command EFFECT_CMD_SET_APP_NAME: stream=3, name=+

02-29 18:55:03.353 21612 21786 I fmod    : ../../src/fmod_thread.cpp(162)                               : TID -1656166096 :    18353 ms   +33 : [LOG] Thread::initThread                       : Initializing FMOD mixer thread.  priority 3

02-29 18:55:03.353 21612 21786 I fmod    : ../../src/fmod_thread.cpp(163)                               : TID -1656166096 :    18353 ms    +0 : [LOG] Thread::initThread                       : - Stacksize 49152.  Stack pointer 0x0 : usesemaphore = 0 : sleeptime = 0

02-29 18:55:03.353 21612 21786 I fmod    : ../android/src/fmod_os_misc.cpp(863)                         : TID -1656166096 :    18353 ms    +0 : [LOG] MemPool::alloc                           :     12 bytes (0x9dde3468) (alloc 5684)

02-29 18:55:03.353 21612 21786 I fmod    : ../android/src/fmod_os_misc.cpp(553)                         : TID -1656166096 :    18353 ms    +0 : [LOG] MemPool::alloc                           :    276 bytes (0xaed61008) (alloc 5685)

02-29 18:55:03.354 21612 21798 I fmod    : ../android/src/fmod_os_misc.cpp(486)                         : TID -1630709456 :    18354 ms    +1 : [LOG] MemPool::free                            :    276 bytes (0xaed61008)

02-29 18:55:03.354 21612 21798 I fmod    : ../../src/fmod_thread.cpp(46)                                : TID -1630709456 :    18354 ms    +0 : [LOG] Thread::callback                         : * FMOD mixer thread started

02-29 18:55:03.354 21612 21786 D cocos2d-x debug info: NOTE : FMOD_SYSTEM_CALLBACK_THREADCREATED occured.

02-29 18:55:03.354 21612 21786 D cocos2d-x debug info: 

02-29 18:55:03.354 21612 21786 D cocos2d-x debug info: Thread ID = -1630709456

02-29 18:55:03.354 21612 21786 D cocos2d-x debug info: 

02-29 18:55:03.354 21612 21786 D cocos2d-x debug info: Thread Name = FMOD mixer thread

02-29 18:55:03.354 21612 21786 D cocos2d-x debug info: 

02-29 18:55:03.357  1781  3807 I Timeline: Timeline: App_transition_ready time:11387850

02-29 18:55:03.360  1781  1799 I Timeline: Timeline: App_transition_ready time:11387853

02-29 18:55:03.365  1781  3568 I Timeline: Timeline: App_transition_ready time:11387858

02-29 18:55:03.369  1781  2837 I Timeline: Timeline: App_transition_ready time:11387862

02-29 18:55:03.390 21612 21612 D Cocos2dxActivity: onWindowFocusChanged() hasFocus=true

02-29 18:55:03.391  1781  1799 I Timeline: Timeline: App_transition_ready time:11387884

02-29 18:55:03.391  1781  1799 I Timeline: Timeline: App_transition_stopped time:11387884

02-29 18:55:03.395  1781  1799 I ActivityManager: Displayed com.netease.g41.netease/org.cocos2dx.lua.AppActivity: +344ms

********************* Resume Normal Case ***********************

02-29 18:56:26.308 21983 22011 I fmod    : ../../src/fmod_systemi.cpp(3625)                             : TID -1363932880 :    16308 ms +1595 : [LOG] SystemI::mixerResume                     : Resuming output.

02-29 18:56:26.309 21983 22011 I fmod    : AudioDevice::init : Min buffer size: 7744 bytes

02-29 18:56:26.309 21983 22011 I fmod    : AudioDevice::init : Actual buffer size: 16384 bytes

02-29 18:56:26.311  1781  1799 I Timeline: Timeline: App_transition_ready time:11470804

02-29 18:56:26.314  1781  1795 V LocationPolicy: onProcessStateChanged

02-29 18:56:26.317  1781  2800 I Timeline: Timeline: App_transition_ready time:11470811

02-29 18:56:26.322   275  2267 V EffectDiracSound: DiracSound_command() start, cmdCode=9

02-29 18:56:26.322   275  2267 V EffectDiracSound: DiracSound_Command EFFECT_CMD_SET_DEVICE: 0x00000002

02-29 18:56:26.322   275  2267 D audio_hw_primary: out_set_parameters: enter: usecase(0: deep-buffer-playback) kvpairs: routing=2

02-29 18:56:26.322   275  2267 I msm8974_platform: platform_get_output_snd_device: enter: output devices(0x2)

02-29 18:56:26.322   275  2267 I msm8974_platform: platform_get_output_snd_device: exit: snd_device(speaker)

02-29 18:56:26.322   275  2267 D audio_hw_extn: audio_extn_set_anc_parameters: anc_enabled:0

02-29 18:56:26.322   275  2267 V audio_hw_primary: out_set_parameters: exit: code(0)

02-29 18:56:26.333  1781  3529 I Timeline: Timeline: App_transition_ready time:11470826

02-29 18:56:26.335   275  2267 D audio_hw_primary: out_set_parameters: enter: usecase(0: deep-buffer-playback) kvpairs: fm_volume=0.5308851600

02-29 18:56:26.335   275  2267 D audio_hw_extn: audio_extn_set_anc_parameters: anc_enabled:0

02-29 18:56:26.335   275  2267 D audio_hw_fm: audio_extn_fm_set_parameters: set_fm_volume usecase

02-29 18:56:26.335   275  2267 D audio_hw_fm: fm_set_volume: (0.530885)

02-29 18:56:26.335   275  2267 V audio_hw_primary: out_set_parameters: exit: code(0)

02-29 18:56:26.342  1781  3626 I Timeline: Timeline: App_transition_ready time:11470836

02-29 18:56:26.330  3417  3417 W Binder_2: type=1400 audit(0.0:1121): avc: denied { search } for name="21983" dev="proc" ino=209116 scontext=u:r:mediaserver:s0 tcontext=u:r:untrusted_app:s0:c512,c768 tclass=dir permissive=0

02-29 18:56:26.345   275  2267 D audio_hw_primary: out_set_parameters: enter: usecase(0: deep-buffer-playback) kvpairs: fm_volume=0.5308851600

02-29 18:56:26.345   275  2267 D audio_hw_extn: audio_extn_set_anc_parameters: anc_enabled:0

02-29 18:56:26.345   275  2267 D audio_hw_fm: audio_extn_fm_set_parameters: set_fm_volume usecase

02-29 18:56:26.345   275  2267 D audio_hw_fm: fm_set_volume: (0.530885)

02-29 18:56:26.345   275  2267 V audio_hw_primary: out_set_parameters: exit: code(0)

02-29 18:56:26.346   275  3417 E AudioFlinger: open /proc/21983/cmdline error

02-29 18:56:26.346   275  3417 I AudioFlinger: setAppName(), name=[], active=[1]

02-29 18:56:26.346   275  4111 E AudioFlinger: open /proc/1781/cmdline error

02-29 18:56:26.346   275  4111 I AudioFlinger: setAppName(), name=[], active=[0]

02-29 18:56:26.347   275  3417 V EffectDiracSound: DiracSound_command() start, cmdCode=23

02-29 18:56:26.347   275  3417 V EffectDiracSound: DiracSound_Command EFFECT_CMD_SET_APP_NAME: stream=3, name=+

02-29 18:56:26.340  4111  4111 W Binder_3: type=1400 audit(0.0:1122): avc: denied { search } for name="1781" dev="proc" ino=13787 scontext=u:r:mediaserver:s0 tcontext=u:r:system_server:s0 tclass=dir permissive=0

02-29 18:56:26.347 21983 22011 I fmod    : ../../src/fmod_thread.cpp(162)                               : TID -1363932880 :    16347 ms   +39 : [LOG] Thread::initThread                       : Initializing FMOD mixer thread.  priority 3

02-29 18:56:26.347 21983 22011 I fmod    : ../../src/fmod_thread.cpp(163)                               : TID -1363932880 :    16347 ms    +0 : [LOG] Thread::initThread                       : - Stacksize 49152.  Stack pointer 0x0 : usesemaphore = 0 : sleeptime = 0

02-29 18:56:26.347 21983 22011 I fmod    : ../android/src/fmod_os_misc.cpp(863)                         : TID -1363932880 :    16347 ms    +0 : [LOG] MemPool::alloc                           :     12 bytes (0x9b756698) (alloc 5685)

02-29 18:56:26.348 21983 22011 I fmod    : ../android/src/fmod_os_misc.cpp(553)                         : TID -1363932880 :    16348 ms    +1 : [LOG] MemPool::alloc                           :    276 bytes (0x98a6a088) (alloc 5686)

02-29 18:56:26.349  3556  4856 I RenderThread: RenderThread resumed

02-29 18:56:26.349  3556  4856 D ScreenElementRoot: resume

02-29 18:56:26.350 21983 22122 I fmod    : ../android/src/fmod_os_misc.cpp(486)                         : TID -1640642256 :    16350 ms    +2 : [LOG] MemPool::free                            :    276 bytes (0x98a6a088)

02-29 18:56:26.350 21983 22122 I fmod    : ../../src/fmod_thread.cpp(46)                                : TID -1640642256 :    16350 ms    +0 : [LOG] Thread::callback                         : * FMOD mixer thread started

02-29 18:56:26.351 21983 22122 D cocos2d-x debug info: NOTE : FMOD_SYSTEM_CALLBACK_PREMIX occured.

02-29 18:56:26.351 21983 22122 D cocos2d-x debug info: 

02-29 18:56:26.351 21983 22122 D cocos2d-x debug info: NOTE : FMOD_SYSTEM_CALLBACK_MIDMIX occured.

02-29 18:56:26.351 21983 22122 D cocos2d-x debug info: 

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: NOTE : FMOD_SYSTEM_CALLBACK_THREADCREATED occured.

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: 

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: Thread ID = -1640642256

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: 

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: Thread Name = FMOD mixer thread

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: 

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1110)                                : TID -1640642256 :    16351 ms    +1 : [LOG] File::read                               : 0x9ae8059c----> want to read 2

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1129)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    mCurrentPosition 27773 mNextPosition 27773 nextpos diffbytes 0

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1130)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    DIRECT READ want 2 bytes

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1178)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    DIRECT READ got  2 bytes

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1233)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c<---- done

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1110)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c----> want to read 49

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1129)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    mCurrentPosition 27775 mNextPosition 27775 nextpos diffbytes 0

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1130)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    DIRECT READ want 49 bytes

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: [LUA-print] onEnterForeground

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1178)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    DIRECT READ got  49 bytes

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1233)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c<---- done

02-29 18:56:26.351 21983 22011 D cocos2d-x debug info: [LUA-print] [INFO] SoundMgr::handleEnterForeground

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1110)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c----> want to read 2

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1129)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    mCurrentPosition 27824 mNextPosition 27824 nextpos diffbytes 0

02-29 18:56:26.351 21983 22122 I fmod    : ../../src/fmod_file.cpp(1130)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    DIRECT READ want 2 bytes

02-29 18:56:26.352 21983 22122 I fmod    : ../../src/fmod_file.cpp(1178)                                : TID -1640642256 :    16351 ms    +0 : [LOG] File::read                               : 0x9ae8059c    DIRECT READ got  2 bytes

02-29 18:56:26.352 21983 22122 I fmod    : ../../src/fmod_file.cpp(1233)                                : TID -1640642256 :    16352 ms    +1 : [LOG] File::read                               : 0x9ae8059c<---- done

02-29 18:56:26.352 21983 22122 I fmod    : ../../src/fmod_file.cpp(1110)                                : TID -1640642256 :    16352 ms    +0 : [LOG] File::read                               : 0x9ae8059c----> want to read 47

02-29 18:56:26.352 21983 22122 I fmod    : ../../src/fmod_file.cpp(1129)                                : TID -1640642256 :    16352 ms    +0 : [LOG] File::read                               : 0x9ae8059c    mCurrentPosition 27826 mNextPosition 27826 nextpos diffbytes 0

It sounds like you are getting a new instance of your activity, i.e. the first instance is paused (mixerSuspend), the second instance is a freshly created FMOD::System, so nothing playing yet.

I’m certainly not an Android activity expert but some quick googling revealed talk of launch modes that control whether activities are reused or not, perhaps that will help in this case?

1 Like

Thanks for the reply.

The activity does create a new instance, I check and print pointer of two activity objects, it’s different.But FMOD::System was create in CPP and I am sure I did not create new one though new activity create.I am calling all fmod’s APIs on the same FMOD::System.

I want to know is fmod system depend on the app’s activity object for playing or does it do some initializing when activity is create internally?Since fmod system is in mixerSuspend status, if it does call some api internally, it will be deadlock.Is that possible?

Launch modes set to singleInstance is my first found solution, it did fix this issue, but I can’t use this for two reason:1.This will make some unnecessary memory holding in background. 2.It conflict with my some payment SDK.It doesn’t pop the pay dialog some times.

Is there may be other reason or hint would cause this problem?Or if you can, please open more inside detail on android platforms initializing and pause/resume process?

FMOD uses the context to query values, but it’s not necessary to play audio. The simplest way forward would be for you to e-mail support@fmod.org with a small Android project that demonstrates your problem, preferably a modified FMOD example. This way a developer on our end can debug the issue for you.

Okay, I will wrote some demos and send to support later, thanks for your reply.

I met the same trouble, have you already solve this problem?

One possible cause is after you call mixerSuspend your game calls into destroy, if this happens make sure you call mixerResume before calling any FMOD functions, this includes release.

1 Like

We are having a similar issue with the latest version of fmod (the one that support AAudio, although we desactivated AAudio use). The onle difference in behavior is that the sound restart after it reaches the end of the loop. but after calling mixerresume nothing can be hear until the background music loops and then we can hear it normally.

Are you checking the FMOD_RESULTs from all the FMOD functons, including mixerResume?