Android ANR分析

ANR基础知识

ANR全称Application not response，即程序无响应。

ANR的分类

• KeyDispatchTimeout 输入超时，一般超时为5S
• BroadcastTimeout 广播超时， 一般为10S
• ServiceTimeout Service处理超时，这个比较少见， 一般为20S
  这几个值在ActivityManagerService.java中有定义。

KeyDispatch:
const nsecs_t DEFAULT_INPUT_DISPATCHING_TIMEOUT = 5000 * 1000000LL; // 5 sec
Broadcast:
    static final int BROADCAST_FG_TIMEOUT = 10*1000;    ->前台10S
    static final int BROADCAST_BG_TIMEOUT = 60*1000;    ->后台60S
Service:
    static final int SERVICE_TIMEOUT = 20*1000;  ->前台20S
    // How long we wait for a service to finish executing.
    static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10; ->后台200S

ANR产生的原因

• 一般是主线程处理耗时动作，Android线程一般是串行作用，如果主线程处理耗时，则其他线程就没法继续处理；

主线程进行网络访问
主线程进行大数据库的访问
主线程进行硬件操作
主线程调用Thread.join或者Thread.sleep
Service忙碌超时
其他线程占有lock,主线程等待Lock,这个设计到锁的问题
主线程等待其他线程返回结果
总结就是主线程因为各种原因，无法处理系统的任务

• 系统性能问题，同一时间系统运行多个程序，造成CPU占用太高，俗称CPU饥饿。
• 特殊情况， 系统向程序发送输入事件，但是由于特殊原因（管道坏掉等），造成程序无法处理。

ANR设置原理

ANR其实就是在SystemServer进程，在下面三个响应的处理Service里面设置timer，当timer时间到达，没有得到响应，编弹出ANR提示，可以让用户kill掉目标进程，来确保系统运行正常， 它一般流程为"埋炸弹"，“拆炸弹”， “引爆炸弹”；

• KeyDispatchTimeout
  key的流程是在systemServer调用inputReader和InPutDispatcher两个线程，InputReader负责从EventHub中读取key事件，通过notify的方式，唤醒inputDispatcher线程，并通过inputDispatcher进行分发到应用进程；
  keyDispatch的ANR区间是inputDispatcher中findFocusedWindowTargetsLocked到下一次执行resetANRTimeoutsLocked的时候；

拆炸弹
void InputDispatcher::resetANRTimeoutsLocked() {
    // Reset input target wait timeout.
    mInputTargetWaitCause = INPUT_TARGET_WAIT_CAUSE_NONE;
    mInputTargetWaitApplicationHandle.clear();
}
引爆炸弹
在findFocusedWindowTargetsLocked里面， 如果mFocusedWindowHandle == NULL ,则调用handleTargetsNotReadyLocked来进行处理，如果时间超过5S，则进入anr,ANR通过jni的方式最终调用到AMS的inputDispatchingTimedOut来执行ANR；

• BroadcastTimeout

埋炸弹和拆炸弹
BroadcastQueue.java
final void processNextBroadcast(boolean fromMsg) {
//broadcast的埋炸弹和拆炸弹都在这个函数里面
  if (r.receivers == null || r.nextReceiver >= numReceivers
                        || r.resultAbort || forceReceive) {
    cancelBroadcastTimeoutLocked();//拆炸弹
  }
  if (! mPendingBroadcastTimeoutMessage) {
    setBroadcastTimeoutLocked(timeoutTime); //埋炸弹
  }
}

引爆炸弹
BroadcastQueue.java
final void broadcastTimeoutLocked(boolean fromMsg) {
    if (anrMessage != null) {
            // Post the ANR to the handler since we do not want to process ANRs while
            // potentially holding our lock. 
            mHandler.post(new AppNotResponding(app, anrMessage));//进入anr处理
    }
}

• ServiceTimeout

