ANR日志traces.txt分析

导致ANR的几种情况

  • KeyDispatchTimeout(5s): 按键或触摸事件在特定时间内无法处理完成
  • BroadcastTimeout(前台10s,后台60s): 广播在特定时间内无法处理完成
  • ServiceTimeout(前台20s,后台200s): Service在特定的时间无法处理完成 另外还有ProviderTimeout和WatchDog等导致的ANR

常见的原因

    A.耗时操作，如复杂的layout，庞大的for循环，IO等。
B.被Binder 对端block
C.被子线程同步锁block
    D.Binder被占满导致主线程无法和SystemServer通信
E.得不到系统资源（CPU/RAM/IO）
其中ABCD比较好分析，而E比较困难。

应用ANR产生的时候,ActivityManagerService的appNotResponding方法就会被调用,然后在/data/anr/traces.txt文件中写入ANR相关信息.
ANR就不作介绍了，下面只介绍如何分析ANR异常.

通常发生了ANR，ActivityManager会打印报错信息：

E/ActivityManager: ANR in com.rui.android.poc  // ANR出现的进程包名
PID: 1322  // ANR进程ID
Reason: Broadcast of Intent { act=android.intent.action.SCREEN_ON flg=0x50000010 }//导致ANR的原因
Load: 4.13 / 2.52 / 1.05
CPU usage from 0ms to 12843ms later://CPU在ANR发生后的使用情况
98% 1322/com.rui.android.poc: 0.5% user + 98% kernel / faults: 1044 minor 104 major
5.6% 567/system_server: 3.4% user + 2.1% kernel / faults: 1940 minor 217 major
2.3% 766/com.android.systemui: 1.2% user + 1% kernel / faults: 251 minor 165 major
1.4% 268/kworker/0:2: 0% user + 1.4% kernel
1.2% 1690/adbd: 0.1% user + 1% kernel / faults: 2 minor 3 major
1% 756/com.android.phone: 0.6% user + 0.3% kernel / faults: 347 minor 61 major
0.9% 139/surfaceflinger: 0.3% user + 0.5% kernel / faults: 1 minor 5 major
0.2% 929/com.sprd.opm: 0.2% user + 0% kernel / faults: 279 minor 115 major
0.2% 23/kworker/u4:1: 0% user + 0.2% kernel
0.2% 368/kworker/u5:1: 0% user + 0.2% kernel
0.1% 914/com.android.modemassert: 0% user + 0% kernel / faults: 182 minor 66 major
0.1% 44/ksmd: 0% user + 0.1% kernel
0% 909/com.spreadst.validator: 0% user + 0% kernel / faults: 164 minor 39 major
0% 8/rcu_preempt: 0% user + 0% kernel
0% 43/kswapd0: 0% user + 0% kernel
0% 117/mmcqd/0: 0% user + 0% kernel
+0% 1770/kworker/0:3: 0% user + 0% kernel
+0% 1774/debuggerd: 0% user + 0% kernel
97% TOTAL: 3.7% user + 55% kernel + 38% iowait  // CUP占用情况
CPU usage from 12301ms to 12824ms later:
100% 1322/com.rui.android.poc: 0% user + 100% kernel
100% 1322/rui.android.poc: 0% user + 100% kernel
1.9% 1333/Binder_2: 0% user + 1.9% kernel
 3.8% 567/system_server: 1.9% user + 1.9% kernel
3.8% 581/ActivityManager: 1.9% user + 1.9% kernel
1.3% 139/surfaceflinger: 1.3% user + 0% kernel
1.3% 249/DispSync: 0% user + 1.3% kernel
1.5% 766/com.android.systemui: 1.5% user + 0% kernel / faults: 2 minor
1.5% 766/ndroid.systemui: 0% user + 1.5% kernel
1.6% 1770/kworker/0:3: 0% user + 1.6% kernel
100% TOTAL: 0% user + 54% kernel + 45% iowait

Log分析：

log打印了ANR的基本信息,我们可以分析CPU使用率得知ANR的简单情况;如果CPU使用率很高,接近100%,可能是在进行大规模的计算更可能是陷入死循环;如果CUP使用率很低,说明主线程被阻塞了,并且当IOwait很高,可能是主线程在等待I/O操作的完成.
对于ANR只是分析Log很难知道问题所在,我们还需要通过Trace文件分析stack调用情况.

