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