NFC問題分析之死結引起的ANR

標籤：exce   點擊   div   ini   anr   stat   使用者   settings   int   

【摘要】 對於Android平台的工程師來說，ANR應該是每個人都會遇到的問題，因為導致它的原因有很多，例如在主線程進行耗時操作，調用大量cpu資源進行複雜的預算等，並且可能在大多數情況下，這類問題不會發生，只會在極端特殊的情況下暴露(例如很長時間的自動化指令碼測試，monkey測試)，所以我們必須得學會如何去分析這類問題，才能讓模組的效能經得住考驗。

一. 什麼是ANR?為什麼會有ANR發生?
如果當你進行一些操作之後，發現手機螢幕上出現類似上面的dialog，那麼很不幸，你中招了。。。ANR，Application Not Responding，即應用無響應。一般來說，當應用對使用者的互動沒有反應時，系統就會彈出上述的ANR dialog。這種情況一般發生在如主線程被IO操作block住了，主線程進行了大量的例如讀取資料庫的操作等。從google官方文檔上介紹來看，主要由以下兩種情況引起:1. 應用在5秒內對於使用者的輸入事件無響應2. BroadcastReceiver在10秒內不能完成onReceive()方法的執行Note: 上述的時間是基於Google原生的Code，國內不少廠商因為某些原因會把這些時間延長，請以具體的vendor代碼為準
二. NFC為什麼會有ANR問題發生

首先和沒接觸過NFC的朋友介紹下NFC。

NFC，Near field communication，即近場通訊，是由非接觸式射頻識別（RFID）演變而來的短距離無線電技術，由Nokia, Sony, NXP共同研發。在國外，如日本，這種技術運用的已經十分廣泛，無論從出行到購物，哪裡都有Felica(日本使用的NFC標準)的身影。然而國內因為某寶過於強大和人性化，NFC技術推動任重而道遠。但是隨著如小米錢包等應用開始使用NFC來類比公交卡以及銀行卡方便使用者的生活，個人認為，未來是美好的！！！

作為一個Local Connectivity的重要模組，NFC不僅可以進行Read/Write Tag，而且可以通過Android Beam（Android 4.0開始支援的點對點傳輸的feature）傳輸檔案。handover的功能更是讓NFC成為一個wifi和bt快速建立連結的橋樑，極大的方便了使用者的近距離傳輸的需求。也正是因為這些原因，在特殊情況下的並行作業，就會導致NFC出現ANR的問題，下面以一個簡單的NFC相互調用死結導致的ANR案例進行分析。

三. 案例分析首先推薦給各位一個查看原始碼的網站，http://androidxref.com/， 如果沒有VPN的話，這個網站看源碼還是比較給力的，可能大多數哥們都知道，呵呵～
下面先簡單介紹下導致ANR發生的操作:在NFC關閉的情況下，(Android Beam必須是隨著NFC的關閉自動關閉的，否則因為相應的component被disable,分享列表中找不到Android Beam選項)，通過Android Beam去分享一個檔案，這種情況下會彈出一個提示需要開啟NFC功能的Dialog,點擊確定，正常情況下，會出現Android Beam的圖片縮放介面如，但是ANR發生時整個介面沒有任何反應，幾秒鐘後，系統就會彈出Settings ANR的dialog。


對於ANR問題的分析，我們應該首先去找問題發生時，手機自動儲存在data/anr目錄下的trace.txt檔案，這是最能直觀反應問題發生時堆棧的資訊以及各種資源的使用方式。

因為NfcService是NFC上層最核心的一個檔案，底層的所有處理都會一層層往上拋給NfcService,上層的API介面也只會通過NfcService去調用具體的底層實現。所有我們現在trace.txt中以NfcService作為關鍵字進行搜尋，看到如下trace.log