traces.txt是如何生成的

当APP(包括系统APP和用户APP)进程出现ANR、应用响应慢或WatchDog的监视没有得到回馈时,系统会dump此时的top进程,进程中Thread的运行状态就都dump到这个Trace文件中了.每次发生ANR， 这个文件都会被清空，写入新的内容. 如果想查看以前发生ANR的信息， 可以去查看DB文件.

DropBox中的log

traces.txt只保留最后一次发生ANR时的信息, android 2.2开始增加了DropBox功能, 保留历史上发生的所有ANR的log.
“/data/system/dropbox”是DB指定的文件存放位置.
日志保存的最长时间， 默认是3天.

shell@sp9820a_Rui8503:/data # cd system/dropbox/
shell@sp9820a_Rui8503:/data/system/dropbox # ls
SYSTEM_BOOT@1325376052965.txt
system_app_crash@1325376052598.txt
system_app_crash@1325376054905.txt
system_app_strictmode@1325376048453.txt.gz
system_app_strictmode@1325376053442.txt.gz
system_app_strictmode@1325376058904.txt.gz
system_server_wtf@1325376043066.txt
system_server_wtf@1325376052708.txt
system_server_wtf@1325376052842.txt
shell@sp9820a_Rui8503:/data/system/dropbox #

SystemServer在启动时， 会创建并添加DROPBOX_SERVICE.

//SystemServer.java
private void startOtherServices() {
... ...
            try {
                Slog.i(TAG, "DropBox Service");
                ServiceManager.addService(Context.DROPBOX_SERVICE,
                        new DropBoxManagerService(context, new File("/data/system/dropbox")));
            } catch (Throwable e) {
                reportWtf("starting DropBoxManagerService", e);
            }
... ...
}

在traces.txt中可以看到如下信息：

//说明了发生ANR的进程id、时间和进程名称。
----- pid 2023 at 2018-07-24 19:33:17 -----
Cmd line: com.rui.android.poc
//下面三行是线程的基本信息
JNI: CheckJNI is off; workarounds are off; pins=0; globals=348
DALVIK THREADS://以下是各个线程的函数堆栈信息
(mutexes: tll=0 tsl=0 tscl=0 ghl=0)

//下面一行说明了线程名称、daemon表示守护进程，线程的优先级（默认5）、线程锁id和线程状态，
//线程名称是启动线程的时候手动指明的，这里的main标识是主线程，是Android自动设定的
//一个线程名称，如果是自己手动创建的线程，一般会被命名成“Thread-xx”的格式，其中xx是
//线程id，它只增不减不会被复用；注意这其中的tid不是线程的id,它是一个在Java虚拟机中用
//来实现线程锁的变量，随着线程的增减，这个变量的值是可能被复用的；
"main" prio=5 tid=1 NATIVE

//group是线程组名称。sCount是此线程被挂起的次数，dsCount是线程被调试器挂起的次数，
//当一个进程被调试后，sCount会重置为0，调试完毕后sCount会根据是否被正常挂起增长，
//但是dsCount不会被重置为0，所以dsCount也可以用来判断这个线程是否被调试过。obj表示
//这个线程的Java对象的地址，self表示这个线程Native的地址。
  | group="main" sCount=1 dsCount=0 obj=0x4164dcf0 self=0x41565628

//此后是线程的调度信息，sysTid是Linux下的内核线程id，nice是线程的调度优先级，
//sched分别标志了线程的调度策略和优先级，cgrp是调度属组，handle是线程的处理函数地址。
  | sysTid=2023 nice=-1 sched=0/0 cgrp=apps handle=1074626900

//线程当前上下文信息，state是调度状态；schedstat从 /proc/[pid]/task/[tid]/schedstat读出，
//三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度，有的
//android内核版本不支持这项信息，得到的三个值都是0；utm是线程用户态下使用的时间
//值(单位是jiffies）;stm是内核态下的调度时间值；core是最后执行这个线程的cpu核的序号。
  | state=S schedstat=( 0 0 0 ) utm=49 stm=21 core=0

