Android 开发相关文章收集Android

ANR日志traces.txt分析

2018-07-24  本文已影响5382人  DD_Dog

导致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

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

上一篇下一篇

猜你喜欢

热点阅读