"Binder_1" prio=5 tid=8 Blocked（prio 進程號， tid 線程號)  | group="main" sCount=1 dsCount=0 obj=0x12c8b0a0 self=0x7f8ef53400  | sysTid=2903 nice=0 cgrp=default sched=0/0 handle=0x7f93af5440  | state=S schedstat=( 81420425 126587653 792 ) utm=3 stm=5 core=0 HZ=100  | stack=0x7f939f9000-0x7f939fb000 stackSize=1013KB  | held mutexes=  at com.android.nfc.NfcService$NfcAdapterService.getState(NfcService.java:1813)  - waiting to lock <0x0196c7d2> (a com.android.nfc.NfcService) held by thread 18  --->被線程18阻塞  at android.nfc.INfcAdapter$Stub.onTransact(INfcAdapter.java:95)  at android.os.Binder.execTransact(Binder.java:477)</span>

從上面的trace log可以看到，NfcService$NfcAdapterService.getState()想獲得0x0196c7d2，即NfcService對象鎖，代碼如下

        @Override        public int getState() throws RemoteException {            synchronized (NfcService.this) {                return mState;            }        }

但是這個對象鎖並不能馬上獲得，因為thread 18正在佔用，看下線程18的堆棧資訊

"Binder_3" prio=5 tid=18 Blocked  | group="main" sCount=1 dsCount=0 obj=0x12e120a0 self=0x7f94114200  | sysTid=3414 nice=0 cgrp=default sched=0/0 handle=0x7f7c9a0440  | state=S schedstat=( 67563697 66692461 439 ) utm=0 stm=6 core=0 HZ=100  | stack=0x7f7c8a4000-0x7f7c8a6000 stackSize=1013KB  | held mutexes=  at com.android.nfc.P2pLinkManager.isLlcpActive(P2pLinkManager.java:410)  - waiting to lock <0x0c8140a3> (a com.android.nfc.P2pLinkManager) held by thread 1 --->被線程1阻塞  at com.android.nfc.NfcService$NxpExtrasService._open(NfcService.java:3173)  - locked <0x0196c7d2> (a com.android.nfc.NfcService)  at com.android.nfc.NfcService$NxpExtrasService.open(NfcService.java:3149)  at com.nxp.intf.INxpExtrasService$Stub.onTransact(INxpExtrasService.java:55)  at android.os.Binder.execTransact(Binder.java:477)

上面的log可以看出，NfcService的對象鎖正在被NfcService$NxpExtrasService._open()方法所持有，代碼如下:

