Android ANR log trace分析实例

一、ANR说明和原因

1.1 简介

ANR全称：Application Not Responding，也就是应用程序无响应。

1.2 原因

Android系统中，ActivityManagerService(简称AMS)和WindowManagerService(简称WMS)会检测App的响应时间，如果App在特定时间无法相应屏幕触摸或键盘输入时间，或者特定事件没有处理完毕，就会出现ANR。

以下四个条件都可以造成ANR发生：

  • InputDispatching Timeout：5秒内无法响应屏幕触摸事件或键盘输入事件
  • BroadcastQueue Timeout ：在执行前台广播（BroadcastReceiver）的onReceive()函数时10秒没有处理完成，后台为60秒。
  • Service Timeout ：前台服务20秒内，后台服务在200秒内没有执行完毕。
  • ContentProvider Timeout ：ContentProvider的publish在10s内没进行完。

1.3 避免

尽量避免在主线程（UI线程）中作耗时操作。

那么耗时操作就放在子线程中。
关于多线程可以参考：Android多线程：理解和简单使用总结

二.ANR一般分析步骤

1.首先从main.log找到进程出现anr对应的大体时间,如在log中查询"anr in"字段

2.根据出现anr的进程名到anr文件夹中找出trance.txt文件，根据文件的信息首先判断anr的类型，是app自身还是系统问题，如果是app应用问题，则根据对用的调用解决问题

3.如不是app应用问题，则从main.log中判断anr的类型，如是keydispatch time out，则应该根据anr准确的时间点上推5s钟，看看此时对用进程正在进程何操作(具体anr的准确时间可以在event.log中搜索anr)

4.trace中无明显异常，可以从下面的情况考虑

a.是否由于io，数据库处理导致cpu使用率过高从而导致其他应用进程无法抢占cpu时间片
b.是否是低内存导致anr(如低内存，可以从system.log中查看进程被kill, 输入某某进程died)
c.是否由于输入法交互处理不当导致不能返回出现anr
d.是否由于进程锁等待，死锁情况出现anr

三.实例分析

例子一

Android ANR 实例分析

例子二

Android ANR log trace日志文件分析

例子三

看 /data/anr/traces.tx. 文件
直接看main thread

----- pid 20663 at 2020-08-25 18:11:47 -----
Cmd line: com.xxxxxing.xxxxxsettings
Build fingerprint: 'Android/xxx/xxx:7.1.2/NHG47L/xxx:user/test-keys'
ABI: 'arm'
Build type: optimized
Zygote loaded classes=4381 post zygote classes=88
Intern table: 41765 strong; 330 weak
JNI: CheckJNI is off; globals=458 (plus 132 weak)
// ...
"main" prio=5 tid=1 Sleeping
  | group="main" sCount=1 dsCount=0 obj=0x74751f58 self=0xf4785400
  | sysTid=20663 nice=-10 cgrp=default sched=0/0 handle=0xf7437534
  | state=S schedstat=( 179097380 5860498 155 ) utm=9 stm=8 core=2 HZ=100
  | stack=0xff77c000-0xff77e000 stackSize=8MB
  | held mutexes=
  at java.lang.Thread.sleep!(Native method)
  - sleeping on <0x09d961ef> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:371)
  - locked <0x09d961ef> (a java.lang.Object)
  at java.lang.Thread.sleep(Thread.java:313)
  at com.xxxxxing.xxxxxsettings.CrashHandler.uncaughtException(CrashHandler.java:81)
  at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1068)
  at java.lang.ThreadGroup.uncaughtException(ThreadGroup.java:1063)

其实这份log 比较容易看出来是哪里有问题了，是在调用了thread sleep 造成的无响应

 at com.xxxxxing.xxxxxsettings.CrashHandler.uncaughtException(CrashHandler.java:81)

看logcat， 直接在log中搜索ANR关键字

