devbox
小丑西瓜9
这个屌丝很懒，什么也没留下！
关注作者
热门标签
热门文章
当前位置:   article > 正文

应用与系统稳定性第一篇---ANR问题分析的一般套路_6.6% 20117/com.android.launcher3: 5.2% user + 1.4%

作者：小丑西瓜9 | 2024-03-22 14:08:58

赞

踩

6.6% 20117/com.android.launcher3: 5.2% user + 1.4% kernel / faults: 6674 min

 

ANR（App Not Responding）基本上99%的App都有，即使是系统，也有system_anr，我相信虽然ANR问题这样的普遍，还是有很多人对ANR问题即熟悉又陌生的，ANR中log信息怎么看？发生的场景有哪些？广播会发生ANR吗？我的App啥事都没有干怎么发生了ANR了等等一些问题，今天通过三个案例总结一下ANR问题分析的一般套路，以做备忘。

一、ANR初步了解

1、发生原因

一句话总结：没有在规定的时间内，干完要干的事情，就会发生ANR。

2、ANR分类

从发生的场景分类：

  • Input事件超过5s没有被处理完
  • Service处理超时，前台20s，后台200s
  • BroadcastReceiver处理超时，前台10S，后台60s
  • ContentProvider执行超时，比较少见

从发生的原因分：

  • 主线程有耗时操作，如有复杂的layout布局，IO操作等。
  • 被Binder对端block
  • 被子线程同步锁block
  • Binder被占满导致主线程无法和SystemServer通信
  • 得不到系统资源（CPU/RAM/IO）

从进程的角度分：

  • 问题出在当前进程:
    主线程本身耗时, 或则主线程的消息队列存在耗时操作;
    主线程被本进程的其他子线程所blocked;
  • 问题出在远端进程(一般是binder call或socket等通信方式)

二、ANR的Log解读

2.1、Log获取

发生了ANR问题，通常会抓一份bugreport

 

adb bugreprot  xxx

最为重要的是，生成的bugreport有anr的trace，如果要单独拿出来也行

 

adb pull /data/anr/traces.txt  xxx

一份完整的bugreport包含下面的信息，对分析ANR问题很关键

Log名称作用获取命令
system.log包含ANR发生时间点信息、ANR发生前的CPU信息,还包含大量系统服务输出的信息adb logcat –b system
main.log包含ANR发生前应用自身输出的信息,可供分析应用是否有异常;此外还包含输出的GC信息，可供分析内存回收的速度,判断系统是否处于低内存或内存碎片化状态adb logcat –b main
event.log包含AMS与WMS输出的应用程序声明周期信息,可供分析窗口创建速度以及焦点转换情况adb logcat –b 　event
kernel.log包含kernel打出的信息,LowMemoryKiller杀进程、内存碎片化或内存不足,mmc驱动异常都可以在这里找到。无

那么这些Log怎么看呢？看下面案例一

2.1、案例一：sp耗时问题导致应用ANR

一般先搜索ANR in获取最直观的信息，如下：

 

  1. 06-16 16:16:28.590  1853  2073 E ActivityManager: ANR in com.android.camera (com.android.camera/.Camera)
  2. 06-16 16:16:28.590  1853  2073 E ActivityManager: PID: 27661
  3. 06-16 16:16:28.590  1853  2073 E ActivityManager: Reason: Input dispatching timed out (com.android.camera/com.android.camera.Camera, 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: 24.  Wait queue head age: 5511.1ms.)
  4. 06-16 16:16:28.590  1853  2073 E ActivityManager: Load: 16.25 / 29.48 / 38.33
  5. 06-16 16:16:28.590  1853  2073 E ActivityManager: CPU usage from 0ms to 8058ms later:
  6. 06-16 16:16:28.590  1853  2073 E ActivityManager:   58% 291/mediaserver: 51% user + 6.7% kernel / faults: 2457 minor 4 major
  7. 06-16 16:16:28.590  1853  2073 E ActivityManager:   27% 317/mm-qcamera-daemon: 21% user + 5.8% kernel / faults: 15965 minor
  8. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.4% 288/debuggerd: 0% user + 0.3% kernel / faults: 21615 minor 87 major
  9. 06-16 16:16:28.590  1853  2073 E ActivityManager:   17% 27661/com.android.camera: 10% user + 6.8% kernel / faults: 2412 minor 34 major
  10. 06-16 16:16:28.590  1853  2073 E ActivityManager:   16% 1853/system_server: 10% user + 6.4% kernel / faults: 1754 minor 87 major
  11. 06-16 16:16:28.590  1853  2073 E ActivityManager:   10% 539/sensors.qcom: 7.8% user + 2.6% kernel / faults: 16 minor
  12. 06-16 16:16:28.590  1853  2073 E ActivityManager:   4.4% 277/surfaceflinger: 1.8% user + 2.6% kernel / faults: 14 minor
  13. 06-16 16:16:28.590  1853  2073 E ActivityManager:   4% 203/mmcqd/0: 0% user + 4% kernel
  14. 06-16 16:16:28.590  1853  2073 E ActivityManager:   2.6% 3510/com.android.phone: 1.9% user + 0.6% kernel / faults: 1148 minor 8 major
  15. 06-16 16:16:28.590  1853  2073 E ActivityManager:   2.1% 2902/com.android.systemui: 1.6% user + 0.4% kernel / faults: 1272 minor 32 major
  16. 06-16 16:16:28.590  1853  2073 E ActivityManager:   1.6% 3110/com.miui.whetstone: 1.6% user + 0% kernel / faults: 2614 minor 22 major
  17. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.8% 99/kswapd0: 0% user + 0.8% kernel
  18. 06-16 16:16:28.590  1853  2073 E ActivityManager:   1.4% 217/jbd2/mmcblk0p25: 0% user + 1.4% kernel
  19. 06-16 16:16:28.590  1853  2073 E ActivityManager:   1.4% 223/logd: 0.7% user + 0.7% kernel / faults: 4 minor
  20. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.9% 12808/kworker/0:1: 0% user + 0.9% kernel
  21. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.8% 35/kworker/u:2: 0% user + 0.8% kernel
  22. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0% 3222/com.miui.sysbase: 0% user + 0% kernel / faults: 1314 minor 12 major
  23. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.8% 3446/com.android.nfc: 0.4% user + 0.3% kernel / faults: 1223 minor 9 major
  24. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.7% 10866/kworker/u:1: 0% user + 0.7% kernel
  25. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.6% 642/mdss_fb0: 0% user + 0.6% kernel
  26. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.6% 29336/kworker/u:7: 0% user + 0.6% kernel
  27. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.4% 6/kworker/u:0: 0% user + 0.4% kernel
  28. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.4% 22924/kworker/u:6: 0% user + 0.4% kernel
  29. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.3% 4421/mpdecision: 0% user + 0.3% kernel
  30. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.2% 276/servicemanager: 0.1% user + 0.1% kernel
  31. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.2% 289/rild: 0.2% user + 0% kernel / faults: 20 minor
  32. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 4161/mcd: 0% user + 0% kernel / faults: 9 minor 1 major
  33. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 3/ksoftirqd/0: 0% user + 0.1% kernel
  34. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 5/kworker/0:0H: 0% user + 0.1% kernel
  35. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 7/kworker/u:0H: 0% user + 0.1% kernel
  36. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0% 215/flush-179:0: 0% user + 0% kernel
  37. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 321/displayfeature: 0.1% user + 0% kernel
  38. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 368/irq/33-cpubw_hw: 0% user + 0.1% kernel
  39. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 403/qmuxd: 0% user + 0.1% kernel / faults: 60 minor
  40. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0% 3491/com.xiaomi.finddevice: 0% user + 0% kernel / faults: 706 minor
  41. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.1% 29330/ksoftirqd/1: 0% user + 0.1% kernel
  42. 06-16 16:16:28.590  1853  2073 E ActivityManager: 96% TOTAL: 56% user + 29% kernel + 6.3% iowait + 4.1% softirq