埋炸弹
private final void realStartServiceLocked(ServiceRecord r,ProcessRecord app, boolean execInFg) throws RemoteException {
    bumpServiceExecutingLocked(r, execInFg, "create");
}
private final void bumpServiceExecutingLocked(ServiceRecord r, boolean fg, String why) {
  scheduleServiceTimeoutLocked(r.app);
}
void scheduleServiceTimeoutLocked(ProcessRecord proc) {
  //就是这边， 定时发送一个message,如果一定时间内，不clear掉，将会执行对应的函数引爆
  mAm.mHandler.sendMessageAtTime(msg proc.execServicesFg ? (now+SERVICE_TIMEOUT) : (now+ SERVICE_BACKGROUND_TIMEOUT));
}

拆炸弹
应用进程创建Service的时候， 通过 Binder调用serviceDoneExecuting；
private void handleCreateService(CreateServiceData data) {
   ActivityManagerNative.getDefault().serviceDoneExecuting(data.token, SERVICE_DONE_EXECUTING_ANON, 0, 0);
}
ActivityManagerService.java
public void serviceDoneExecuting(IBinder token, int type, int startId, int res) {
    mServices.serviceDoneExecutingLocked((ServiceRecord)token, type, startId, res);
}
ActiveServices.java
void serviceDoneExecutingLocked(ServiceRecord r, int type, int startId, int res) {
    serviceDoneExecutingLocked(r, inDestroying, inDestroying);
}

private void serviceDoneExecutingLocked(ServiceRecord r, boolean inDestroying,
            boolean finishing) {
    //这边remove掉message,所有， 如果在20S 内，中途有任何block的，造成这边没有remove ,便会引起anr
    mAm.mHandler.removeMessages(ActivityManagerService.SERVICE_TIMEOUT_MSG, r.app);
}

引爆炸弹
如果message没有被remove，这执行对应的handler;
ActivityManagerService.java
case SERVICE_TIMEOUT_MSG: {
      mServices.serviceTimeout((ProcessRecord)msg.obj);
} break;

void serviceTimeout(ProcessRecord proc) {
        //弹出提示,用户可以kill掉进程
        if (anrMessage != null) {
            mAm.mAppErrors.appNotResponding(proc, null, null, false, anrMessage);
        }
}

ANR问题分析步骤

• 查看main_log，查找关键字"ANR in",查看event log，查找关键字"am_anr"，可以找到对应anr的信息；
• 在main log中查看当时的CPU使用情况，是否占用过高，造成CPU饥饿；
• 查看 IOwait，是否是因为IO操作造成anr
• 查看发生时的data/anr/traces.txt,找到对应的anr进程，查看main线程的堆栈；
• 初步定为线程是因为阻塞，死锁等问题，查看栈顶是否有wait,sleep等进程操作，是否有Binder操作， 因为binder是同步的，所以如果binder另一端出现问题，得不到返回，这边就一直等待了，是否有网络数据库等操作（这些占时操作尽量放到子线程）；
• 根据堆栈的函数，结合log推测当时的情况；

ANR实例分析

(1)主线程执行耗时操作

• 问题描述
  在Setting数据流量的菜单，选择"限制后台流量"，出现ANR;
• 问题分析
  main log

01-21 18:37:20.918 E/ActivityManager(  830): ANR in com.android.settings (com.android.settings/.SubSettings)
01-21 18:37:20.918 E/ActivityManager(  830): PID: 1111
01-21 18:37:20.918 E/ActivityManager(  830): Reason: Input dispatching timed out (Waiting to send non-key event because the touched window has not finished processing certain input events that were delivered to it over 500.0ms ago.  Wait queue length: 11.  Wait queue head age: 5599.9ms.)
01-21 18:37:20.918 E/ActivityManager(  830): Load: 7.01 / 3.19 / 1.21
01-21 18:37:20.918 E/ActivityManager(  830): CPU usage from 22ms to -5294ms ago:
01-21 18:37:20.918 E/ActivityManager(  830):   69% 830/system_server: 32% user + 36% kernel / faults: 15796 minor 50 major

traces log