[2020/8/25 18:13:42] (20663): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:42] 08-25 18:11:48.197 I/art     ( 4713): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:42] 08-25 18:11:48.339 I/art     ( 4701): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] 08-25 18:11:48.411 I/art     ( 4688): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] 08-25 18:11:48.467 I/art     ( 4668): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] 08-25 18:11:48.530 I/art     ( 4653): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] 08-25 18:11:48.588 I/art     ( 4638): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] 08-25 18:11:48.701 I/art     ( 4461): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] 08-25 18:11:48.878 I/art     ( 4379): Wrote stack traces to '/data/anr/traces.txt'
[2020/8/25 18:13:43] o=700386 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:anr_data_file:s0 tclass=file permissive=1
[2020/8/25 18:13:43] mcblk0p14" ino=700386 scontext=u:r:untrusted_app:s0:c512,c768 tcontext=u:object_r:anr_data_file:s0 tclass=file permissive=1
[2020/8/25 18:13:44] 08-25 18:11:51.547 E/ActivityManager( 4271): ANR in com.xxxxxing.xxxxxsettings(com.xxxxxing.xxxxxsettings/.ConnectionInfoActivity)

看ANR 附近log 信息

[2020/8/25 18:13:44] 08-25 18:11:51.547 E/ActivityManager( 4271): PID: 20663

直接搜20663 这个进程做了什么，如下log 可以看到是 signal 9 信号kill 掉的，关于signal 更新介绍可以看 FreeBSD Manual Pages

同时我们先看到anr 的打印是在process killed 之前打印的，说明是先发生了ANR后再杀掉了进程

    Line 1637: [2020/8/25 18:13:42] 08-25 18:11:47.492 I/art     (20663): 
    Line 1642: [2020/8/25 18:13:42] (20663): Wrote stack traces to '/data/anr/traces.txt'
    Line 1651: [2020/8/25 18:13:42] 08-25 18:11:47.844 I/Process (20663): Sending signal. PID: 20663 SIG: 9
    Line 1651: [2020/8/25 18:13:42] 08-25 18:11:47.844 I/Process (20663): Sending signal. PID: 20663 SIG: 9
    Line 1663: [2020/8/25 18:13:42] 08-25 18:11:48.114 I/ActivityManager( 4271): Process com.xxxxxing.xxxxxsettings (pid 20663) has died
    Line 1664: [2020/8/25 18:13:42] 08-25 18:11:48.115 D/ActivityManager( 4271): cleanUpApplicationRecord -- 20663
    Line 1866: [2020/8/25 18:13:44] 08-25 18:11:51.547 E/ActivityManager( 4271): PID: 20663

结合trace 和 logcat 以及源码 得出的结论为
1、程序封装的exception 类，收到了exception 后进入到重载的函数
使用方法参考 UncaughtException 的使用

2、重载的函数中实现 调用了sleep 后导致了ANR，然后在kill process

    @Override
    public void uncaughtException(Thread thread, Throwable ex) {
        if(!handleException(thread) && mDefaultHandler != null){
          mDefaultHandler.uncaughtException(thread, ex);// 系统默认异常处理器
        } else {
          Thread.sleep(3000);
          android.os.Process.killProcess(android.os.Process.myPid);
          System.exit(1);
        }
    }

例子四 Android ANR 处理之Handler

背景：播放多媒体的时候seek 卡住了，操作其他按键导致ANR

这里有两个问题要分析，一个是为什么seek 会卡住，另一个问题是即使seek卡住了也不应该导致ANR

先看ANR的main thread 如下