遇到ANR问题，摆在我们面前的trace是不是第一案发现场，如果ANR发生的输出的信息很多，当时的CPU和I/O资源比较紧张，那么这段日志输出的时间点可能会延迟10秒到20秒都有可能，所以我们有时候需要提高警惕，现在举例逐行解读一下：

 

06-16 16:16:28.590  1853  2073 E ActivityManager: ANR in com.android.camera (com.android.camera/.Camera)

这一行得知ANR发生的时间是06-16 16:16:28.590，发生的进程是com.android.camera ，具体在com.android.camera/.Camera，其中1853是systemserver的pid，2073是ActivityManager线程的pid，ActivityManager是一个系统线程。其实在Events log中也有对应的信息，搜索关键字am_anr

 

06-16 16:16:20.536  1853  2073 I am_anr  : [0,27661,com.android.camera,952745541,Input dispatching timed out (com.android.camera/com.android.camera.Camera, 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: 24.  Wait queue head age: 5511.1ms.)]

由此同样可以确定ANR的时间点，类型，进程pid，进程名称等，继续看下一行

 

06-16 16:16:28.590  1853  2073 E ActivityManager: PID: 27661

这一行得知ANR进程的pid是27661，特殊情况，如果pid为0，说明在发生ANR之前，这个进程就被LowMemoryKiller杀死了或者出现了Crash，这种情况下，是无法接收到系统的广播或者按键消息的，故出现ANR

 

06-16 16:16:28.590  1853  2073 E ActivityManager: Reason: Input dispatching timed out (com.android.camera/com.android.camera.Camera, 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: 24.  Wait queue head age: 5511.1ms.)

这一行得知ANR发生的原因是Input dispatching timed out

 

06-16 16:16:28.590  1853  2073 E ActivityManager: Load: 16.25 / 29.48 / 38.33

这行得知Cpu的负载，在Linux操作系统上，输入uptime也能得到一段时间的负载。

 

  1. wangjing@wangjing-OptiPlex-7050:~$ uptime
  2. 20:09:54 up 71 days, 10:48,  1 user,  load average: 0.99, 0.78, 0.86

那么负载是什么意思呢？Load后面的三个数字的意思分别是1分钟、5分钟、15分钟内系统的平均负荷。当CPU完全空闲的时候，平均负荷为0；当CPU工作量饱和的时候，平均负荷为1，通过Load可以判断系统负荷是否过重。有一个形象的比喻：个CPU想象成一座大桥，桥上只有一根车道，所有车辆都必须从这根车道上通过，系统负荷为0，意味着大桥上一辆车也没有，系统负荷为0.5，意味着大桥一半的路段有车，系统负荷为1.0，意味着大桥的所有路段都有车，也就是说大桥已经"满"了，系统负荷为2.0，意味着车辆太多了，大桥已经被占满了（100%），后面等着上桥的车辆还有一倍。大桥的通行能力，就是CPU的最大工作量；桥梁上的车辆，就是一个个等待CPU处理的进程（process）。

经验法则是这样的：
当系统负荷持续大于0.7，你必须开始调查了，问题出在哪里，防止情况恶化。
当系统负荷持续大于1.0，你必须动手寻找解决办法，把这个值降下来。
当系统负荷达到5.0，就表明你的系统有很严重的问题