DALVIK THREADS (22):
"main" prio=5 tid=1 Native
  | group="main" sCount=1 dsCount=0 obj=0x7548dfb8 self=0x55773a16a0
  | sysTid=3374 nice=0 cgrp=apps sched=0/0 handle=0x7f87c54150
  | state=S schedstat=( 11692707735 13876692717 17098 ) utm=936 stm=233 core=0 HZ=100
  | stack=0x7fc8ba3000-0x7fc8ba5000 stackSize=8MB
  | held mutexes=
  kernel: (couldn't read /proc/self/task/3374/stack)
  native: #00 pc 0005f234  /system/lib64/libc.so (__ioctl+4)
  native: #01 pc 00068758  /system/lib64/libc.so (ioctl+100)
  native: #02 pc 00027544  /system/lib64/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+164)
  native: #03 pc 00027fa4  /system/lib64/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+112)
  native: #04 pc 00028218  /system/lib64/libbinder.so (android::IPCThreadState::transact(int, unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+176)
  native: #05 pc 0001ff18  /system/lib64/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+64)
  native: #06 pc 000d9a48  /system/lib64/libandroid_runtime.so (???)
  native: #07 pc 00fd580c  /data/dalvik-cache/arm64/system@framework@boot.oat (Java_android_os_BinderProxy_transactNative__ILandroid_os_Parcel_2Landroid_os_Parcel_2I+212)
  at android.os.BinderProxy.transactNative(Native method)
  at android.os.BinderProxy.transact(Binder.java:496)
  at android.net.INetworkPolicyManager$Stub$Proxy.setRestrictBackground(INetworkPolicyManager.java:454)
  at android.net.NetworkPolicyManager.setRestrictBackground(NetworkPolicyManager.java:169)

根据之前的分析流程,得出下面的结论：
(1) anr发生在com.android.settings
(2) CPU和IO都正常
(3) 查看trace，main线程没有发生死锁，wait, sleep这些；
(4) 从trace看，settings进程执行android.net.INetworkPolicyManager$Stub$Proxy.setRestrictBackground，怀疑是不是这个函数耗时太多；
(5) 查看代码

//函数setRestrictBackground,在做个什么鬼，经过检测，发现果然是这个函数耗费时间长，把他放到子线程；
public void setRestrictBackground(boolean restrictBackground) {
        mPolicyManager.setRestrictBackground(restrictBackground);
        updateMenuTitles();
}

//option执行，点击菜单就只调用了setRestrictBackground
public boolean onOptionsItemSelected(MenuItem item) {
    switch (item.getItemId()) {
        case R.id.data_usage_menu_restrict_background: {
             setRestrictBackground(false);
        }
    }
}

• 解决方案
  将mPolicyManager.setRestrictBackground(restrictBackground);放到子线程处理

    public class RestrictBackgroundTask extends AsyncTask<DataUsageSummary, Void, Void>{
        private boolean restrictBackground;
        public  RestrictBackgroundTask(boolean restrictBackground){
            this.restrictBackground = restrictBackground;
        }
 
        @Override
        protected Void doInBackground(DataUsageSummary... params) {
            mPolicyManager.setRestrictBackground(restrictBackground);
            return null;
        }
            
    }
   
   public void setRestrictBackground(boolean restrictBackground) {
        mRestrictBackgroundTask = new RestrictBackgroundTask(restrictBackground);
        mRestrictBackgroundTask.execute(this);//开起线程处理
        updateMenuTitles();
    }

(2)主线程死锁

• 问题描述
  音乐中删除记录时出现anr;

• 问题分析
  这个问题只抓到了trace.txt，不过惊喜的是， trace居然能直接看出问题；

DALVIK THREADS (22):
"main" prio=5 tid=1 TimedWaiting
  | group="main" sCount=1 dsCount=0 obj=0x752ccfb8 self=0x559e6b26a0
  | sysTid=3078 nice=0 cgrp=apps/bg_non_interactive sched=0/0 handle=0x7f81cd4150
  | state=S schedstat=( 521831915 7324195292 1199 ) utm=46 stm=6 core=3 HZ=100
  | stack=0x7fec70d000-0x7fec70f000 stackSize=8MB
  | held mutexes=
  at java.lang.Object.wait!(Native method)
  - waiting on <0x2f38fd73> (a java.lang.Object)
  at java.lang.Thread.parkFor(Thread.java:1220)
  - locked <0x2f38fd73> (a java.lang.Object)
  at sun.misc.Unsafe.park(Unsafe.java:299)
  at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:197)
  at android.database.sqlite.SQLiteConnectionPool.waitForConnection(SQLiteConnectionPool.java:670)
  at android.database.sqlite.SQLiteConnectionPool.acquireConnection(SQLiteConnectionPool.java:348)
  at android.database.sqlite.SQLiteSession.acquireConnection(SQLiteSession.java:894)
  at android.database.sqlite.SQLiteSession.prepare(SQLiteSession.java:586)
  at android.database.sqlite.SQLiteProgram.<init>(SQLiteProgram.java:58)
  at android.database.sqlite.SQLiteStatement.<init>(SQLiteStatement.java:31)
  at android.database.sqlite.SQLiteDatabase.updateWithOnConflict(SQLiteDatabase.java:1574)
  at android.database.sqlite.SQLiteDatabase.update(SQLiteDatabase.java:1522)
  at com.android.providers.media.MediaProvider$2.onReceive(MediaProvider.java:351)
  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:861)
  at android.os.Handler.handleCallback(Handler.java:739)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5221)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:898)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:693)