//线程的调用栈信息(这里可查看导致ANR的代码调用流程，分析ANR最重要的信息)
  (native backtrace unavailable)
  at libcore.io.Posix.open(Native Method)
  at libcore.io.BlockGuardOs.open(BlockGuardOs.java:110)
  at libcore.io.IoBridge.open(IoBridge.java:430)
  at java.io.FileInputStream.<init>(FileInputStream.java:78)
  at com.ruiven.android.Peripheral.util.kingFiles.write(kingFiles.java:58)
  at com.ruiven.android.Peripheral.util.kingFiles.write(kingFiles.java:51)
  at com.ruiven.android.Peripheral.util.kingLog.writeToFiles(kingLog.java:71)
  at com.ruiven.android.Peripheral.util.kingLog.f(kingLog.java:47)
  at com.ruiven.android.poc.receiver.ReceiverBatteryChanged.onReceive(ReceiverBatteryChanged.java:114)
  at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:767)
  at android.os.Handler.handleCallback(Handler.java:769)
  at android.os.Handler.dispatchMessage(Handler.java:97)
  at android.os.Looper.loop(Looper.java:136)
  at com.ruiven.android.Peripheral.util.Cockroach$1.run(Cockroach.java:38)
  at android.os.Handler.handleCallback(Handler.java:769)
  at android.os.Handler.dispatchMessage(Handler.java:97)
  at android.os.Looper.loop(Looper.java:136)
  at android.app.ActivityThread.main(ActivityThread.java:5375)
  at java.lang.reflect.Method.invokeNative(Native Method)
  at java.lang.reflect.Method.invoke(Method.java:515)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:976)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:792)
  at dalvik.system.NativeStart.main(Native Method)

//Binder线程是进程的线程池中用来处理binder请求的线程
"Binder_3" prio=5 tid=23 NATIVE
  | group="main" sCount=1 dsCount=0 obj=0x41b765f8 self=0x4f213f18
  | sysTid=1347 nice=0 sched=0/0 cgrp=apps handle=1327603952
  | state=S schedstat=( 0 0 0 ) utm=0 stm=3 core=1
  #00  pc 000205d0  /system/lib/libc.so (__ioctl+8)
  #01  pc 0002d01f  /system/lib/libc.so (ioctl+14)
  #02  pc 0001e519  /system/lib/libbinder.so (android::IPCThreadState::talkWithDriver(bool)+140)
  #03  pc 0001ec67  /system/lib/libbinder.so (android::IPCThreadState::getAndExecuteCommand()+6)
  #04  pc 0001ecfd  /system/lib/libbinder.so (android::IPCThreadState::joinThreadPool(bool)+48)
  #05  pc 000236cd  /system/lib/libbinder.so
  #06  pc 0000ea19  /system/lib/libutils.so (android::Thread::_threadLoop(void*)+216)
  #07  pc 0004e769  /system/lib/libandroid_runtime.so (android::AndroidRuntime::javaThreadShell(void*)+68)
  #08  pc 0000e54b  /system/lib/libutils.so
  #09  pc 0000d240  /system/lib/libc.so (__thread_entry+72)
  #10  pc 0000d3dc  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

//JDWP线程是支持虚拟机调试的线程，daemon表示守护进程，不需要关心
"JDWP" daemon prio=5 tid=4 VMWAIT
  | group="system" sCount=1 dsCount=0 obj=0x41a21868 self=0x4cc821b0
  | sysTid=785 nice=0 sched=0/0 cgrp=apps handle=1257589656
  | state=S schedstat=( 0 0 0 ) utm=0 stm=0 core=1
  #00  pc 00021420  /system/lib/libc.so (recvmsg+8)
  #01  pc 000668ab  /system/lib/libdvm.so
  #02  pc 00066adf  /system/lib/libdvm.so
  #03  pc 000697af  /system/lib/libdvm.so
  #04  pc 00059fdd  /system/lib/libdvm.so
  #05  pc 0000d240  /system/lib/libc.so (__thread_entry+72)
  #06  pc 0000d3dc  /system/lib/libc.so (pthread_create+240)
  at dalvik.system.NativeStart.run(Native Method)