而我们现在的手机是多核CPU架构，八核的多的是，意味着Cpu处理的能力就乘以了８，每个核运行的时间可以从下面的文件中得到，/sys/devices/system/cpu/cpu%d/cpufreq/stats/time_in_state 中读取的，%d代表是CPU的核。文件中记录了 CPU 从开机到读取文件时，在各个频率下的运行时间，单位：10 mS。

 

  1. 使用adb shell cat /sys/devices/system/cpu/cpu1/cpufreq/stats/time_in_state查看
  2. 频度       时间
  3. 652800 1813593
  4. 1036800 46484
  5. 1401600 521974
  6. 1689600 2956667
  7. 1843200 83065
  8. 1958400 53516
  9. 2016000 251693

关于负荷详细的可以看理解Linux系统负荷，不过多扩展。

 

  1. 06-16 16:16:28.590  1853  2073 E ActivityManager: CPU usage from 0ms to 8058ms later:
  2. 06-16 16:16:28.590  1853  2073 E ActivityManager:   58% 291/mediaserver: 51% user + 6.7% kernel / faults: 2457 minor 4 major
  3. 06-16 16:16:28.590  1853  2073 E ActivityManager:   27% 317/mm-qcamera-daemon: 21% user + 5.8% kernel / faults: 15965 minor
  4. 06-16 16:16:28.590  1853  2073 E ActivityManager:   0.4% 288/debuggerd: 0% user + 0.3% kernel / faults: 21615 minor 87 major
  5. 06-16 16:16:28.590  1853  2073 E ActivityManager:   17% 27661/com.android.camera: 10% user + 6.8% kernel / faults: 2412 minor 34 major
  6. ....
  7. 06-16 16:16:28.590  1853  2073 E ActivityManager: 96% TOTAL: 56% user + 29% kernel + 6.3% iowait + 4.1% softirq
  8. .....

这一段日志可以得到ANR发生的时候，Top进程的Cpu占用情况，user代表是用户空间，kernel是内核空间，一般的有如下的规律。

  • kswapd0 cpu占用率偏高，系统整体运行会缓慢，从而引起各种ANR。把问题转给"内存优化"，请他们进行优化。

  • logd　CPU占用率偏高，也会引起系统卡顿和ANR，因为各个进程输出LOG的操作被阻塞从而执行的极为缓慢。

  • Vold占用CPU过高，会引起系统卡顿和ANR，请负责存储的同学先调查

  • qcom.sensor CPU占用率过高，会引起卡顿，请系统同学调查

  • 应用自身CPU占用率较高，高概率应用自身问题

  • 系统CPU占用率不高，但主线程在等待一个锁，高概率应用自身问题

  • 应用处于D状态，发生ANR，如果最后的操作是refriger，那么是应用被冻结了，正常情况下是功耗优化引起的。

好了，通过上面的日志我们得到了ANR的基本信息，要得到阻塞的地方，还要靠trace文件。一般都在anr目录下。在这个trace文件中搜索主线程的堆栈，如下：

 

  1. ----- pid 27661 at 2017-06-16 16:16:20 -----
  2. Cmd line: com.android.camera
  3. "main" prio=5 tid=1 Waiting
  4.  | group="main" sCount=1 dsCount=0 obj=0x75a4b5c8 self=0xb4cf6500
  5.  | sysTid=27661 nice=-10 cgrp=default sched=0/0 handle=0xb6f6cb34
  6.  | state=S schedstat=( 11242036155 8689191757 38520 ) utm=895 stm=229 core=0 HZ=100
  7.  | stack=0xbe4ea000-0xbe4ec000 stackSize=8MB
  8.  | held mutexes=
  9.  at java.lang.Object.wait!(Native method)
  10.  - waiting on <0x09e6a059> (a java.lang.Object)
  11.  at java.lang.Thread.parkFor$(Thread.java:1220)
  12.  - locked <0x09e6a059> (a java.lang.Object)
  13.  at sun.misc.Unsafe.park(Unsafe.java:299)
  14.  at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
  15.  at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInterrupt(AbstractQueuedSynchronizer.java:810)
  16.  at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireSharedInterruptibly(AbstractQueuedSynchronizer.java:970)
  17.  at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireSharedInterruptibly(AbstractQueuedSynchronizer.java:1278)
  18.  at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:203)
  19.  at android.app.SharedPreferencesImpl$EditorImpl$1.run(SharedPreferencesImpl.java:366)
  20.  at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
  21.  at android.app.ActivityThread.handleStopActivity(ActivityThread.java:3605)
  22.  at android.app.ActivityThread.access$1300(ActivityThread.java:153)
  23.  at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1399)
  24.  at android.os.Handler.dispatchMessage(Handler.java:102)
  25.  at android.os.Looper.loop(Looper.java:154)
  26.  at android.app.ActivityThread.main(ActivityThread.java:5528)
  27.  at java.lang.reflect.Method.invoke!(Native method)
  28.  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:740)
  29.  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:630)

解读一下部分字段的含义

字段含义
tid=1线程号
sysTid=27661主线程的线程号和进程号相同
Waiting线程状态，其中state也是线程状态，如果state=D代表底层被blocked了。
nicenice值越小，则优先级越高。因为是主线程此处nice=-10, 可以看到优先级很高了
schedstat括号中的3个数字，依次是Running, Runable, Switch，Running时间。Running时间：CPU运行的时间，单位ns。 　Runable时间：RQ队列的等待时间，单位ns。　　Switch次数：CPU调度切换次数
utm该线程在用户态所执行的时间，单位是jiffies
stm该线程在内核态所执行的时间，单位是jiffies
sCount此线程被挂起的次数
dsCount线程被调试器挂起的次数，当一个进程被调试后，sCount会重置为0，调试完毕后sCount会根据是否被正常挂起增长，但是dsCount不会被重置为0，所以dsCount也可以用来判断这个线程是否被调试过
self线程本身的地址

