NFC问题分析之死锁引起的ANR

【摘要】 对于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即可。

注:本人水平有限，欢迎各位大牛批评指正，谢谢～