main" prio=5 tid=1 Native
 | group="main" sCount=1 dsCount=0 flags=1 obj=0x74d45000 self=0xed1d1000
 | sysTid=13857 nice=-10 cgrp=default sched=0/0 handle=0xf13ee494
 | state=S schedstat=( 0 0 0 ) utm=156 stm=22 core=1 HZ=100
 | stack=0xff34a000-0xff34c000 stackSize=8MB
 | held mutexes=
 kernel: __switch_to+0xa4/0xc4
 kernel: binder_thread_read+0x3e0/0x1104
 kernel: binder_ioctl+0x8e0/0xac4
 kernel: compat_SyS_ioctl+0xd4/0xed8
 kernel: el0_svc_naked+0x34/0x38
 native: #00 pc 00053b8c  /system/lib/libc.so (__ioctl+8)
 native: #01 pc 00021b63  /system/lib/libc.so (ioctl+30)
 native: #02 pc 0003d3f5  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+204)
 native: #03 pc 0003dde3  /system/lib/libbinder.so (android::IPCThreadState::waitForResponse(android::Parcel*, int*)+26)
 native: #04 pc 0003713d  /system/lib/libbinder.so (android::BpBinder::transact(unsigned int, android::Parcel const&, android::Parcel*, unsigned int)+36)
 native: #05 pc 00039f19  /system/lib/libmedia.so (android::BpMediaPlayer::seekTo(int, android::MediaTrack::ReadOptions::SeekMode)+84)
 native: #06 pc 00033025  /system/lib/libmedia.so (android::MediaPlayer::seekTo_l(int, android::MediaTrack::ReadOptions::SeekMode)+184)
 native: #07 pc 00033081  /system/lib/libmedia.so (android::MediaPlayer::seekTo(int, android::MediaTrack::ReadOptions::SeekMode)+40)
 native: #08 pc 0003049b  /system/lib/libmedia_jni.so (android_media_MediaPlayer_seekTo(_JNIEnv*, _jobject*, long long, int)+82)
 at android.media.MediaPlayer._seekTo(Native method)
 at android.media.MediaPlayer.seekTo(MediaPlayer.java:1961)
 at android.media.MediaPlayer.seekTo(MediaPlayer.java:1973)
 at com.xxx.media.xxxAndroidMediaPlayer.seekTo(xxxAndroidMediaPlayer.kt:310)
 at com.xxx.media.xxx.seekTo(xxxVideoView.kt:883)
 at com.xxx.media.MediaController$5.handleMessage(MediaController.java:587)
 at android.os.Handler.dispatchMessage(Handler.java:106)
 at android.os.Looper.loop(Looper.java:193)
 at android.app.ActivityThread.main(ActivityThread.java:6669)
 at java.lang.reflect.Method.invoke(Native method)
 at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
 at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:866)

Apk的代码时别人写，一时看代码感觉没有发现问题，收到按键后，通过Handler 发送消息处理

 private Handler mHandler = new Handler() {
 @Override
 public void handleMessage(Message msg) {
 super.handleMessage(msg);
 switch (msg.what) {
 case SEEK_MSG:
 if (mPlayer != null) {
 Log.d(LOG_TAG, "msg.arg1=="+msg.arg1);
 mDragging = false;
 seekSave = -1;
 mPlayer.seekTo(msg.arg1); // 播放器seek
 }
 break;
 }
 }
 };
 @Override
 public boolean dispatchKeyEvent(KeyEvent event) {
 if (event.getAction() == KeyEvent.ACTION_DOWN ) {
 Log.d(LOG_TAG, "dispatchKeyEvent: SEEK_MSG");
 mHandler.removeMessages(SEEK_MSG);
 mHandler.sendMessageDelayed(mHandler.obtainMessage(SEEK_MSG, mNewPosition, 0),1000);
 }
 }

为了模拟这个问题很简单，在 mPlayer.seekTo(msg.arg1); // 播放器seek 前面加一段sleep 30s，seek后再操作按键就好

同样能够模拟出问题来，堆栈基本也一样

"main" prio=5 tid=1 Sleeping
 | group="main" sCount=1 dsCount=0 flags=1 obj=0x742ee000 self=0xeffd1000
 | sysTid=9639 nice=-10 cgrp=default sched=0/0 handle=0xf41e2494
 | state=S schedstat=( 0 0 0 ) utm=38 stm=12 core=3 HZ=100
 | stack=0xff1b0000-0xff1b2000 stackSize=8MB
 | held mutexes=
 at java.lang.Thread.sleep(Native method)
 - sleeping on <0x06bc3a7d> (a java.lang.Object)
 at java.lang.Thread.sleep(Thread.java:373)
 - locked <0x06bc3a7d> (a java.lang.Object)
 at java.lang.Thread.sleep(Thread.java:314)
 at com.xxx.media.MediaController$5.handleMessage(MediaController.java:591)
 at android.os.Handler.dispatchMessage(Handler.java:106)
 at android.os.Looper.loop(Looper.java:193)
 at android.app.ActivityThread.main(ActivityThread.java:6669)
 at java.lang.reflect.Method.invoke(Native method)
 at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:493)
 at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:866)

然后又再细看了一遍，其实是自己对Android Handler的理解不够，上面apk的代码是有问题的，虽然handler处了理seek msg，但是这个是主线程的looper，其实就是在主线程的looper中做了耗时的操作，这时候有按键进来是无法响应的

