AudioFlinger中的一个线程同步引起的issue, 涉及到了audio方面更复杂点的Framework.
[Symptom]
11-09 21:47:37.879 161 6305 W AudioFlinger: removeEffect_l() 0x41cc53f0 cannot promote chain for effect 0x42445ac8
11-09 21:47:37.879 161 6305 W AudioPolicyManagerBase: unregisterEffect() unknown effect ID 12251
11-09 21:47:37.879 161 6305 V VPT20 : EffectRelease 0x433fedf0
11-09 21:47:37.879 161 6305 V VPT20 : Vpt_release start
11-09 21:47:37.879 161 6305 V VPT20 : EmptyDataProc start
11-09 21:47:37.879 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_EventBufferFlag
11-09 21:47:37.889 161 3294 E VPT20 : FillBuffer is no data
11-09 21:47:37.889 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_EventBufferFlag
11-09 21:47:37.889 161 3294 E VPT20 : FillBuffer is no data
11-09 21:47:37.889 161 6305 V VPT20 : EmptyDataProc end
11-09 21:47:37.889 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_CommandStateSet State:2
11-09 21:47:37.889 161 6305 V VPT20 : FreeBuffer start
11-09 21:47:37.889 161 6305 V VPT20 : FreeBuffer end
11-09 21:47:37.889 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_CommandStateSet State:1
11-09 21:47:37.889 161 6305 V VPT20 : Vpt_release end
11-09 21:47:37.889 161 6305 V VPT20 : EffectRelease end
11-09 21:47:37.889 161 6305 F libc : Fatal signal 11 (SIGSEGV) at 0x00000010 (code=1), thread 6305 (Binder_3)
11-09 21:47:37.999 156 156 I DEBUG : *** *** *** *** *** *** *** *** *** *** *** *** *** *** *** ***
11-09 21:47:37.999 156 156 I DEBUG : Build fingerprint: xxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxxx:userdebug/release-keys'
11-09 21:47:37.999 156 156 I DEBUG : pid: 161, tid: 6305, name: Binder_3 >>> /system/bin/mediaserver <<<
11-09 21:47:37.999 156 156 I DEBUG : signal 11 (SIGSEGV), code 1 (SEGV_MAPERR), fault addr 00000010
11-09 21:47:38.619 610 611 D dalvikvm: GC_CONCURRENT freed 6991K, 44% free 11196K/19911K, paused 22ms+35ms, total 291ms
11-09 21:47:38.849 156 156 I DEBUG : r0 00000000 r1 00000010 r2 00000001 r3 00000001
11-09 21:47:38.849 156 156 I DEBUG : r4 4268cd30 r5 4268cd38 r6 42445ac8 r7 00000001
11-09 21:47:38.849 156 156 I DEBUG : r8 4268cdd4 r9 000000a1 sl 40319a6c fp 00000001
11-09 21:47:38.849 156 156 I DEBUG : ip 00000003 sp 4268cd20 lr 4023dbbb pc 40235228 cpsr 40000030
11-09 21:47:38.849 156 156 I DEBUG : d0 7361656c65527465 d1 7520292874636520
11-09 21:47:38.849 156 156 I DEBUG : d2 65206e776f6e6b65 d3 444920746365666e
11-09 21:47:38.849 156 156 I DEBUG : d4 ff431cfd2fddff23 d5 af7feaffff0de3ff
11-09 21:47:38.849 156 156 I DEBUG : d6 5100fa19e8fffcff d7 000000005a251022
11-09 21:47:38.849 156 156 I DEBUG : d8 0000000000000000 d9 0000000000000000
11-09 21:47:38.849 156 156 I DEBUG : d10 0000000000000000 d11 0000000000000000
11-09 21:47:38.849 156 156 I DEBUG : d12 0000000000000000 d13 0000000000000000
11-09 21:47:38.849 156 156 I DEBUG : d14 0000000000000000 d15 0000000000000000
11-09 21:47:38.849 156 156 I DEBUG : d16 0000000000000000 d17 00000000000001f4
11-09 21:47:38.849 156 156 I DEBUG : d18 00000000000179a5 d19 9d32811804279cf3
11-09 21:47:38.849 156 156 I DEBUG : d20 bf3b893feeaf5f7d d21 62f3fff0876afffe
11-09 21:47:38.849 156 156 I DEBUG : d22 250561599109be60 d23 1a36dab6b20e5dad
11-09 21:47:38.849 156 156 I DEBUG : d24 3fe999a1f2459fc7 d25 000000000000374c
11-09 21:47:38.849 156 156 I DEBUG : d26 00000000000001f2 d27 0000000000000000
11-09 21:47:38.849 156 156 I DEBUG : d28 00000000000174fe d29 0000000000000213
11-09 21:47:38.849 156 156 I DEBUG : d30 0000000000003b66 d31 0000000000017316
11-09 21:47:38.849 156 156 I DEBUG : scr 60000010
11-09 21:47:38.859 156 156 I DEBUG :
11-09 21:47:38.859 156 156 I DEBUG : backtrace:
11-09 21:47:38.859 156 156 I DEBUG : #00 pc 00038228 /system/lib/libaudioflinger.so (android::wp<android::AudioFlinger::EffectHandle>::promote() const+7)
11-09 21:47:38.859 156 156 I DEBUG : #01 pc 00040bb7 /system/lib/libaudioflinger.so (android::AudioFlinger::EffectHandle::disconnect(bool)+76)
11-09 21:47:38.859 156 156 I DEBUG : #02 pc 00053531 /system/lib/libmedia.so (android::BnEffect::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+244)
11-09 21:47:38.859 156 156 I DEBUG : #03 pc 00014391 /system/lib/libbinder.so (android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+60)
11-09 21:47:38.859 156 156 I DEBUG : #04 pc 00016f15 /system/lib/libbinder.so (android::IPCThreadState::executeCommand(int)+520)
11-09 21:47:38.859 156 156 I DEBUG : #05 pc 0001733d /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+184)
11-09 21:47:38.869 156 156 I DEBUG : #06 pc 0001af55 /system/lib/libbinder.so
11-09 21:47:38.869 156 156 I DEBUG : #07 pc 00010e37 /system/lib/libutils.so (android::Thread::_threadLoop(void*)+114)
11-09 21:47:38.869 156 156 I DEBUG : #08 pc 0001099d /system/lib/libutils.so
11-09 21:47:38.869 156 156 I DEBUG : #09 pc 00012df0 /system/lib/libc.so (__thread_entry+48)
11-09 21:47:38.869 156 156 I DEBUG : #10 pc 00012548 /system/lib/libc.so (pthread_create+172)
11-09 21:47:38.869 156 156 I DEBUG :
11-09 21:47:38.869 156 156 I DEBUG : stack:
11-09 21:47:38.869 156 156 I DEBUG : 4268cce0 402de779 /system/lib/libc.so (dlfree)
11-09 21:47:38.869 156 156 I DEBUG : 4268cce4 4268cd10 [stack:6305]
11-09 21:47:38.869 156 156 I DEBUG : 4268cce8 42445ac8
11-09 21:47:38.869 156 156 I DEBUG : 4268ccec 00000001
11-09 21:47:38.869 156 156 I DEBUG : 4268ccf0 4268cd38 [stack:6305]
11-09 21:47:38.869 156 156 I DEBUG : 4268ccf4 4268cdd4 [stack:6305]
11-09 21:47:38.869 156 156 I DEBUG : 4268ccf8 4268cd10 [stack:6305]
11-09 21:47:38.869 156 156 I DEBUG : 4268ccfc 402dff85 /system/lib/libc.so (free+12)
11-09 21:47:38.879 156 156 I DEBUG : 4268cd00 4268cd10 [stack:6305]
11-09 21:47:38.879 156 156 I DEBUG : 4268cd04 40233135 /system/lib/libaudioflinger.so (android::sp<android::AudioFlinger::Client>::~sp()+14)
11-09 21:47:38.879 156 156 I DEBUG : 4268cd08 4268cd10 [stack:6305]
11-09 21:47:38.879 156 156 I DEBUG : 4268cd0c 4023ad57 /system/lib/libaudioflinger.so (android::AudioFlinger::EffectModule::disconnect(android::wp<android::AudioFlinger::EffectHandle> const&, bool)+58)
11-09 21:47:38.879 156 156 I DEBUG : 4268cd10 42445ac8
11-09 21:47:38.879 156 156 I DEBUG : 4268cd14 41cc53f0 [heap]
11-09 21:47:38.879 156 156 I DEBUG : 4268cd18 df0027ad
11-09 21:47:38.879 156 156 I DEBUG : 4268cd1c 00000000
11-09 21:47:38.879 156 156 I DEBUG : #00 4268cd20 00000001
11-09 21:47:38.889 156 156 I DEBUG : 4268cd24 41c73f70
11-09 21:47:38.889 156 156 I DEBUG : 4268cd28 4268cd38 [stack:6305]
11-09 21:47:38.889 156 156 I DEBUG : 4268cd2c 4023dbbb /system/lib/libaudioflinger.so (android::AudioFlinger::EffectHandle::disconnect(bool)+80)
11-09 21:47:38.889 156 156 I DEBUG : #01 4268cd30 00000000
11-09 21:47:38.889 156 156 I DEBUG : 4268cd34 41f0a548
11-09 21:47:38.889 156 156 I DEBUG : 4268cd38 41c73f70
11-09 21:47:38.889 156 156 I DEBUG : 4268cd3c 41c73b38
11-09 21:47:38.889 156 156 I DEBUG : 4268cd40 00000000
11-09 21:47:38.889 156 156 I DEBUG : 4268cd44 41c73f70
11-09 21:47:38.889 156 156 I DEBUG : 4268cd48 4268ce04 [stack:6305]
11-09 21:47:38.889 156 156 I DEBUG : 4268cd4c 4268cdd4 [stack:6305]
11-09 21:47:38.889 156 156 I DEBUG : 4268cd50 00000004
11-09 21:47:38.889 156 156 I DEBUG : 4268cd54 400eb533 /system/lib/libmedia.so (android::BnEffect::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+246)
11-09 21:47:38.899 156 156 I DEBUG : #02 4268cd58 00000000
11-09 21:47:38.899 156 156 I DEBUG : 4268cd5c 40430aa9 /system/lib/libbinder.so (android::Parcel::releaseObjects()+54)
11-09 21:47:38.899 156 156 I DEBUG : 4268cd60 4268cdd4 [stack:6305]
11-09 21:47:38.899 156 156 I DEBUG : 4268cd64 41cc2b20 [heap]
11-09 21:47:38.899 156 156 I DEBUG : 4268cd68 00000000
11-09 21:47:38.899 156 156 I DEBUG : 4268cd6c 4268cdd4 [stack:6305]
11-09 21:47:38.899 156 156 I DEBUG : 4268cd70 00000034
11-09 21:47:38.899 156 156 I DEBUG : 4268cd74 4268ce04 [stack:6305]
11-09 21:47:38.899 156 156 I DEBUG : 4268cd78 41c73f74
11-09 21:47:38.899 156 156 I DEBUG : 4268cd7c 00000004
11-09 21:47:38.899 156 156 I DEBUG : 4268cd80 4022e809 /system/lib/libaudioflinger.so (non-virtual thunk to android::AudioFlinger::EffectHandle::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int))
11-09 21:47:38.899 156 156 I DEBUG : 4268cd84 4268cdd4 [stack:6305]
11-09 21:47:38.899 156 156 I DEBUG : 4268cd88 000000a1
11-09 21:47:38.899 156 156 I DEBUG : 4268cd8c 40319a6c
11-09 21:47:38.899 156 156 I DEBUG : 4268cd90 00000001
11-09 21:47:38.899 156 156 I DEBUG : 4268cd94 4042b393 /system/lib/libbinder.so (android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+62)
11-09 21:47:38.909 156 156 I DEBUG :
11-09 21:47:38.909 156 156 I DEBUG : memory near r4:
11-09 21:47:38.909 156 156 I DEBUG : 4268cd10 42445ac8 41cc53f0 df0027ad 00000000 .ZDB.S.A.'......
11-09 21:47:38.909 156 156 I DEBUG : 4268cd20 00000001 41c73f70 4268cd38 4023dbbb ....p?.A8.hB..#@
11-09 21:47:38.909 156 156 I DEBUG : 4268cd30 00000000 41f0a548 41c73f70 41c73b38 ....H..Ap?.A8;.A
11-09 21:47:38.909 156 156 I DEBUG : 4268cd40 00000000 41c73f70 4268ce04 4268cdd4 ....p?.A..hB..hB
11-09 21:47:38.909 156 156 I DEBUG : 4268cd50 00000004 400eb533 00000000 40430aa9 ....3..@......C@
11-09 21:47:38.909 156 156 I DEBUG :
11-09 21:47:38.909 156 156 I DEBUG : memory near r5:
11-09 21:47:38.919 156 156 I DEBUG : 4268cd18 df0027ad 00000000 00000001 41c73f70 .'..........p?.A
11-09 21:47:38.919 156 156 I DEBUG : 4268cd28 4268cd38 4023dbbb 00000000 41f0a548 8.hB..#@....H..A
11-09 21:47:38.919 156 156 I DEBUG : 4268cd38 41c73f70 41c73b38 00000000 41c73f70 p?.A8;.A....p?.A
11-09 21:47:38.919 156 156 I DEBUG : 4268cd48 4268ce04 4268cdd4 00000004 400eb533 ..hB..hB....3..@
11-09 21:47:38.919 156 156 I DEBUG : 4268cd58 00000000 40430aa9 4268cdd4 41cc2b20 ......C@..hB +.A
11-09 21:47:38.919 156 156 I DEBUG :
11-09 21:47:38.919 156 156 I DEBUG : memory near r6:
11-09 21:47:38.919 156 156 I DEBUG : 42445aa8 70696f76 616c665f 00003d67 00000013 voip_flag=......
11-09 21:47:38.919 156 156 I DEBUG : 42445ab8 70696f76 616c665f 00003d67 00000169 voip_flag=..i...
11-09 21:47:38.919 156 156 I DEBUG : 42445ac8 42445ac0 42445ac0 00000000 00000000 .ZDB.ZDB........
11-09 21:47:38.919 156 156 I DEBUG : 42445ad8 42445e88 00000000 41f0a468 41c62fb8 .^DB....h..A./.A
11-09 21:47:38.919 156 156 I DEBUG : 42445ae8 00002fdb 00002fd1 ec7178ec 4432e5e1 ./.../...xq...2D
11-09 21:47:38.919 156 156 I DEBUG :
11-09 21:47:38.919 156 156 I DEBUG : memory near r8:
11-09 21:47:38.919 156 156 I DEBUG : 4268cdb4 4042df17 00000010 4042da21 41cd6f98 ..B@....!.B@.o.A
11-09 21:47:38.919 156 156 I DEBUG : 4268cdc4 00000002 00000006 404aee57 41c73f74 ........W.J@t?.A
11-09 21:47:38.919 156 156 I DEBUG : 4268cdd4 00000000 40c990c0 00000034 00000034 .......@4...4...
11-09 21:47:38.919 156 156 I DEBUG : 4268cde4 00000034 40c990f4 00000000 00000000 4......@........
11-09 21:47:38.919 156 156 I DEBUG : 4268cdf4 00000000 00010001 4042da21 41cd6f98 ........!.B@.o.A
11-09 21:47:38.919 156 156 I DEBUG :
11-09 21:47:38.919 156 156 I DEBUG : memory near sl:
11-09 21:47:38.919 156 156 I DEBUG : 40319a4c 00000000 00000000 00000000 00000000 ................
11-09 21:47:38.919 156 156 I DEBUG : 40319a5c 00000000 00000000 00000000 00000000 ................
11-09 21:47:38.919 156 156 I DEBUG : 40319a6c 48e06d21 00000000 00000000 00000000 !m.H............
11-09 21:47:38.929 156 156 I DEBUG : 40319a7c 00000000 00000000 00000000 00000000 ................
11-09 21:47:38.929 156 156 I DEBUG : 40319a8c 00000000 00000000 00000000 00000000 ................
11-09 21:47:38.929 156 156 I DEBUG :
11-09 21:47:38.929 156 156 I DEBUG : memory near sp:
11-09 21:47:38.929 156 156 I DEBUG : 4268cd00 4268cd10 40233135 4268cd10 4023ad57 ..hB51#@..hBW.#@
11-09 21:47:38.929 156 156 I DEBUG : 4268cd10 42445ac8 41cc53f0 df0027ad 00000000 .ZDB.S.A.'......
11-09 21:47:38.929 156 156 I DEBUG : 4268cd20 00000001 41c73f70 4268cd38 4023dbbb ....p?.A8.hB..#@
11-09 21:47:38.929 156 156 I DEBUG : 4268cd30 00000000 41f0a548 41c73f70 41c73b38 ....H..Ap?.A8;.A
11-09 21:47:38.929 156 156 I DEBUG : 4268cd40 00000000 41c73f70 4268ce04 4268cdd4 ....p?.A..hB..hB
11-09 21:47:38.929 156 156 I DEBUG :
11-09 21:47:38.929 156 156 I DEBUG : code around pc:
11-09 21:47:38.929 156 156 I DEBUG : 40235208 81f0e8bd 00011b8e 00011136 00011b5c ........6...\...
11-09 21:47:38.929 156 156 I DEBUG : 40235218 000110db 0001104d 4604b538 60202000 ....M...8..F. `
11-09 21:47:38.929 156 156 I DEBUG : 40235228 460d680b 6848b133 f7f34621 b108ebd8 .h.F3.Hh!F......
11-09 21:47:38.929 156 156 I DEBUG : 40235238 60216829 bd384620 f100b573 46060410 )h!` F8.s......F
11-09 21:47:38.939 156 156 I DEBUG : 40235248 f7fa4620 f106fc2b 46680108 ffe4f7ff F..+.....hF....
11-09 21:47:38.939 156 156 I DEBUG :
11-09 21:47:38.939 156 156 I DEBUG : code around lr:
11-09 21:47:38.939 156 156 I DEBUG : 4023db98 b11b9b02 46299803 ecfef7ea 202cf894 ......)F......,
11-09 21:47:38.939 156 156 I DEBUG : 4023dba8 f894b19a b183302d 46686921 f7f73110 ....-0..!ihF.1..
11-09 21:47:38.939 156 156 I DEBUG : 4023dbb8 9800fb33 6923b130 0110f104 6a5b2200 3...0.#i....."[j
11-09 21:47:38.939 156 156 I DEBUG : 4023dbc8 ffb9f7ff f7f44668 6920ff56 f104b128 ....hF..V. i(...
11-09 21:47:38.939 156 156 I DEBUG : 4023dbd8 f7ea0110 2000ecbe 69a16120 6a20b319 ....... a.i.. j
11-09 21:47:39.299 2882 2895 W AudioEffect: IEffect died
11-09 21:47:39.299 602 13457 W IMediaDeathNotifier: media server died
11-09 21:47:39.299 422 627 W IMediaDeathNotifier: media server died
11-09 21:47:39.299 422 681 W AudioEffect: IEffect died
11-09 21:47:39.309 1175 2873 W IMediaDeathNotifier: media server died
11-09 21:47:39.309 422 681 W AudioEffects-JNI: EVENT_ERROR
11-09 21:47:39.309 2882 2895 W AudioEffects-JNI: EVENT_ERROR
11-09 21:47:39.309 422 627 W MediaMetadataRetriever: MediaMetadataRetriever server died!
11-09 21:47:39.309 6929 7416 W MediaMetadataRetriever: MediaMetadataRetriever server died!
1
11-09 21:47:39.329 7895 7906 W MediaMetadataRetriever: MediaMetadataRetriever server died!
11-09 21:47:39.339 422 676 W AudioSystem: AudioFlinger server died!
11-09 21:47:39.339 422 676 E AudioEffectService: binderDied : AudioFlinger is dead.
11-09 21:47:39.339 422 710 W AudioSystem: AudioPolicyService server died!
11-09 21:47:39.339 602 31905 W AudioSystem: AudioFlinger server died!
11-09 21:47:39.339 602 8752 W AudioSystem: AudioPolicyService server died!
11-09 21:47:39.349 1175 3802 W AudioSystem: AudioFlinger server died!
11-09 21:47:39.629 2882 2894 W AudioSystem: AudioFlinger server died!
[Analysis]
The translated StackTrace:
#00 pc 00038228 /system/lib/libaudioflinger.so
android::wp<android::AudioFlinger::EffectHandle>::promote() const
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/include/utils/RefBase.h:433
#01 pc 00040bb7 /system/lib/libaudioflinger.so
android::AudioFlinger::EffectHandle::disconnect(bool)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/av/services/audioflinger/AudioFlinger.cpp:9401
#02 pc 00053531 /system/lib/libmedia.so
android::BnEffect::onTransact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/av/media/libmedia/IEffect.cpp:184
#03 pc 00014391 /system/lib/libbinder.so
android::BBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/libs/binder/Binder.cpp:108
#04 pc 00016f15 /system/lib/libbinder.so
android::IPCThreadState::executeCommand(int)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/libs/binder/IPCThreadState.cpp:1034
#05 pc 0001733d /system/lib/libbinder.so
android::IPCThreadState::joinThreadPool(bool)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/libs/binder/IPCThreadState.cpp:473
#06 pc 0001af55 /system/lib/libbinder.so
android::PoolThread::threadLoop()
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/libs/binder/ProcessState.cpp:67
#07 pc 00010e37 /system/lib/libutils.so
android::Thread::_threadLoop(void*)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/libs/utils/Threads.cpp:793
#08 pc 0001099d /system/lib/libutils.so
thread_data_t::trampoline(thread_data_t const*)
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/frameworks/native/libs/utils/Threads.cpp:132
#09 pc 00012df0 /system/lib/libc.so
__thread_entry
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/bionic/libc/bionic/pthread.c:217
#10 pc 00012548 /system/lib/libc.so
pthread_create
/opt/Weekly_Release/Integration/5855/LINUX_JB_userdebug_single/bionic/libc/bionic/pthread.c:356
The releated source code lists as follows.
It can be found that the crash occurs in DISCONNECT handling of BBinder.
129status_t BnEffect::onTransact(
130 uint32_t code, const Parcel& data, Parcel* reply, uint32_t flags)
131{
132 switch (code) {
133 case ENABLE: {
134 ALOGV("ENABLE");
135 CHECK_INTERFACE(IEffect, data, reply);
136 reply->writeInt32(enable());
137 return NO_ERROR;
138 } break;
139
140 case DISABLE: {
141 ALOGV("DISABLE");
142 CHECK_INTERFACE(IEffect, data, reply);
143 reply->writeInt32(disable());
144 return NO_ERROR;
145 } break;
146
147 case COMMAND: {
148 ALOGV("COMMAND");
149 CHECK_INTERFACE(IEffect, data, reply);
150 uint32_t cmdCode = data.readInt32();
151 uint32_t cmdSize = data.readInt32();
152 char *cmd = NULL;
153 if (cmdSize) {
154 cmd = (char *)malloc(cmdSize);
155 data.read(cmd, cmdSize);
156 }
157 uint32_t replySize = data.readInt32();
158 uint32_t replySz = replySize;
159 char *resp = NULL;
160 if (replySize) {
161 resp = (char *)malloc(replySize);
162 }
163 status_t status = command(cmdCode, cmdSize, cmd, &replySz, resp);
164 reply->writeInt32(status);
165 if (replySz < replySize) {
166 replySize = replySz;
167 }
168 reply->writeInt32(replySize);
169 if (replySize) {
170 reply->write(resp, replySize);
171 }
172 if (cmd) {
173 free(cmd);
174 }
175 if (resp) {
176 free(resp);
177 }
178 return NO_ERROR;
179 } break;
180
181 case DISCONNECT: {
182 ALOGV("DISCONNECT");
183 CHECK_INTERFACE(IEffect, data, reply);
184 disconnect(); ********************
185 return NO_ERROR;
186 } break;
187
188 case GET_CBLK: {
189 CHECK_INTERFACE(IEffect, data, reply);
190 reply->writeStrongBinder(getCblk()->asBinder());
191 return NO_ERROR;
192 } break;
193
194 default:
195 return BBinder::onTransact(code, data, reply, flags);
196 }
197}
In frameworks/av/services/audioflinger/AudioFlinger.cpp
9387void AudioFlinger::EffectHandle::disconnect()
9388{
9389 disconnect(true);
9390}
9391
9392void AudioFlinger::EffectHandle::disconnect(bool unpinIfLast)
9393{
9394 ALOGV("disconnect(%s)", unpinIfLast ? "true" : "false");
9395 if (mEffect == 0) {
9396 return;
9397 }
9398 mEffect->disconnect(this, unpinIfLast);
9399
9400 if (mHasControl && mEnabled) {
9401 sp<ThreadBase> thread = mEffect->thread().promote(); *******crash occurs in*****
9402 if (thread != 0) {
9403 thread->checkSuspendOnEffectEnabled(mEffect, false, mEffect->sessionId());
9404 }
9405 }
9406
9407 // release sp on module => module destructor can be called now
9408 mEffect.clear();
9409 if (mClient != 0) {
9410 if (mCblk != NULL) {
9411 // unlike ~TrackBase(), mCblk is never a local new, so don't delete
9412 mCblk->~effect_param_cblk_t(); // destroy our shared-structure.
9413 }
9414 mCblkMemory.clear(); // free the shared memory before releasing the heap it belongs to
9415 // Client destructor must run with AudioFlinger mutex locked
9416 Mutex::Autolock _l(mClient->audioFlinger()->mLock);
9417 mClient.clear();
9418 }
9419}
429template<typename T>
430sp<T> wp<T>::promote() const
431{
432 sp<T> result;
433 if (m_ptr && m_refs->attemptIncStrong(&result)) { ****** crash occurs here ******
434 result.set_pointer(m_ptr);
435 }
436 return result;
437}
In wp<T>.promote(), we can know the SIGSEGV gives out at line #433, but we can't position precisely where the signal gives out.
So, dump the assemble code.
Dump of assembler code for function android::wp<android::AudioFlinger::ThreadBase>::promote() const:
0x00038220 <+0>: push {r3, r4, r5, lr}
0x00038222 <+2>: mov r4, r0 r0 points to the returned sp<ThreadBase>, local result variable is optimized out.
0x00038224 <+4>: movs r0, #0
0x00038226 <+6>: str r0, [r4, #0] assign result.m_ptr with NULL;
0x00038228 <+8>: ldr r3, [r1, #0] evaluate this.m_ptr, !!crash here!!
0x0003822a <+10>: mov r5, r1
0x0003822c <+12>: cbz r3, 0x3823c <android::wp<android::AudioFlinger::ThreadBase>::promote() const+28>
0x0003822e <+14>: ldr r0, [r1, #4]
0x00038230 <+16>: mov r1, r4
0x00038232 <+18>: blx 0x2b9e4
0x00038236 <+22>: cbz r0, 0x3823c <android::wp<android::AudioFlinger::ThreadBase>::promote() const+28>
0x00038238 <+24>: ldr r1, [r5, #0]
0x0003823a <+26>: str r1, [r4, #0] assign result.m_ptr with this.m_ptr
0x0003823c <+28>: mov r0, r4
0x0003823e <+30>: pop {r3, r4, r5, pc}
End of assembler dump.
From the code, the SIGSEGV crash occurs when the m_ptr of wp<ThreadBase> is to be evaluated in if block.
m_ptr is at the offset of 0x00 of wp<ThreadBase>, so, the 'this' pointer points to the wp<ThreadBase> object is wild pointer with value 0x10.
According to definitions of class EffectModule and class EffectHandle,
1545 class EffectModule: public RefBase { @ AudioFlinger.h
1546 public:
.......
1595 const wp<ThreadBase>& thread() { return mThread; } ***************
.......
1621 bool mPinned;
.......
1632mutable Mutex mLock; // mutex for process, commands and handles list protection
1633 wp<ThreadBase> mThread; // parent thread ***************
1634 wp<EffectChain> mChain; // parent effect chain
.......
1648 };
1656 class EffectHandle: public android::BnEffect { @ AudioFlinger.h
.........
1703 protected:
1704 friend class AudioFlinger; // for mEffect, mHasControl, mEnabled
1705 EffectHandle(const EffectHandle&);
1706 EffectHandle& operator =(const EffectHandle&);
1707
1708 sp<EffectModule> mEffect; // pointer to controlled EffectModule
1709 sp<IEffectClient> mEffectClient; // callback interface for client notifications
1710 /*const*/ sp<Client> mClient; // client for shared memory allocation, see disconnect()
1711 sp<IMemory> mCblkMemory; // shared memory for control block
1712 effect_param_cblk_t* mCblk; // control block for deferred parameter setting via shared memory
1713 uint8_t* mBuffer; // pointer to parameter area in shared memory
1714 int mPriority; // client application priority to control the effect
1715 bool mHasControl; // true if this handle is controlling the effect
1716 bool mEnabled; // cached enable state: needed when the effect is
1717 // restored after being suspended
1718 };
The mEffect is sp<EffectModule> type.
EffectModule::thread() returns class EffectModule's mThread field which is at offset 0x10 of EffectModule.
So the mEffect.m_ptr is NULL, that is to say that object EffectHandle::mEffect has been cleared.
Notice some Effect object is released before the crash occurs.
-----------------------------------------------------------------------------------------------------------------------------------------------------
From the EffectModule object address and mId value printed in the log, part of the original EffectModule object may be re-drawn.
11-09 21:47:37.879 161 6305 W AudioFlinger: removeEffect_l() 0x41cc53f0--(ThreadBase*) cannot promote chain for effect 0x42445ac8(EffectModule*)
11-09 21:47:37.879 161 6305 W AudioPolicyManagerBase: unregisterEffect() unknown effect ID 12251 (0x2fdb)
11-09 21:47:37.879 161 6305 V VPT20 : EffectRelease 0x433fedf0 (effect_handle_t mEffectInterface of EffecModule)
11-09 21:47:38.919 156 156 I DEBUG : memory near r6:
11-09 21:47:38.919 156 156 I DEBUG : 42445aa8 70696f76 616c665f 00003d67 00000013 voip_flag=......
11-09 21:47:38.919 156 156 I DEBUG : 42445ab8 70696f76 616c665f 00003d67 00000169 voip_flag=..i...
42445ac8 42445ac0 vtbl ?? may memory has been reused?
42445acc 42445ac0 RefBase::mRefs ?? may memory has been reused?
42445ad0 00000000 mPinned
42445ad4 00000000 mLock
42445ad8 42445e88 00000000 wp<ThreadBase> {m_ptr, m_refs}
42445ae0 41f0a468 41c62fb8 wp<EffectChain> {m_ptr, m_refs}
42445ae8 00002fdb mId
42445aec 00002fd1 mSessionId
42445af0 ec7178ec 4432e5e1 mDescriptor {......}
8686void AudioFlinger::EffectModule::disconnect(const wp<EffectHandle>& handle, bool unpinIfLast)
8687{
8688 ALOGV("disconnect() %p handle %p", this, handle.unsafe_get());
8689 // keep a strong reference on this EffectModule to avoid calling the
8690 // destructor before we exit
8691 sp<EffectModule> keep(this);
8692 {
8693 sp<ThreadBase> thread = mThread.promote();
8694 if (thread != 0) {
8695 thread->disconnectEffect(keep, handle, unpinIfLast); ==calls==>>
8696 }
8697 }
8698}
8364void AudioFlinger::ThreadBase::disconnectEffect(const sp<EffectModule>& effect,
8365 const wp<EffectHandle>& handle,
8366 bool unpinIfLast) {
8367
8368 Mutex::Autolock _l(mLock);
8369 ALOGV("disconnectEffect() %p effect %p", this, effect.get());
8370 // delete the effect module if removing last handle on it
8371 if (effect->removeHandle(handle) == 0) {
8372 if (!effect->isPinned() || unpinIfLast) {
8373 removeEffect_l(effect); ===>>
8374 AudioSystem::unregisterEffect(effect->id()); ------ printed out
8375 }
8376 }
8377}
In AudioFlinger::EffectModule::disconnect(const wp<EffectHandle>& handle, bool unpinIfLast), AudioFlinger::ThreadBase::disconnectEffect is called.
AudioFlinger::ThreadBase::disconnectEffect in turn calls removeEffect_l and AudioSystem::unregisterEffect(..).
From the log,
AudioFlinger::ThreadBase::removeEffect_l claims that W AudioFlinger: removeEffect_l() 0x41cc53f0 cannot promote chain for effect 0x42445ac8,
AudioSystem::unregisterEffect(..) claims that AudioPolicyManagerBase: unregisterEffect() unknown effect ID 12251.
This gives us a light that the EffectModule maybe has been destroyed.
8641size_t AudioFlinger::EffectModule::removeHandle(const wp<EffectHandle>& handle)
8642{
8643 Mutex::Autolock _l(mLock);
8644 size_t size = mHandles.size();
8645 size_t i;
8646 for (i = 0; i < size; i++) {
8647 if (mHandles[i] == handle) break;
8648 }
8649 if (i == size) {
8650 return size;
8651 }
8652 ALOGV("removeHandle() %p removed handle %p in position %d", this, handle.unsafe_get(), i);
8653
8654 bool enabled = false;
8655 EffectHandle *hdl = handle.unsafe_get();
8656 if (hdl != NULL) {
8657 ALOGV("removeHandle() unsafe_get OK");
8658 enabled = hdl->enabled();
8659 }
8660 mHandles.removeAt(i);
8661 size = mHandles.size();
8662 // if removed from first place, move effect control from this handle to next in line
8663 if (i == 0 && size != 0) {
8664 sp<EffectHandle> h = mHandles[0].promote();
8665 if (h != 0) {
8666 h->setControl(true /*hasControl*/, true /*signal*/ , enabled /*enabled*/);
8667 }
8668 }
8669
8670 // Prevent calls to process() and other functions on effect interface from now on.
8671 // The effect engine will be released by the destructor when the last strong reference on
8672 // this object is released which can happen after next process is called.
8673 if (size == 0 && !mPinned) {
8674 mState = DESTROYED;
8675 }
8676
8677 return size;
8678}
For line #8664, is it safe for EffectHandle[0] if it is EffectModule's wrpper EffectHandle?? can this case be existed??
Though it maybe cause the EffectHandle destroyed, but EffectHandle::mEffect.m_ptr can't be NULL.
Except m_ptr is re-filled with zeros, it is most possible that mEffect.clear() is called.
8302void AudioFlinger::ThreadBase::removeEffect_l(const sp<EffectModule>& effect) {
8303
8304 ALOGV("removeEffect_l() %p effect %p", this, effect.get());
8305 effect_descriptor_t desc = effect->desc();
8306 if ((desc.flags & EFFECT_FLAG_TYPE_MASK) == EFFECT_FLAG_TYPE_AUXILIARY) {
8307 detachAuxEffect_l(effect->id());
8308 }
8309
8310 sp<EffectChain> chain = effect->chain().promote();
8311 if (chain != 0) {
8312 // remove effect chain if removing last effect
8313 if (chain->removeEffect_l(effect) == 0) {
8314 removeEffectChain_l(chain);
8315 }
8316 } else {
8317 ALOGW("removeEffect_l() %p cannot promote chain for effect %p", this, effect.get()); ********claims*****
8318 }
8319}
949status_t AudioPolicyManagerBase::unregisterEffect(int id)
950{
951 ssize_t index = mEffects.indexOfKey(id); ******** has been removed already **********
952 if (index < 0) {
953 LOGW("unregisterEffect() unknown effect ID %d", id); *****************claims******************
954 return INVALID_OPERATION;
955 }
956
957 EffectDescriptor *pDesc = mEffects.valueAt(index);
958
959 setEffectEnabled(pDesc, false);
960
961 if (mTotalEffectsMemory < pDesc->mDesc.memoryUsage) {
962 LOGW("unregisterEffect() memory %d too big for total %d",
963 pDesc->mDesc.memoryUsage, mTotalEffectsMemory);
964 pDesc->mDesc.memoryUsage = mTotalEffectsMemory;
965 }
966 mTotalEffectsMemory -= pDesc->mDesc.memoryUsage;
967 LOGV("unregisterEffect() effect %s, ID %d, memory %d total memory %d",
968 pDesc->mDesc.name, id, pDesc->mDesc.memoryUsage, mTotalEffectsMemory);
969
970 mEffects.removeItem(id);
971 delete pDesc;
972
973 return NO_ERROR;
974}
-------------------------------------------------------------------------------------------------------------------------------------------
From the log of above two functions print out, we can image that the EffectModule object is destroyed before those two functions called.
From the following log lines which is output by EffectRelease(), it is certain that the EffectModule is destroyed.
11-09 21:47:37.879 161 6305 V VPT20 : EffectRelease 0x433fedf0
11-09 21:47:37.879 161 6305 V VPT20 : Vpt_release start
11-09 21:47:37.879 161 6305 V VPT20 : EmptyDataProc start
11-09 21:47:37.879 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_EventBufferFlag
11-09 21:47:37.889 161 3294 E VPT20 : FillBuffer is no data
11-09 21:47:37.889 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_EventBufferFlag
11-09 21:47:37.889 161 3294 E VPT20 : FillBuffer is no data
11-09 21:47:37.889 161 6305 V VPT20 : EmptyDataProc end
11-09 21:47:37.889 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_CommandStateSet State:2
11-09 21:47:37.889 161 6305 V VPT20 : FreeBuffer start
11-09 21:47:37.889 161 6305 V VPT20 : FreeBuffer end
11-09 21:47:37.889 161 3294 V VPT20 : Vpt_cb_EventHandler OMX_CommandStateSet State:1
11-09 21:47:37.889 161 6305 V VPT20 : Vpt_release end
11-09 21:47:37.889 161 6305 V VPT20 : EffectRelease end
8591AudioFlinger::EffectModule::~EffectModule()
8592{
8593 ALOGV("Destructor %p", this);
8594 if (mEffectInterface != NULL) {
8595 if ((mDescriptor.flags & EFFECT_FLAG_TYPE_MASK) == EFFECT_FLAG_TYPE_PRE_PROC ||
8596 (mDescriptor.flags & EFFECT_FLAG_TYPE_MASK) == EFFECT_FLAG_TYPE_POST_PROC) {
8597 sp<ThreadBase> thread = mThread.promote();
8598 if (thread != 0) {
8599 audio_stream_t *stream = thread->stream();
8600 if (stream != NULL) {
8601 stream->remove_audio_effect(stream, mEffectInterface);
8602 }
8603 }
8604 }
8605 // release effect engine
8606 EffectRelease(mEffectInterface); ************
8607 }
8608}
It can be judged primarily as a race condition and thread sync issue.
EffectModule object is accessed via sp<EffectModule>, it should not destroyed abnormally.
So, the most case maybe EffectModule is destroyed explicitly via sp<T>.clear(), which decStrong reference and set sp<T>.m_ptr with NULL.
Find where mEffect.clear() is called besides AudioFlinger::EffectModule::~EffectModule() in AudioFlinger.cpp,
7699void AudioFlinger::purgeStaleEffects_l() {
7700
7701 ALOGV("purging stale effects");
7702
7721
7722 for (size_t i = 0; i < chains.size(); i++) {
7723 sp<EffectChain> ec = chains[i];
7724 int sessionid = ec->sessionId();
7725 sp<ThreadBase> t = ec->mThread.promote();
7726 if (t == 0) {
7727 continue;
7728 }
7740 if (!found) {
7741 // remove all effects from the chain
7742 while (ec->mEffects.size()) {
7743 sp<EffectModule> effect = ec->mEffects[0];
7744 effect->unPin();
7745 Mutex::Autolock _l (t->mLock);
7746 t->removeEffect_l(effect);
7747 for (size_t j = 0; j < effect->mHandles.size(); j++) {
7748 sp<EffectHandle> handle = effect->mHandles[j].promote();
7749 if (handle != 0) {
7750 handle->mEffect.clear(); // *** Reference solution: should be Mutex::Autolock(..) here *******
7751 if (handle->mHasControl && handle->mEnabled) {
7752 t->checkSuspendOnEffectEnabled_l(effect, false, effect->sessionId());
7753 }
7754 }
7755 }
7756 AudioSystem::unregisterEffect(effect->id());
7757 }
7758 }
7759 }
7760 return;
7761}
9944void AudioFlinger::EffectChain::setEffectSuspended_l(
9945 const effect_uuid_t *type, bool suspend)
9946{
9947 sp<SuspendedEffectDesc> desc;
9948 // use effect type UUID timelow as key as there is no real risk of identical
9949 // timeLow fields among effect type UUIDs.
9950 ssize_t index = mSuspendedEffects.indexOfKey(type->timeLow);
9951 if (suspend) {
9968 } else {
9969 if (index < 0) {
9970 return;
9971 }
9972 desc = mSuspendedEffects.valueAt(index);
9973 if (desc->mRefCount <= 0) {
9974 ALOGW("setEffectSuspended_l() restore refcount should not be 0 %d", desc->mRefCount);
9975 desc->mRefCount = 1;
9976 }
9977 if (--desc->mRefCount == 0) {
9978 ALOGV("setEffectSuspended_l() remove entry for %08x", mSuspendedEffects.keyAt(index));
9979 if (desc->mEffect != 0) {
9980 sp<EffectModule> effect = desc->mEffect.promote();
9981 if (effect != 0) {
9982 effect->setSuspended(false);
9983 sp<EffectHandle> handle = effect->controlHandle();
9984 if (handle != 0) {
9985 effect->setEnabled(handle->enabled());
9986 }
9987 }
9988 desc->mEffect.clear();
9989 }
9990 mSuspendedEffects.removeItemsAt(index);
9991 }
9992 }
9993}
10089void AudioFlinger::EffectChain::checkSuspendOnEffectEnabled(const sp<EffectModule>& effect,
10090 bool enabled)
10091{
10092 ssize_t index = mSuspendedEffects.indexOfKey(effect->desc().type.timeLow);
10093 if (enabled) {
10094 if (index < 0) {
10095 // if the effect is not suspend check if all effects are suspended
10112 sp<SuspendedEffectDesc> desc = mSuspendedEffects.valueAt(index);
10113 // if effect is requested to suspended but was not yet enabled, supend it now.
10114 if (desc->mEffect == 0) {
10115 desc->mEffect = effect;
10116 effect->setEnabled(false);
10117 effect->setSuspended(true);
10118 }
10119 } else {
10120 if (index < 0) {
10121 return;
10122 }
10123 ALOGV("checkSuspendOnEffectEnabled() disable restoring fx %08x",
10124 effect->desc().type.timeLow);
10125 sp<SuspendedEffectDesc> desc = mSuspendedEffects.valueAt(index);
10126 desc->mEffect.clear();
10127 effect->setSuspended(false);
10128 }
10129}
So, the app should be well thread synced based on the thread model.
With the help from audio framework dept, find that purgeStaleEffects_l() called in releaseAudioSession is called in another thread that not well synchronized with the crash thread.
More, maybe it should be considered to prevent the whole EffectHandle's from being destroyed.
And notice the wp<T>'s life cycle, remember in mind that sp<T>'s destroy may cause T t's destroy.
Use wp<T>.promote() to try to get sp<T> everytime.