在说一下线程的状态

状态值说明
THREAD_ZOMBIE0TERMINATED
THREAD_RUNNING1RUNNABLE or running now
THREAD_TIMED_WAIT2TIMED_WAITING in Object.wait()
THREAD_MONITOR3BLOCKED on a monitor
THREAD_INITIALIZING5allocated not yet running
THREAD_STARTING6started not yet on thread list
THREAD_NATIVE7off in a JNI native method
THREAD_VMWAIT8waiting on a VM resource
THREAD_SUSPENDED9suspended usually by GC or debugger

那么这个问题怎么搞呢，通过上面的基础介绍与trace文件，我们知道，blocked点是

 

  1.  at java.util.concurrent.CountDownLatch.await(CountDownLatch.java:203)
  2.  at android.app.SharedPreferencesImpl$EditorImpl$1.run(SharedPreferencesImpl.java:366)
  3.  at android.app.QueuedWork.waitToFinish(QueuedWork.java:88)
  4.  at android.app.ActivityThread.handleStopActivity(ActivityThread.java:3605)
  5.  at android.app.ActivityThread.access$1300(ActivityThread.java:153)

先来看QueuedWork.waitToFinish

 

  1. 77    /**
  2. 78     * Finishes or waits for async operations to complete.
  3. 79     * (e.g. SharedPreferences$Editor#startCommit writes)
  4. 80     *
  5. 81     * Is called from the Activity base class's onPause(), after
  6. 82     * BroadcastReceiver's onReceive, after Service command handling,
  7. 83     * etc.  (so async work is never lost)
  8. 84     */
  9. 85    public static void waitToFinish() {
  10. 86        Runnable toFinish;
  11. 　　　　　//等待所有等待完成的任务完成
  12. 87        while ((toFinish = sPendingWorkFinishers.poll()) != null) {
  13. 88            toFinish.run();
  14. 89        }
  15. 90    }

QueuedWork.waitToFinish会在Activity的onPause或者BroadcastReceiver的onReceive之后被调用，目的是确保异步任务执行完成．在waitToFinish中遍历sPendingWorkFinishers所有等待完成的任务，并等待他们的完成。在来看SharedPreferencesImpl.apply，这个方法里面会将等待写入到文件系统的任务放到QueuedWork的等待完成队列里

 

  1. 361        public void apply() {
  2. 362            final MemoryCommitResult mcr = commitToMemory();
  3. 363            final Runnable awaitCommit = new Runnable() {
  4. 364                    public void run() {
  5. 365                        try {
  6. 366                            mcr.writtenToDiskLatch.await();
  7. 367                        } catch (InterruptedException ignored) {
  8. 368                        }
  9. 369                    }
  10. 370                };
  11. 371
  12. 　　　　　//将等待写入到文件系统的任务放到QueuedWork的等待队列中
  13. 372            QueuedWork.add(awaitCommit);
  14. 373            ... ... ... ... ... ...
  15. 388        }

虽然apply方法本身可以很快返回，但是当Activity的onPause被调用时，会等待写入到文件系统的任务完成．也就是说，虽然apply本身不会阻塞调用线程，但是会将等待时间转嫁到主线程．因此，如果写入任务执行比较慢，activity, service, broadcast在生命周期结束时, sp操作没有完成,就会阻塞主线程造成ANR。分析到这里，明显是个系统问题了，而App也是无能为力，好在小米手机上已经缓解了这个问题，方案不透露了。一般的看trace有如下规律：

  • 发生ANR时，trace中找不到相应进程，检查一下Android Runtime是否因为应用的崩溃给ShutDown了，如果ShutDown了，此时要去查ShutDown的原因。

  • 应用发生ANR，如果主线程正在执行getContentProvider，那么它正在请求另一个应用的ContentProvider，此时要查一下目标ContentProvider的宿主进程，看看正在做什么

  • 主线程执行数据库操作或网络请求，应该是应用自身问题

  • 主线程等待其他线程持有的锁，而目标线程执行数据库操作或网络请求，那么是应用自身问题。

这里只是先搞一个案例熟悉一下ANR分析基本流程。到这里总结一下上面的套路：

  • 抓取bugreport，搜索ANR in，查看发生的时间和进程
  • 根据进程寻找主线程的trace，发现被blocked的地方
  • 结合源码进行分析解决
    当然通过这两个步骤就定位到ANR发生的原因，说明我们的运气比较好，然而大多数时候不是这个样子的。

上面我们分析了一个系统问题导致的ANR，这里你可能会想，我的app什么活都没有干，竟然发生ANR了，以后可以把锅直接甩给系统了，非也，具体问题还是要具体分析，怀疑系统，我们要有证据，证据从哪里来，还是从Log里面来，继续看第三节，系统耗时分析方案

三、系统耗时分析方案

系统做了一些耗时分析的操作，在一些手机厂商中，Log里面还有其他的加强，这里列举比较通用的一些

1.binder_sample

  • A.功能说明: 监控每个进程的主线程的binder transaction的耗时情况, 当超过阈值时,则输出相应的目标调用信息，默认1000ms打开。

  • B.log格式: 52004 binder_sample (descriptor|3),(method_num|1|5),(time|1|3),(blocking_package|3),(sample_percent|1|6)

  • C.log实例:

 

2754 2754 I binder_sample: [android.app.IActivityManager,35,2900,android.process.media,5]