更多关于hanlder的知识可以看这里 https://www.tqwba.com/x_d/jishu/269458.html

https://blog.csdn.net/ly502541243/article/details/52062179/

https://blog.csdn.net/javazejian/article/details/52426353

最后编辑于 ：
©著作权归作者所有,转载或内容合作请联系作者
  • 人面猴
    序言：七十年代末，一起剥皮案震惊了整个滨河市，随后出现的几起案子，更是在滨河造成了极大的恐慌，老刑警刘岩，带你破解...
    沈念sama阅读 202,529评论 5赞 475
  • 死咒
    序言：滨河连续发生了三起死亡事件，死亡现场离奇诡异，居然都是意外死亡，警方通过查阅死者的电脑和手机，发现死者居然都...
    沈念sama阅读 85,015评论 2赞 379
  • 救了他两次的神仙让他今天三更去死
    文/潘晓璐 我一进店门，熙熙楼的掌柜王于贵愁眉苦脸地迎上来，“玉大人，你说我怎么就摊上这事。” “怎么了？”我有些...
    开封第一讲书人阅读 149,409评论 0赞 335
  • 道士缉凶录：失踪的卖姜人
    文/不坏的土叔 我叫张陵，是天一观的道长。 经常有香客问我，道长，这世上最难降的妖魔是什么？ 我笑而不...
    开封第一讲书人阅读 54,385评论 1赞 273
  • 港岛之恋（遗憾婚礼）
    正文 为了忘掉前任，我火速办了婚礼，结果婚礼上，老公的妹妹穿的比我还像新娘。我一直安慰自己，他们只是感情好，可当我...
    茶点故事阅读 63,387评论 5赞 364
  • 恶毒庶女顶嫁案：这布局不是一般人想出来的
    文/花漫 我一把揭开白布。 她就那样静静地躺着，像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上，一...
    开封第一讲书人阅读 48,466评论 1赞 281
  • 城市分裂传说
    那天，我揣着相机与录音，去河边找鬼。 笑死，一个胖子当着我的面吹牛，可吹牛的内容都是我干的。 我是一名探鬼主播，决...
    沈念sama阅读 37,880评论 3赞 395
  • 双鸳鸯连环套：你想象不到人心有多黑
    文/苍兰香墨 我猛地睁开眼，长吁一口气：“原来是场噩梦啊……” “哼！你这毒妇竟也来了？” 一声冷哼从身侧响起，我...
    开封第一讲书人阅读 36,528评论 0赞 256
  • 万荣杀人案实录
    序言：老挝万荣一对情侣失踪，失踪者是张志新（化名）和其女友刘颖，没想到半个月后，有当地人在树林里发现了一具尸体，经...
    沈念sama阅读 40,727评论 1赞 295
  • 护林员之死
    正文 独居荒郊野岭守林人离奇死亡，尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 35,528评论 2赞 319
  • 白月光启示录
    正文 我和宋清朗相恋三年，在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 37,602评论 1赞 329
  • 活死人
    序言：一个原本活蹦乱跳的男人离奇死亡，死状恐怖，灵堂内的尸体忽然破棺而出，到底是诈尸还是另有隐情，我是刑警宁泽，带...
    沈念sama阅读 33,302评论 4赞 318
  • 日本核电站爆炸内幕
    正文 年R本政府宣布，位于F岛的核电站，受9级特大地震影响，放射性物质发生泄漏。R本人自食恶果不足惜，却给世界环境...
    茶点故事阅读 38,873评论 3赞 306
  • 男人毒药：我在死后第九天来索命
    文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹，春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 29,890评论 0赞 19
  • 一桩弑父案，背后竟有这般阴谋
    文/苍兰香墨 我抬头看了看天上的太阳。三九已至，却和暖如春，着一层夹袄步出监牢的瞬间，已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,132评论 1赞 259
  • 情欲美人皮
    我被黑心中介骗来泰国打工， 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留，地道东北人。 一个月前我还...
    沈念sama阅读 42,777评论 2赞 349
  • 代替公主和亲
    正文 我出身青楼，却偏偏与公主长得像，于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子，可洞房花烛夜当晚...
    茶点故事阅读 42,310评论 2赞 342