//“Signal Catcher”负责接收和处理kernel发送的各种信号，例如SIGNAL_QUIT、SIGNAL_USR1等就是被该线程
//接收到并处理的，traces.txt 文件中的内容就是由该线程负责输出的，可以看到它的状态是RUNNABLE.
"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
  | group="system" sCount=0 dsCount=0 obj=0x41a21770 self=0x4af3e5e0
  | sysTid=784 nice=0 sched=0/0 cgrp=apps handle=1257677168
  | state=R schedstat=( 0 0 0 ) utm=2 stm=2 core=1
  at dalvik.system.NativeStart.run(Native Method)
----- end 2023 -----

如果ANR在native层,那么堆栈中就不会有相关调用的路径,这种情况只能在native层添加更多的Log,一步步来查找了

NATIVE表示当前线程的状态：

Thread状态及其对应的值

ThreadState (defined at “dalvik/vm/thread.h “)
THREAD_UNDEFINED = -1, /* makes enum compatible with int32_t */
THREAD_ZOMBIE = 0, /* TERMINATED */( 线程死亡，终止运行)
THREAD_RUNNING = 1, /* RUNNABLE or running now */(线程可运行或正在运行)
THREAD_TIMED_WAIT = 2, /* TIMED_WAITING in Object.wait() */(执行了带有超时参数的wait、sleep或join函数)
THREAD_MONITOR = 3, /* BLOCKED on a monitor */(线程阻塞，等待获取对象锁)
THREAD_WAIT = 4, /* WAITING in Object.wait() */( 执行了无超时参数的wait函数)
THREAD_INITIALIZING= 5, /* allocated, not yet running */(新建，正在初始化，为其分配资源)
THREAD_STARTING = 6, /* started, not yet on thread list */(新建，正在启动)
THREAD_NATIVE = 7, /* off in a JNI native method */(正在执行JNI本地函数)
THREAD_VMWAIT = 8, /* waiting on a VM resource */(正在等待VM资源)
THREAD_SUSPENDED = 9, /* suspended, usually by GC or debugger */(线程暂停，通常是由于GC或debug被暂停)

**特别说明一下MONITOR状态和SUSPEND状态，MONITOR状态一般是类的同步块或者同步方法造成的，SUSPENDED状态在debugger的时候会出现，可以用来区别是不是真的是用户正常操作跑出了ANR。

mutexes(互斥)的选项简写对应含义：
tll--thread list lock
tsl-- thread suspend lock
tscl-- thread suspend count lock
ghl--gc heap lock
hwl--heap worker lock
hwll--heap worker list lock
  • 通过Cmd line: packagename可以找到要分析的进程
  • 并不是trace文件包含的应用就一定是造成ANR的帮凶，应用出现在trace文件中，只能说明出现ANR的时候这个应用进程还活着，trace文件的顶部则是触发ANR的应用信息。因此，如果你的应用出现在了trace文件的顶部，那么很有可能是因为你的应用造成了ANR，否则是你的应用造成ANR的可能性不大，但是具体是不是还需要进一步分析

参考：https://blog.csdn.net/yxz329130952/article/details/50087731

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

推荐阅读更多精彩内容

  • 给解决问题ANR一个印象
    简介 现在感觉自己做的工作，基本上脱离Android了就是用java写代码，而且可能试用期完了就会被刷，很多东西是...
    我叫王菜鸟阅读 14,463评论 2赞 17
  • Android应用ANR分析
    一.ANR是什么 Application Not Responding，字面意思就是应用无响应，稍加解释就是用户的...
    silentleaf阅读 63,174评论 7赞 93
  • Android ANR分析详解
    traces文件分析 简单了解ANR各个应用进程和系统进程的函数堆栈信息都输出到了/data/anr/traces...
    youseewhat阅读 29,470评论 0赞 27
  • Android ANR问题总结
    在实际情况中，当Android项目的用户量特别大时候，一些细小的问题也会被放大，ANR问题就是一个典型的例子。一些...
    Uprising阅读 53,777评论 4赞 116
  • 如何分析解决Android ANR
    ==================================================== 一：什么...
    爱情小傻蛋阅读 9,608评论 3赞 31