从上面的log中可以得出
1.主线程2754;
2.执行android.app.IActivityManager接口

  1. 所对应方法code =35(即STOP_SERVICE_TRANSACTION),
  2. 所花费时间为2900ms.
  3. 该block所在package为 android.process.media，最后一个参数是sample比例(没有太大价值)

2、dvm_lock_sample

  • A.功能说明: 当某个线程等待lock的时间blocked超过阈值,则输出当前的持锁状态 ;
  • B.log格式: 20003 dvm_lock_sample (process|3),(main|1|5),(thread|3),(time|1|3),(file|3),(line|1|5),(ownerfile|3),(ownerline|1|5),(sample_percent|1|6)
  • C.log实例:

 

dvm_lock_sample: [system_server,1,Binder_9,1500,ActivityManagerService.java,6403,-,1448,0]

意思是system_server: Binder_9,执行到ActivityManagerService.java的6403行代码,一直在等待AMS锁, 而该锁所同一文件的1448行代码所持有, 从而导致Binder_9线程被阻塞1500ms.

3、 binder starved

  • A.功能说明: 当system_server等进程的线程池使用完, 无空闲线程时, 则binder通信都处于饥饿状态, 则饥饿状态超过一定阈值则输出信息;
  • B.云控参数: persist.sys.binder.starvation (默认值16ms)
  • C.log实例:

 

1232 1232 "binder thread pool (16 threads) starved for 100 ms"
  • D.log解析: system_server进程的 线程池已满的持续长达100ms

一般有了这些信息之后，可以辅助我们确定问题原因归属是系统原因还是App原因，看下面的案例二：

4、案例二：疯狂Binder Call导致应用ANR

搜索ANR in

 

  1. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: ANR in com.jeejen.family (com.jeejen.family/com.jeejen.home.launcher.ShoppingActivity)
  2. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: PID: 20576
  3. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: Reason: Input dispatching timed out (com.jeejen.family/com.jeejen.home.launcher.WelcomeActivity, 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: 2.  Wait queue head age: 10064.4ms.)
  4. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: Parent: com.jeejen.family/com.jeejen.home.launcher.WelcomeActivity
  5. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: Load: 1.25 / 1.1 / 1.37
  6. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: CPU usage from 5166ms to 0ms ago (2018-08-28 18:53:51.270 to 2018-08-28 18:53:56.436):
  7. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   7.7% 1825/system_server: 5.6% user + 2.1% kernel / faults: 1329 minor
  8. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   3.6% 20683/com.jeejen.family:pushcenter_pushservice: 3% user + 0.5% kernel / faults: 542 minor
  9. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   2.7% 4114/cnss_diag: 1.9% user + 0.7% kernel
  10. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   2.1% 422/kworker/u16:7: 0% user + 2.1% kernel
  11. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   1.9% 20830/com.jeejen.family:store: 1.3% user + 0.5% kernel / faults: 199 minor
  12. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   1.7% 20608/com.jeejen.family:pushcenter: 1.1% user + 0.5% kernel
  13. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   1.5% 725/android.hardware.sensors@1.0-service: 0.7% user + 0.7% kernel / faults: 1 minor
  14. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.9% 3538/com.android.systemui: 0.7% user + 0.1% kernel / faults: 11 minor
  15. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.5% 241/crtc_commit:111: 0% user + 0.5% kernel
  16. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.5% 419/kworker/u16:4: 0% user + 0.5% kernel
  17. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.5% 786/surfaceflinger: 0.5% user + 0% kernel
  18. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.3% 185/IPCRTR_dsps_sme: 0% user + 0.3% kernel
  19. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.3% 730/android.hardware.wifi@1.0-service: 0.1% user + 0.1% kernel / faults: 28 minor
  20. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.3% 820/dsps_IPCRTR: 0% user + 0.3% kernel
  21. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.3% 1147/msm_irqbalance: 0.1% user + 0.1% kernel
  22. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.3% 4113/sugov:0: 0% user + 0.3% kernel
  23. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 10/rcuop/0: 0% user + 0.1% kernel
  24. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 18/ksoftirqd/1: 0% user + 0.1% kernel
  25. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0% 34/ksoftirqd/3: 0% user + 0% kernel
  26. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0% 53/rcuop/5: 0% user + 0% kernel
  27. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0% 61/rcuop/6: 0% user + 0% kernel
  28. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 242/crtc_event:111: 0% user + 0.1% kernel
  29. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 538/ueventd: 0.1% user + 0% kernel
  30. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 577/jbd2/sda22-8: 0% user + 0.1% kernel
  31. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 591/logd: 0.1% user + 0% kernel
  32. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 719/android.hardware.graphics.composer@2.1-service: 0.1% user + 0% kernel
  33. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 928/thermal-engine: 0% user + 0.1% kernel
  34. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 3490/cds_mc_thread: 0% user + 0.1% kernel
  35. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 3491/cds_ol_rx_threa: 0% user + 0.1% kernel
  36. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 3680/com.android.phone: 0% user + 0.1% kernel / faults: 16 minor
  37. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 4248/com.miui.daemon: 0.1% user + 0% kernel / faults: 4 minor
  38. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 4488/com.miui.powerkeeper: 0.1% user + 0% kernel / faults: 10 minor
  39. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 5545/com.lbe.security.miui: 0% user + 0.1% kernel / faults: 6 minor
  40. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 6490/kworker/u17:2: 0% user + 0.1% kernel
  41. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 7535/kworker/u16:15: 0% user + 0.1% kernel
  42. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0% 7723/kworker/3:5: 0% user + 0% kernel
  43. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 15111/kworker/1:0: 0% user + 0.1% kernel
  44. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 15138/kworker/3:0: 0% user + 0.1% kernel
  45. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0% 19857/kworker/0:3: 0% user + 0% kernel
  46. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager:   0.1% 20492/kworker/5:3: 0% user + 0.1% kernel
  47. 08-28 18:54:00.110  1000  1825  1848 E ActivityManager: 3.8% TOTAL: 2% user + 1.1% kernel + 0% iowait + 0.3% irq + 0.1% softirq