main线程居然是TimedWaiting;
TIMED_WAITING 这个状态就是有限的(时间限制)的WAITING, 一般出现在调用wait(long), join(long)等情况下, 另外一个线程sleep后, 也会进入TIMED_WAITING状态

private SQLiteConnection waitForConnection(String sql, int connectionFlags,
       CancellationSignal cancellationSignal) {
       // Wait to be unparked (may already have happened), a timeout, or interruption.
       LockSupport.parkNanos(this, busyTimeoutMillis * 1000000L); //这边就wait掉了
}

• 解决方案
  本着尽量在上层进行修改的原则，我们还是选择规避该问题， 在上层
  “ at com.android.providers.media.MediaProvider$2.onReceive(MediaProvider.java:351)”的时候不去调用update,理论上， 当前情况也不需要update;

主线程循环调用sleep，造成主线程处于sleep状态

• 问题描述
  打开Call->在dial pad中输入“*#2886# ”->进入factory mode，按返回键，出现MMI ANR
• 问题分析
  main log: anr发生在 mmi进程，CPU和IO 正常， 进程ID2148， Input Dispatching ANR；

02-10 13:57:06.492 E/ActivityManager(  884): ANR in com.android.mmi (com.android.mmi/.MMITest)
02-10 13:57:06.492 E/ActivityManager(  884): PID: 2148
02-10 13:57:06.492 E/ActivityManager(  884): Reason: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)
02-10 13:57:06.492 E/ActivityManager(  884): Load: 7.08 / 4.38 / 4.11
02-10 13:57:06.492 E/ActivityManager(  884): CPU usage from 4399ms to -5752ms ago:
02-10 13:57:06.492 E/ActivityManager(  884):   35% 884/system_server: 16% user + 19% kernel / faults: 7913 minor 124 major
02-10 13:57:06.492 E/ActivityManager(  884):   27% 1845/com.android.phone: 15% user + 12% kernel / faults: 5880 minor 50 major
02-10 13:57:06.492 E/ActivityManager(  884):   26% 256/logd: 22% user + 4.2% kernel / faults: 4 minor
02-10 13:57:06.492 E/ActivityManager(  884):   11% 1532/com.android.systemui: 5.7% user + 5.3% kernel / faults: 3579 minor 76 major
02-10 13:57:06.492 E/ActivityManager(  884):   8.4% 296/rild: 7% user + 1.4% kernel / faults: 34 minor 1 major
02-10 13:57:06.492 E/ActivityManager(  884):   4.6% 1027/logcat: 1.6% user + 2.9% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 295/debuggerd: 0% user + 0% kernel / faults: 3166 minor 33 major
02-10 13:57:06.492 E/ActivityManager(  884):   2.5% 259/servicemanager: 0.5% user + 1.9% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   1% 1791/com.android.server.telecom: 0.3% user + 0.6% kernel / faults: 2209 minor 181 major
02-10 13:57:06.492 E/ActivityManager(  884):   1.9% 184/mmcqd/0: 0% user + 1.9% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   1.6% 1810/com.android.nfc: 1% user + 0.5% kernel / faults: 1849 minor 155 major
02-10 13:57:06.492 E/ActivityManager(  884):   1.2% 1017/reporthelper: 0% user + 1.2% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   1.2% 2148/com.android.mmi: 0.8% user + 0.3% kernel / faults: 1199 minor 56 major
02-10 13:57:06.492 E/ActivityManager(  884):   0.2% 22257/com.qualcomm.telephony: 0% user + 0.1% kernel / faults: 2242 minor 26 major
02-10 13:57:06.492 E/ActivityManager(  884):   1% 379/qmuxd: 0.5% user + 0.4% kernel / faults: 1 minor
02-10 13:57:06.492 E/ActivityManager(  884):   0.9% 261/surfaceflinger: 0.2% user + 0.6% kernel / faults: 26 minor 3 major
02-10 13:57:06.492 E/ActivityManager(  884):   0.3% 1828/com.android.dlnaservice: 0% user + 0.3% kernel / faults: 1548 minor 48 major
02-10 13:57:06.492 E/ActivityManager(  884):   0.8% 31309/kworker/0:2: 0% user + 0.8% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.7% 158/cfinteractive: 0% user + 0.7% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.6% 103/kswapd0: 0% user + 0.6% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.3% 323/sdcard: 0% user + 0.3% kernel / faults: 3 minor
02-10 13:57:06.492 E/ActivityManager(  884):   0.3% 1341/com.tct.calendar: 0% user + 0.2% kernel / faults: 892 minor
02-10 13:57:06.492 E/ActivityManager(  884):   0.3% 2226/com.google.android.apps.plus: 0.2% user + 0% kernel / faults: 964 minor
02-10 13:57:06.492 E/ActivityManager(  884):   0.2% 2441/com.google.process.location: 0.2% user + 0% kernel / faults: 594 minor 8 major
02-10 13:57:06.492 E/ActivityManager(  884):   0% 20346/VosMCThread: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 27/kworker/1:1: 0% user + 0.1% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.2% 33/kworker/u9:0: 0% user + 0.2% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.2% 316/zygote: 0.2% user + 0% kernel / faults: 1521 minor
02-10 13:57:06.492 E/ActivityManager(  884):   0.2% 1829/com.google.android.gm: 0.1% user + 0% kernel / faults: 546 minor 4 major
02-10 13:57:06.492 E/ActivityManager(  884):   0.2% 31286/kworker/u8:2: 0% user + 0.2% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 3/ksoftirqd/0: 0% user + 0.1% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 8/rcu_preempt: 0% user + 0.1% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 12/ksoftirqd/1: 0% user + 0.1% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 16/ksoftirqd/2: 0% user + 0.1% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 2196/com.tct.gallery3d: 0% user + 0% kernel / faults: 712 minor
02-10 13:57:06.492 E/ActivityManager(  884):   0.1% 11789/kworker/u8:12: 0% user + 0.1% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 20/ksoftirqd/3: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 258/lmkd: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 298/mediaserver: 0% user + 0% kernel / faults: 20 minor 5 major
02-10 13:57:06.492 E/ActivityManager(  884):   0% 1863/com.tct.launcher: 0% user + 0% kernel / faults: 144 minor 1 major
02-10 13:57:06.492 E/ActivityManager(  884):   0% 20347/VosTXThread: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 20348/VosRXThread: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 20369/wpa_supplicant: 0% user + 0% kernel / faults: 254 minor 8 major
02-10 13:57:06.492 E/ActivityManager(  884):   0% 22016/com.tct.weather: 0% user + 0% kernel / faults: 1168 minor 9 major
02-10 13:57:06.492 E/ActivityManager(  884):   0% 23402/kworker/2:1: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 31280/mdss_fb0: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 31308/kworker/u8:3: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   0% 31372/kworker/1:0: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):  +0% 2278/com.android.providers.calendar: 0% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884): 36% TOTAL: 18% user + 15% kernel + 1.4% iowait + 0.9% softirq
02-10 13:57:06.492 E/ActivityManager(  884): CPU usage from 5049ms to 5578ms later:
02-10 13:57:06.492 E/ActivityManager(  884):   56% 256/logd: 43% user + 13% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     43% 1032/logd.reader.per: 30% user + 13% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     15% 276/logd.writer: 11% user + 3.7% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   37% 1845/com.android.phone: 33% user + 3.7% kernel / faults: 36 minor
02-10 13:57:06.492 E/ActivityManager(  884):     5.6% 1860/Binder_1: 5.6% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     5.6% 3572/Binder_6: 3.7% user + 1.8% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     5.6% 6834/Binder_7: 5.6% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     3.7% 1845/m.android.phone: 3.7% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     3.7% 2153/Binder_3: 1.8% user + 1.8% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     3.7% 2167/Binder_4: 3.7% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     3.7% 2627/Binder_5: 3.7% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     3.7% 6835/Binder_8: 3.7% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):     1.8% 1974/RILReceiver: 1.8% user + 0% kernel
02-10 13:57:06.492 E/ActivityManager(  884):   12% 1532/com.android.systemui: 7.6% user + 5.1% kernel
02-10 13:57:06.492 D/SubController( 1845): StackTrace - [getPhoneId] subId=-2