private int _open(IBinder b) {            synchronized(NfcService.this) {                if (!isNfcEnabled()) {                    return EE_ERROR_NFC_DISABLED;                }                if (mInProvisionMode) {                    // Deny access to the NFCEE as long as the device is being setup                    return EE_ERROR_IO;                }                if (mP2pLinkManager.isLlcpActive()) {                    // Don't allow PN544-based devices to open the SE while the LLCP                    // link is still up or in a debounce state. This avoids race                    // conditions in the NXP stack around P2P/SMX switching.                    return EE_ERROR_EXT_FIELD;                }

上面的這個方法遲遲不能執行完畢，是因為調用了mP2pLinkManager.isLlcpActive()，這個方法希望獲得0x0c8140a3，即P2pLinkManager的對象鎖，但是這個對象鎖也不能馬上獲得，正在被thread1掛起。

public boolean isLlcpActive() {        synchronized (this) { ---> P2pLinkManager對象鎖            return mLinkState != LINK_STATE_DOWN;        }    }

那麼我們繼續看下thread1的trace資訊:

"main" prio=5 tid=1 Blocked  | group="main" sCount=1 dsCount=0 obj=0x762a8fb8 self=0x7f955fba00  | sysTid=2880 nice=0 cgrp=default sched=0/0 handle=0x7f98da8fe8  | state=S schedstat=( 344423025 553179190 922 ) utm=24 stm=10 core=3 HZ=100  | stack=0x7fca15d000-0x7fca15f000 stackSize=8MB  | held mutexes=  at com.android.nfc.NfcService.playSound(NfcService.java:1509)  - waiting to lock <0x0196c7d2> (a com.android.nfc.NfcService) held by thread 18  at com.android.nfc.P2pEventManager.onP2pNfcTapRequested(P2pEventManager.java:81)  at com.android.nfc.P2pLinkManager.onManualBeamInvoke(P2pLinkManager.java:455)  - locked <0x0c8140a3> (a com.android.nfc.P2pLinkManager)  at com.android.nfc.NfcService$NfcServiceHandler.handleMessage(NfcService.java:4366)  at android.os.Handler.dispatchMessage(Handler.java:102)  at android.os.Looper.loop(Looper.java:148)  at android.app.ActivityThread.main(ActivityThread.java:5541)  at java.lang.reflect.Method.invoke!(Native method)  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:935)  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:726)

0x0c8140a3這個鎖正在被P2pLinkManager.onManualBeamInvoke()方法佔用，代碼如下:

 public void onManualBeamInvoke(BeamShareData shareData) {        synchronized (P2pLinkManager.this)    {            if (mLinkState != LINK_STATE_DOWN) {                return;            }            if (mForegroundUtils.getForegroundUids().contains(mNdefCallbackUid)) {                // Try to get data from the registered NDEF callback                prepareMessageToSend(false);            } else {                mMessageToSend = null;                mUrisToSend = null;            }            if (mMessageToSend == null && mUrisToSend == null && shareData != null) {                // No data from the NDEF callback, get data from ShareData                if (shareData.uris != null) {                    mUrisToSend = shareData.uris;                } else if (shareData.ndefMessage != null) {                    mMessageToSend = shareData.ndefMessage;                }                mUserHandle = shareData.userHandle;            }            if (mMessageToSend != null ||                    (mUrisToSend != null && mHandoverDataParser.isHandoverSupported())) {                mSendState = SEND_STATE_PENDING;                mEventListener.onP2pNfcTapRequested();                scheduleTimeoutLocked(MSG_WAIT_FOR_LINK_TIMEOUT, WAIT_FOR_LINK_TIMEOUT_MS);            }        }    }

上面的方法裡會去調用mEventListener.onP2pNfcTapRequested()，代碼如下:

@Override    public void onP2pNfcTapRequested() {        mNfcService.playSound(NfcService.SOUND_START);        mNdefSent = false;        mNdefReceived = false;        mInDebounce = false;        mVibrator.vibrate(VIBRATION_PATTERN, -1);

這個方法會調用NfcService裡面的mNfcService.playSound()。trace log顯示playSound()會去想持有0x0196c7d2即NfcService對象。看下代碼是不是這樣:

public void playSound(int sound) {        synchronized (this) { ---> NfcService對象鎖            if (mSoundPool == null) {                Log.w(TAG, "Not playing sound when NFC is disabled");                return;            }

這裡請注意，上面NfcService$NxpExtrasService._open()正在持有的對象也是這個。

現在基本知道什麼情況下，我們回過頭來再捋一捋。

NfcAdapterService.getState希望持有NfcService對象，無法獲得block

NfcService對象正在被NxpExtrasService._open()持有, 這個方法無法執行完畢，被mP2pLinkManager.isLlcpActive() block

mP2pLinkManager.isLlcpActive()希望持有P2pLinkManager的對象，無法獲得 block

P2pLinkManager對象正在被onManualBeamInvoke()方法持有，這個方法無法執行完畢，被mEventListener.onP2pNfcTapRequested() block

mEventListener.onP2pNfcTapRequested() 無法執行完畢，被mNfcService.playSound() block

mNfcService.playSound() 希望持有NfcService的對象，這個對象被最上面的NxpExtrasService._open()持有

所以總體來說，就是正在佔用NfcService鎖的NxpExtrasService._open()需要P2pLinkManager的鎖釋放，而正在佔用P2pLinkManager這個鎖的onManualBeamInvoke()方法需要NfcService的鎖釋放，雙方互不讓步，造成死結。

暫時想到的解決的策略就是將

public void playSound(int sound) {        synchronized (this) { <---> NfcService對象鎖            if (mSoundPool == null) {                Log.w(TAG, "Not playing sound when NFC is disabled");                return;            }

這個鎖的範圍縮小，換成一個私人鎖。

即 Object mPlaySoundLock = new Obejct()，然後將this替換成mPlaySoundLock即可。

注:本人水平有限，歡迎各位大牛批評指正，謝謝～

NFC問題分析之死結引起的ANR