按照上面的套路看看，各方面比较正常，发生时间大概是08-28 18:54:00.110 ，在看主线程的trace。

 

  1. ----- pid 20576 at 2018-08-28 18:53:56 -----
  2. Cmd line: com.jeejen.family
  3. "main" prio=5 tid=1 Native
  4. | group="main" sCount=1 dsCount=0 flags=1 obj=0x77ffca18 self=0xecfce000
  5. | sysTid=20576 nice=-10 cgrp=default sched=0/0 handle=0xf0bf2494
  6. | state=S schedstat=( 628294395 402363898 957 ) utm=42 stm=20 core=4 HZ=100
  7. | stack=0xff5fe000-0xff600000 stackSize=8MB
  8. | held mutexes=
  9. kernel: (couldn't read /proc/self/task/20576/stack)
  10. native: #00 pc 00053cfc /system/lib/libc.so (__ioctl+8)
  11. native: #01 pc 00021cd3 /system/lib/libc.so (ioctl+30)
  12. native: #02 pc 0003d3f5 /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+204)
  13. native: #03 pc 0003dde3 /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
  14. native: #04 pc 0003713d /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
  15. native: #05 pc 000c3cf1 /system/lib/libandroid_runtime.so (android_os_BinderProxy_transact(_JNIEnv*, _jobject*, int, _jobject*, _jobject*, int)+200)
  16. at android.os.BinderProxy.transactNative(Native method)
  17. at android.os.BinderProxy.transact(Binder.java:1127)
  18. at android.net.wifi.IWifiManager$Stub$Proxy.getConnectionInfo(IWifiManager.java:1441)
  19. at android.net.wifi.WifiManager.getConnectionInfo(WifiManager.java:1778)
  20. at org.chromium.net.NetworkChangeNotifierAutoDetect$WifiManagerDelegate.getWifiInfoLocked(NetworkChangeNotifierAutoDetect.java:28)
  21. at org.chromium.net.NetworkChangeNotifierAutoDetect$WifiManagerDelegate.getWifiSsid(NetworkChangeNotifierAutoDetect.java:22)
  22. - locked <0x0f4edae7> (a java.lang.Object)
  23. at org.chromium.net.NetworkChangeNotifierAutoDetect.getCurrentNetworkState(NetworkChangeNotifierAutoDetect.java:67)
  24. at org.chromium.net.NetworkChangeNotifierAutoDetect.<init>(NetworkChangeNotifierAutoDetect.java:21)
  25. at org.chromium.net.NetworkChangeNotifier.setAutoDetectConnectivityStateInternal(NetworkChangeNotifier.java:61)

看样子是binder call阻塞了，调用的接口是IWifiManager.getConnectionInfo()。因为是binder调用，查看一下binder_sample。

 

  1. 08-28 18:54:01.384 10171 20576 20576 I binder_sample: [android.net.wifi.IWifiManager,24,16004,com.jeejen.family,100]
  2. 08-28 18:54:04.868 10171 20576 20576 I binder_sample: [android.net.wifi.IWifiManager,24,3479,com.jeejen.family,100]
  3. 08-28 18:56:12.712 10171 21885 21885 I binder_sample: [android.net.wifi.IWifiManager,24,8963,com.jeejen.family,100]

可以看到在ANR附近的时间，使用IWifiManager接口的binder调用确实耗时比较长，那么这个是不是系统原因呢？那么去看他的对端Sysytem的代码。

 

  1. 1763    /**
  2. 1764     * See {@link android.net.wifi.WifiManager#getConnectionInfo()}
  3. 1765     * @return the Wi-Fi information, contained in {@link WifiInfo}.
  4. 1766     */
  5. 1767    @Override
  6. 1768    public WifiInfo getConnectionInfo() {
  7. 1769        enforceAccessPermission();
  8. 1770        mLog.trace("getConnectionInfo uid=%").c(Binder.getCallingUid()).flush();
  9. 1771        /*
  10. 1772         * Make sure we have the latest information, by sending
  11. 1773         * a status request to the supplicant.
  12. 1774         */
  13. 1775        return mWifiStateMachine.syncRequestConnectionInfo();
  14. 1776    }

 

  1. 1521    public WifiInfo syncRequestConnectionInfo() {
  2. 1522        WifiInfo result = new WifiInfo(mWifiInfo);
  3. 1523        return result;
  4. 1524    }
  5.

getConnectionInfo直接通过wifiService调用wifiStateMachine中syncRequestConnectionInfo,这部分的实现不会阻塞住，难道Binder被沾满了？从trace中并没有看出这一点，那么怎么回事呢？我们尝试复现这个问题，好在比较容易复现。

 

  1. 09-04 18:24:29.182 D/WifiStateMachine( 1312): syncRequestConnectionInfo/in SSID: MIOffice-5G, BSSID: 70:3a:0e:2c:bb:f1, MAC: 80:ad:16:4c:0b:fe, Supplicant state: COMPLETED, RSSI: -44, Link speed: 400Mbps, Frequency: 5180MHz, Net ID: 0, Metered hint: false, score: 60
  2. 09-04 18:24:29.182 D/WifiStateMachine( 1312): syncRequestConnectionInfo/out SSID: MIOffice-5G, BSSID: 70:3a:0e:2c:bb:f1, MAC: 80:ad:16:4c:0b:fe, Supplicant state: COMPLETED, RSSI: -44, Link speed: 400Mbps, Frequency: 5180MHz, Net ID: 0, Metered hint: false, score: 60

发现在主线程进行大量输出上面的Log，极简桌面在1分钟内调用此接口160次，导致了SystemServer不能及时响应这个App，造成了App自己的ANR。像Binder call导致ANR的问题很常见，存在被blocked的风险，此刻可以尝试放到异步里面执行，其次不要短时间的大量Binder调用，这样行为轻则App自己有问题，重则系统发生Watchdog死机重启。

4、案例三：广播超时导致App的ANR

继续看一个案例三，按照上面的套路，首先在event　log中查看发生ANR的时间。

 

12-17 06:02:14.463  1566  1583 I am_anr  : [0,8769,com.android.updater,952680005,Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }]