traces log: 主线程Sleeping, 看调用堆栈的地方，居然有Thread.sleep,查看代码，看哪里调用到sleep；

"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 obj=0x74b7cbc0 self=0xb88d0088
  | sysTid=17967 nice=0 cgrp=apps sched=0/0 handle=0xb6f21ec8
  | state=S schedstat=( 76988439 75071667 165 ) utm=3 stm=4 core=1 HZ=100
  | stack=0xbe6d5000-0xbe6d7000 stackSize=8MB
  | held mutexes=
  at java.lang.Thread.sleep!(Native method)
  - sleeping on <0x2ea0c232> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:1031)
  - locked <0x2ea0c232> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:985)
  at android.os.SystemClock.sleep(SystemClock.java:125)
  at com.android.mmi.util.JRDClient.<init>(JRDClient.java:72)
  at com.android.mmi.traceability.TraceabilityStruct.<init>(TraceabilityStruct.java:51)
  at com.android.mmi.util.TestItemManager.isDoubleSim(TestItemManager.java:177)
  at com.android.mmi.util.TestItemManager.LoadStaticTestItems(TestItemManager.java:141)
  at com.android.mmi.util.TestItemManager.InitStaticInfo(TestItemManager.java:95)
  at com.android.mmi.CommonActivity.onCreate(CommonActivity.java:64)
  at com.android.mmi.MMITest.onCreate(MMITest.java:43)
  at android.app.Activity.performCreate(Activity.java:5976)
  at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1105)
  at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2262)
  at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2371)
  at android.app.ActivityThread.access$800(ActivityThread.java:149)
  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1289)
  at android.os.Handler.dispatchMessage(Handler.java:102)
  at android.os.Looper.loop(Looper.java:135)
  at android.app.ActivityThread.main(ActivityThread.java:5260)
  at java.lang.reflect.Method.invoke!(Native method)
  at java.lang.reflect.Method.invoke(Method.java:372)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:898)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:693)

