Android中ANR的分析和解决( 二 )

通过上面的代码我们知道 , 当ANR发生的时候 , 会将ANR记录到event log和main log中 。
三、查看events_log(如果没有找到该文件可以跳过这一步)查看mobilelog文件夹下的events_log,从日志中搜索关键字:am_anr , 找到出现ANR的时间点、进程PID、ANR类型 。
【Android中ANR的分析和解决】如日志:
07-20 15:36:36.472100015201597 I am_anr: [0,1480,com.xxxx.moblie,952680005,Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)]从上面的log我们可以看出: 应用com.xxxx.moblie 在07-20 15:36:36.472时间 , 发生了一次KeyDispatchTimeout类型的ANR , 它的进程号是1480.
把关键的信息整理一下:

  • ANR时间:07-20 15:36:36.472
  • 进程pid:1480
  • 进程名:com.xxxx.moblie
  • ANR类型:KeyDispatchTimeout
我们已经知道了发生KeyDispatchTimeout的ANR是因为 input事件在5秒内没有处理完成 。那么在这个时间07-20 15:36:36.472 的前5秒 , 也就是(15:36:30 ~15:36:31)时间段左右程序到底做了什么事情?这个简单 , 因为我们已经知道pid了 , 再搜索一下pid = 1480的日志.这些日志表示该进程所运行的轨迹 , 关键的日志如下:
07-20 15:36:29.749 1010214801737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE07-20 15:36:30.136 1010214801737 D moblie-Application: receiving an empty message, drop07-20 15:36:35.791 1010214801766 I Adreno: QUALCOMM build: 9c9b012, I92eb381bc907-20 15:36:35.791 1010214801766 I Adreno: Build Date: 12/31/1707-20 15:36:35.791 1010214801766 I Adreno: OpenGL ES Shader Compiler Version: EV031.22.00.0107-20 15:36:35.791 1010214801766 I Adreno: Local Branch: 07-20 15:36:35.791 1010214801766 I Adreno: Remote Branch: refs/tags/AU_linux_ANDROID_LA.UM.6.4.R1.08.00.00.309.04907-20 15:36:35.791 1010214801766 I Adreno: Remote Branch: NONE07-20 15:36:35.791 1010214801766 I Adreno: Reconstruct Branch: NOTHING07-20 15:36:35.826 1010214801766 I vndksupport: sphal namespace is not configured for this process. Loading /vendor/lib64/hw/gralloc.msm8998.so from the current namespace instead.07-20 15:36:36.682 1010214801480 W ViewRootImpl[MainActivity]: Cancelling event due to no window focus: KeyEvent { action=ACTION_UP, keyCode=KEYCODE_PERIOD, scanCode=0, metaState=0, flags=0x28, repeatCount=0, eventTime=16099429, downTime=16099429, deviceId=-1, source=0x101 }从上面我们可以知道 , 在时间 07-20 15:36:29.749 程序收到了一个action消息 。
07-20 15:36:29.749 1010214801737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE 。原来是应用com.xxxx.moblie 收到了一个推送消息(com.ttt.push.RECEIVE_MESSAGE)导致了阻塞 , 我们再串联一下目前所获取到的信息:在时间07-20 15:36:29.749 应用com.xxxx.moblie 收到了一下推送信息action=com.ttt.push.RECEIVE_MESSAGE发生阻塞 , 5秒后发生了KeyDispatchTimeout的ANR 。
四、查看main_log日志信息在分析ANR的时候 , 我们首先要确认是不是当时CPU很紧张、各路APP都在抢占资源 , CPU无法及时响应最终导致了ANR?为了排查这种情况 , 我们就需要获取ANR发生时候的CPU状态参数 。
1、接下来我们来看一个ANR模拟日志案例
07-20 15:36:58.711100015201597 E ActivityManager: ANR in com.xxxx.moblie (com.xxxx.moblie/.ui.MainActivity) (关键字ANR in + 进程名 + Activity名称)07-20 15:36:58.711100015201597 E ActivityManager: PID: 1480 (进程pid)07-20 15:36:58.711100015201597 E ActivityManager: Reason: Input dispatching timed out (AppWindowToken{da8f666 token=Token{5501f51 ActivityRecord{15c5c78 u0 com.xxxx.moblie/.ui.MainActivity t3862}}}, Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)(ANR的原因 , 输入分发超时)07-20 15:36:58.711100015201597 E ActivityManager: Load: 0.0 / 0.0 / 0.0 (Load表明是1分钟,5分钟,15分钟CPU的负载)07-20 15:36:58.711100015201597 E ActivityManager: CPU usage from 20ms to 20286ms later (2018-07-20 15:36:36.170 to 2018-07-20 15:36:56.436):07-20 15:36:58.711100015201597 E ActivityManager:42% 6774/pressure: 41% user + 1.4% kernel / faults: 168 minor07-20 15:36:58.711100015201597 E ActivityManager:34% 142/kswapd0: 0% user + 34% kernel07-20 15:36:58.711100015201597 E ActivityManager:31% 1520/system_server: 13% user + 18% kernel / faults: 58724 minor 1585 major07-20 15:36:58.711100015201597 E ActivityManager:13% 29901/com.ss.android.article.news: 7.7% user + 6% kernel / faults: 56007 minor 2446 major07-20 15:36:58.711100015201597 E ActivityManager:13% 32638/com.android.quicksearchbox: 9.4% user + 3.8% kernel / faults: 48999 minor 1540 major07-20 15:36:58.711100015201597 E ActivityManager:11% (CPU的使用率)1480/com.xxxx.moblie: 5.2%(用户态的使用率) user + (内核态的使用率) 6.3% kernel / faults: 76401 minor 2422 major07-20 15:36:58.711100015201597 E ActivityManager:8.2% 21000/kworker/u16:12: 0% user + 8.2% kernel07-20 15:36:58.711100015201597 E ActivityManager:0.8% 724/mtd: 0% user + 0.8% kernel / faults: 1561 minor 9 major07-20 15:36:58.711100015201597 E ActivityManager:8% 29704/kworker/u16:8: 0% user + 8% kernel07-20 15:36:58.711100015201597 E ActivityManager:7.9% 24391/kworker/u16:18: 0% user + 7.9% kernel07-20 15:36:58.711100015201597 E ActivityManager:7.1% 30656/kworker/u16:14: 0% user + 7.1% kernel07-20 15:36:58.711100015201597 E ActivityManager:7.1% 9998/kworker/u16:4: 0% user + 7.1% kernel


推荐阅读