发生ANR的时间是am_anr 时间点是12-17 06:02:14.463，继续看Log

 

  1. 12-17 06:02:00.370  1566  1583 W BroadcastQueue: Timeout of broadcast BroadcastRecord{21ef8c2 u0 android.intent.action.BOOT_COMPLETED} - receiver=android.os.BinderProxy@2a6c365, started 60006ms ago
  2. 12-17 06:02:00.370  1566  1583 W BroadcastQueue: Receiver during timeout: ResolveInfo{5a8283a com.android.updater/.BootCompletedReceiver m=0x108000}
  3. 12-17 06:02:00.370  1566  1583 I am_broadcast_discard_app: [0,35584194,android.intent.action.BOOT_COMPLETED,49,ResolveInfo{5a8283a com.android.updater/.BootCompletedReceiver m=0x108000}]

但是我们发现在12-17 06:02:00.370 已经发生ANR，说明event　log中的时间是个大概值，可能由于系统资源比较紧张造成一定程度的滞后。由于是android.intent.action.BOOT_COMPLETED这个广播接收出现的ANR，那么我们顺藤摸瓜。

 

12-17 06:01:00.383  1566  3524 I ActivityManager: Start proc 8769:com.android.updater/9802 for broadcast com.android.updater/.BootCompletedReceiver caller=null

在12-17 06:01:00.383的时候启动了广播进程

 

  1. 12-17 06:01:36.721  8769  8769 D BootCompletedReceiver: onReceive android.intent.action.BOOT_COMPLETED
  2. 12-17 06:02:14.725 8769 8769 D UpdateService: onCreate

在12-17 06:01:36.721的时候，客户端BootCompletedReceiver onReceiver方法 开始回调，然后onReceive 启动UpdateService，调用UpdateService.onCreate时间是12-17 06:02:14.725。根据上面的分析有两个初步的疑问。

启动广播是在12-17 06:01:00.383，广播的onReceiver方法开始回调是在12-17 06:01:36.721，ANR的时间是在12-17 06:02:00.370 ，那么为什么启动了36s后我才收到bootcompleted广播，这本身就不正常吧，其次为什么广播启动UpdateService耗时将近化了一分多钟？分析到这里App同学认为无法分析下去，八成是系统原因，从cpu的统计上来看，认为是某些程序占用过高导致的，贴出下面的Log。

 

  1. 12-17 06:02:19.286  1566  1583 E ActivityManager: ANR in com.android.updater
  2. 12-17 06:02:19.286  1566  1583 E ActivityManager: PID: 8769
  3. 12-17 06:02:19.286  1566  1583 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) }
  4. 12-17 06:02:19.286  1566  1583 E ActivityManager: Load: 0.0 / 0.0 / 0.0
  5. 12-17 06:02:19.286  1566  1583 E ActivityManager: CPU usage from 0ms to 18846ms later (2017-12-17 06:02:00.379 to 2017-12-17 06:02:19.224):
  6. 12-17 06:02:19.286  1566  1583 E ActivityManager:   195% 6142/com.immomo.momo: 195% user + 0% kernel
  7. 12-17 06:02:19.286  1566  1583 E ActivityManager:   2.3% 8170/com.tencent.mm: 2.3% user + 0% kernel / faults: 448 minor
  8. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.7% 1566/system_server: 0.4% user + 0.3% kernel / faults: 150 minor 1 major
  9. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.4% 90/kworker/u16:3: 0% user + 0.4% kernel
  10. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.3% 4704/com.tencent.mm:push: 0.1% user + 0.2% kernel / faults: 116 minor
  11. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.3% 8769/com.android.updater: 0.2% user + 0.1% kernel / faults: 1600 minor 2 major
  12. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.2% 4790/com.tencent.mm:patch: 0.2% user + 0% kernel / faults: 748 minor
  13. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.2% 329/mmc-cmdqd/0: 0% user + 0.2% kernel
  14. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.2% 5429/com.tencent.mm:push: 0% user + 0.1% kernel / faults: 17 minor
  15. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.2% 5435/com.tencent.mm:patch: 0.2% user + 0% kernel / faults: 82 minor
  16. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.2% 8712/com.tencent.mm:exdevice: 0.1% user + 0% kernel
  17. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 432/logd: 0.1% user + 0% kernel / faults: 4 minor
  18. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 844/msm_irqbalance: 0% user + 0.1% kernel / faults: 4 minor
  19. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 7580/kworker/u16:2: 0% user + 0.1% kernel
  20. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 7/rcu_preempt: 0% user + 0.1% kernel
  21. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 1240/zygote: 0% user + 0.1% kernel / faults: 84 minor
  22. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0% 3216/com.xiaomi.simactivate.service: 0% user + 0% kernel / faults: 5 minor
  23. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 8645/kworker/7:0: 0% user + 0.1% kernel
  24. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0.1% 8730/kworker/4:2: 0% user + 0.1% kernel
  25. 12-17 06:02:19.286  1566  1583 E ActivityManager:   0% 45/rcuop/4: 0% user + 0% kernel