• 代码分析

private static boolean LoadStaticTestItems(Context context, String product) {
    for(String item : maxItemsArray) {    //在for循环中调用(isDoubleSim() || getBoardId() == 1)
         if((isDoubleSim() || getBoardId() == 1)){  //堆栈信息可以看出，这个里面调用到了JRDClient
             if(itemInfo[0].trim().equals("Memory Card")){
                 itemHash.put("deftype", "0");
        }
    }
  }
}
//JRDClient构造函数里面有做500ms的sleep， 联系之前的代码，这个是放到一个for循环里面的， 这样就会造成主线程一直处于sleep,造成ANR；
public JRDClient() {
        //mSocket = new LocalSocket();
        if (android.os.SystemProperties.get("init.svc.tctd") != "running") {
            android.os.SystemProperties.set("ctl.start", "tctd");
            SystemClock.sleep(500);
        }
    }

• 解决方案
  将Thread.sleep相关的代码拉出for循环：

private static boolean LoadStaticTestItems(Context context, String product) {
    boolean flag = (isDoubleSim() || getBoardId() == 1);
    for(String item : maxItemsArray) {   
         if(flag){ //这边调用flag值，这样不会循环调用isDoubleSim了
           if(itemInfo[0].trim().equals("Memory Card")){
             itemHash.put("deftype", "0");
          }
        }
    }
}

最后贴上相应的思维导图：

ANR分析.png