然而cpu占用195%并不算高，在多核中每个核最大占用率都是100%（八核占用率是800%），其次Load: 0.0 / 0.0 / 0.0，Load在15分钟这段时间都是０，停止运转了？貌似这个Log也不太正确。然而在小米手机上，ANR的监控会有加强的，输出了下面的Log。

 

12-17 06:02:14.693  8769  8769 W MIUI-BLOCK-MONITOR: The msg { when=-36s107ms what=113 obj=ReceiverData{intent=Intent { act=android.intent.action.BOOT_COMPLETED flg=0x9000010 cmp=com.android.updater/.BootCompletedReceiver (has extras) } packageName=com.android.updater resultCode=0 resultData=null resultExtras=null} target=android.app.ActivityThread$H planTime=1513461660613 dispatchTime=1513461696720 finishTime=0 } took 74080ms and took 37973ms after dispatch.

我们对每一个Message都额外记录了它各个状态的时间点，方便我们进行分析

  • when:消息从应该被执行到发生anr的时间
  • planTime：消息计划被执行的时间点
  • dispatchTime：消息真正被执行的时间点
  • finishTime：消息完成时的时间点
    计算消息执行的时间为:-when-(dispatchTime-planTime)=0，那么这意味着什么呢？意味着113这个Message正要开始执行，还没有开始执行就发生了ANR，在主线程的Looper消息队列中，等待了36秒。这份日志中没有主线程的trace，有也没有作用，因为可以看到这个消息还没有执行呢？那么这个36秒期间在做什么呢？有比较多下面的Log。

 

  1. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: The binder call took 3973ms.
  2. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: java.lang.Throwable
  3. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.AnrMonitor.checkBinderCallTime(AnrMonitor.java:591)
  4. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.BinderProxy.transact(Binder.java:623)
  5. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.content.pm.IPackageManager$Stub$Proxy.getApplicationInfo(IPackageManager.java:2658)
  6. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ApplicationPackageManager.getApplicationInfoAsUser(ApplicationPackageManager.java:340)
  7. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ApplicationPackageManager.getApplicationInfo(ApplicationPackageManager.java:333)
  8. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.core.ManifestParser.create(SourceFile:64)
  9. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.core.SdkManager.start(SourceFile:186)
  10. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at java.lang.reflect.Method.invoke(Native Method)
  11. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.external.a.abx()
  12. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at miui.external.a.attachBaseContext()
  13. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.Application.attach(Application.java:193)
  14. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.Instrumentation.newApplication(Instrumentation.java:1009)
  15. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.Instrumentation.newApplication(Instrumentation.java:993)
  16. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.LoadedApk.makeApplication(LoadedApk.java:800)
  17. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread.handleBindApplication(ActivityThread.java:5471)
  18. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread.-wrap2(ActivityThread.java)
  19. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1584)
  20. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.Handler.dispatchMessage(Handler.java:102)
  21. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.os.Looper.loop(Looper.java:163)
  22. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at android.app.ActivityThread.main(ActivityThread.java:6221)
  23. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at java.lang.reflect.Method.invoke(Native Method)
  24. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:904)
  25. 12-17 06:01:29.334 8769 8769 W MIUI-BLOCK-MONITOR: at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:794)

36秒期间都在做bindApplication操作，这种情况下极有可能是系统状态此时并不乐观的原因，其次通过上面的分析也可以看到BootCompletedReceiver的onReceiver是在主线程处理的，启动Service也花费了很多的时间，我们也可以考虑在注册Receiver的时候，可以指定Handler，让onReceiver运行在子线程中(怎么做，可以看源码哦)

本篇文章主要梳理三个小案例，总结ANR问题的分析套路，最后在次总结分析步骤：

  • 抓取bugreport，搜索ANR in，查看发生的时间和进程，Cpu的负载有没有问题
  • 根据进程寻找主线程的trace，发现被blocked的地方，如果是Binder call则，进一步确认下对端的情况；如果是耗时操作，直接修改成异步，怀疑系统执行慢可以看看binder_sample，dvm_lock等信息，其次gc多不多，lmk杀进程是不是很频繁，都可以看出系统的健康状态。
  • 结合源码进行分析解决

本文只是记录一些案例和分析手段，指导思想就是找出主线程在过去一段时间内被block的原因。总体上比较容易掌握，还没有到深入具体的原理，比如ANR的dump原理，系统怎么判定ANR，ANR的无效trace怎么办等等比较深入的问题。因为ANR问题有时候确实比较头疼，trace可能并不是第一案发现场，对于一些手机厂商，对ANR都做了加强的监控，可以输出来更多的信息，提高了ANR问题的分析效率，另外也可以看出来对于ANR问题做Room的同学会由于工作中阅读源码的经验，会更加得心应手一些。



作者：LooperJing
链接：https://www.jianshu.com/p/18f16aba79dd
来源：简书
著作权归作者所有。商业转载请联系作者获得授权，非商业转载请注明出处。

声明：本文内容由网友自发贡献，不代表【wpsshop博客】立场，版权归原作者所有，本站不承担相应法律责任。如您发现有侵权的内容，请联系我们。转载请注明出处：https://www.wpsshop.cn/w/小丑西瓜9/article/detail/288648
推荐阅读
相关标签

Copyright © 2003-2013 www.wpsshop.cn 版权所有，并保留所有权利。

  

闽ICP备14008679号