赞
踩
在Android 的开发性能优化领域常常会和trace.txt文件打交道,里面包含一些线程的堆栈信息:Blocked、TimedWaiting、mutexes等等关键字,那么这些信息是想要告诉我们什么呢?在本文中,我们将从简要介绍一下相关计算机知识。
在计算机科学中,互斥是一种机制,通过互斥对象是在代码的关键部分期间,使得一次只允许一个线程访问共享资源,而在Java中被称为Lock。互斥机制通常依赖两类方法:获取和释放(有时称为lock和unlock)。操作系统内核保证,一旦一个线程成功地获得了锁,在第一个线程释放它之前,没有其他线程可以获得它,如果第二个线程尝试获取就会被阻塞住,直到这个锁再次可用。因此,如果所有线程都确保只在获取和释放调用之间使用共享资源,则保证它们会轮流使用该资源。
虽然互斥对象在正确使用时非常强大,但它们确实有可能导致一个罕见的、难以捉摸的问题,即死锁。这通常发生在两个线程都试图获取另一个线程持有的互斥对象时,这将导致它们被永久阻塞。简而言之,如果两个线程之间都需要同时获取到两个或者多个共享资源才能正常工作,而当线程A持有了共享资源A正申请共享资源B,与此用时线程B持有共享资源B正申请共享资源A,但两个线程互不相让,最终就会进入死锁状态。在Android中线程对运行应用程序至关重要(如果其中一个线程是主线程),它很可能导致ANR(应用程序不响应)和应用程序崩溃。
ANR设计基于系统对与之交互的四大组件(Activity,Service,Receiver,Provider、BroadcastReceiver)以及用户交互系统(InputEvent)进行超时监控,以判断应用进程(主线程)是否存在卡死或响应过慢的问题,就相当于是Android系统中的看门狗(watchdog)的设计思想。
JVM Finalizer机制,当根可达性算法进行第一次检索完成后,并非所有不可达的对象都意味着即将消亡。因为当GC开始时会触发两次标记过程,第一次首先标记处没有必要执行finalize方法的对象,这部分对象被直接宣布“死刑”;而那些重写了finallize方法的对象则得到一次救赎的机会的,相当于是目前只是判了“死缓”,还有机会在finalize方法中重获新生(比如让他重新连上"GC"链),所以第二次标记才是真正执行“死刑”——真正开始回收不可达的对象。
com\android\server\am\ActivityManagerService.java
只有静态注册的广播和有序广播超时时才可能导致ANR,而动态注册的非有序广播并不会ANR 。因为广播发送时,会判断该进程是否存在,不存在则创建,创建进程的耗时也算在超时时间里。
只有当进程存在前台显示的Activity才会弹出ANR对话框,否则会直接杀掉当前进程 。
// How long we allow a receiver to run before giving up on it.
static final int BROADCAST_FG_TIMEOUT = 10*1000;
static final int BROADCAST_BG_TIMEOUT = 60*1000;
前台Broadcast:onReceiver在10S
内没有处理完成发生ANR。
发送时添加上前台广播标志 intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)即位前台广播
后台Broadcast:onReceiver在60s
内没有处理完成发生ANR。
logcat日志关键字:
Timeout of broadcast BroadcastRecord
/base/services/core/java/com/android/server/am/ActiveServices.java
Service的onCreate()、onStartCommand()、onStart()、 onBind()、 onRebind(),、onTaskRemoved(),、onUnbind()、onDestroy()生命周期方法在主线程处理耗时任务超时可能导致ANR。
// How long we wait for a service to finish executing.
static final int SERVICE_TIMEOUT = 20*1000;
// How long we wait for a service to finish executing.
static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;
前台Service在20s
内没有处理完成发生ANR。
即App处于用户态(即App中的某个Activity正处于前台、以Foreground Service 方式启动或者有前台广播正在执行)时正在运行的Service则为前台Service。
后台Service在200s
内没有处理完成发生ANR。
logcat日志关键字:
Timeout executing service:/executing service XXX
ContentProvider publish在10S
内没有处理完成发生ANR。
logcat日志关键字:timeout publishing content providers
KeyDispatchTimeout,InputDispatcher 分发keyEvent 到对应进程的Focused Window,当对应的Window 不存在、处于暂停态或者Input Chanel 占满、Input Chanel 未注册、渠道异常或5s内没有处理完这个keyEvent 就会导致ANR。简而言之,input事件在5S
内没有处理完成导致ANR。
日志关键字:Input event dispatching timed out
ANR的定位和排查是需要具体问题具体分析的,
查看mobilelog文件夹下的events_log,从日志中搜索关键字:am_anr
,找到出现ANR的时间点、进程PID、ANR类型。
07-20 15:36:36.472 1000 1520 1597 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 10102 1480 1737 D moblie-Application: [Thread:17329] receive an intent from server, action=com.ttt.push.RECEIVE_MESSAGE
07-20 15:36:30.136 10102 1480 1737 D moblie-Application: receiving an empty message, drop
07-20 15:36:35.791 10102 1480 1766 I Adreno : QUALCOMM build : 9c9b012, I92eb381bc9
07-20 15:36:35.791 10102 1480 1766 I Adreno : Build Date : 12/31/17
07-20 15:36:35.791 10102 1480 1766 I Adreno : OpenGL ES Shader Compiler Version: EV031.22.00.01
07-20 15:36:35.791 10102 1480 1766 I Adreno : Local Branch :
07-20 15:36:35.791 10102 1480 1766 I Adreno : Remote Branch : refs/tags/AU_LINUX_ANDROID_LA.UM.6.4.R1.08.00.00.309.049
07-20 15:36:35.791 10102 1480 1766 I Adreno : Remote Branch : NONE
07-20 15:36:35.791 10102 1480 1766 I Adreno : Reconstruct Branch : NOTHING
07-20 15:36:35.826 10102 1480 1766 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 10102 1480 1480 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 10102 1480 1737 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
。虽然知道了是怎么开始的,但是具体原因还没有找到,是不是当时CPU很紧张、各路APP再抢占资源? 我们再看看CPU的信息,。搜索关键字关键字: ANR in
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: ANR in com.xxxx.moblie (com.xxxx.moblie/.ui.MainActivity) (进程名)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: PID: 1480 (进程pid)
07-20 15:36:58.711 1000 1520 1597 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.)
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: Load: 0.0 / 0.0 / 0.0 (Load表明是1分钟,5分钟,15分钟CPU的负载)
07-20 15:36:58.711 1000 1520 1597 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.711 1000 1520 1597 E ActivityManager: 42% 6774/pressure: 41% user + 1.4% kernel / faults: 168 minor
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 34% 142/kswapd0: 0% user + 34% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 31% 1520/system_server: 13% user + 18% kernel / faults: 58724 minor 1585 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 13% 29901/com.ss.android.article.news: 7.7% user + 6% kernel / faults: 56007 minor 2446 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 13% 32638/com.android.quicksearchbox: 9.4% user + 3.8% kernel / faults: 48999 minor 1540 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 11% (CPU的使用率)1480/com.xxxx.moblie: 5.2%(用户态的使用率) user + (内核态的使用率) 6.3% kernel / faults: 76401 minor 2422 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 8.2% 21000/kworker/u16:12: 0% user + 8.2% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 0.8% 724/mtd: 0% user + 0.8% kernel / faults: 1561 minor 9 major
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 8% 29704/kworker/u16:8: 0% user + 8% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.9% 24391/kworker/u16:18: 0% user + 7.9% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.1% 30656/kworker/u16:14: 0% user + 7.1% kernel
07-20 15:36:58.711 1000 1520 1597 E ActivityManager: 7.1% 9998/kworker/u16:4: 0% user + 7.1% kernel
我已经在log 中标志了相关的含义。com.xxxx.moblie
占用了11%的CPU,其实这并不算多。现在的手机基本都是多核CPU。假如你的CPU是4核,那么上限是400%,以此类推。既然不是CPU负载的原因,那么到底是什么原因呢? 这时就要看我们的终极大杀器——traces.txt
。
当APP不响应、响应慢了、或者WatchDog的监视没有得到回应时,系统就会dump出一个traces.txt
文件,存放在文件目录:/data/anr/traces.txt
,通过traces文件,我们可以拿到线程名、堆栈信息、线程当前状态、binder call等信息。所以在定位ANR时,要特别注意“main”(tid=1)线程,它是处理UI操作的线程,大部分ANR总是由这个线程被阻塞或执行太多工作引起的。通过adb命令拿到该文件:adb pull /data/anr/traces.txt
有些ROM 可能anr日志名称不总是traces.txt
trace: Cmd line:com.xxxx.moblie
"main" prio=5 tid=1 Runnable
| group="main" sCount=0 dsCount=0 obj=0x73bcc7d0 self=0x7f20814c00
| sysTid=20176 nice=-10 cgrp=default sched=0/0 handle=0x7f251349b0
| state=R schedstat=( 0 0 0 ) utm=12 stm=3 core=5 HZ=100
| stack=0x7fdb75e000-0x7fdb760000 stackSize=8MB
| held mutexes= "mutator lock"(shared held)
// java 堆栈调用信息,可以查看调用的关系,定位到具体位置
at ttt.push.InterceptorProxy.addMiuiApplication(InterceptorProxy.java:77)
at ttt.push.InterceptorProxy.create(InterceptorProxy.java:59)
at android.app.Activity.onCreate(Activity.java:1041)
at miui.app.Activity.onCreate(SourceFile:47)
at com.xxxx.moblie.ui.b.onCreate(SourceFile:172)
at com.xxxx.moblie.ui.MainActivity.onCreate(SourceFile:68)
at android.app.Activity.performCreate(Activity.java:7050)
at android.app.Instrumentation.callActivityOnCreate(Instrumentation.java:1214)
at android.app.ActivityThread.performLaunchActivity(ActivityThread.java:2807)
at android.app.ActivityThread.handleLaunchActivity(ActivityThread.java:2929)
at android.app.ActivityThread.-wrap11(ActivityThread.java:-1)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1618)
at android.os.Handler.dispatchMessage(Handler.java:105)
at android.os.Looper.loop(Looper.java:171)
at android.app.ActivityThread.main(ActivityThread.java:6699)
at java.lang.reflect.Method.invoke(Native method)
at com.android.internal.os.Zygote$MethodAndArgsCaller.run(Zygote.java:246)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:783)
解析一下traces.txt
里面的一些字段,看看它到底能给我们提供什么信息.
main | main标识是主线程,如果是线程,那么命名成“Thread-X”的格式,x表示线程id,逐步递增。 |
prio | 线程优先级,默认是5 |
tid | tid本质上不是线程的id,是线程唯一标识ID |
group | 是线程组名称 |
sCount | 该线程被挂起的次数 |
dsCount | 是线程被调试器挂起的次数 |
obj | 对象地址 |
self | 该线程Native的地址 |
sysTid | 线程号(主线程的线程号和进程号相同) |
nice | 线程的调度优先级 |
sched | 分别标志了线程的调度策略和优先级 |
cgrp | 调度归属组 |
handle | 线程处理函数的地址。 |
state | 调度状态,(正常有 “R (running)”, “S (sleeping)”, “D (disk sleep)”, “T (stopped)”, “t (tracing stop)”, “Z (zombie)”, “X (dead)”, “x (dead)”, “K (wakekill)”, “W (waking)”,),通常一般的Process 处于的状态都是S (sleeping), 而如果一旦发现处于如D, T, Z (zombie) 等就要认真审查。 |
schedstat | 从 /proc/[pid]/task/[tid]/schedstat 读出,三个值分别表示线程在cpu上执行的时间、线程的等待时间和线程执行的时间片长度,不支持这项信息的三个值都是0; |
utm | 线程用户态下使用的时间值(单位是jiffies) |
stm | 内核态下的调度时间值 |
core | 最后执行这个线程的cpu核的标识 |
Java的堆栈信息是我们最关心的,它能够定位到具体位置。从上面的traces,我们可以判断ttt.push.InterceptorProxy.addMiuiApplicationInterceptorProxy.java:77
导致了com.xxxx.moblie
发生了ANR。这时候可以对着源码查看,找到出问题,并且解决它。总结一下这分析流程:首先我们搜索am_anr
,找到出现ANR的时间点、进程PID、ANR类型、然后再找搜索PID
,找前5秒左右的日志。过滤ANR IN 查看CPU信息,接着查看traces.txt
,找到java的堆栈信息定位代码位置,最后查看源码,分析与解决问题。
执行adb bugreport
后会在当前路径下生成一个异常报告压缩包(保存着所有进程的堆栈快照),文件名以bugreport_开头的压缩包,里面包含所有进程的mountinfo、完整堆栈和内存信息等。
windows最好以管理员模式运行cmd
HeapTaskDaemon——GC的守护进程,为了脱敏隐藏了相关的库名和包名,还加了混淆。当然这些日志并不是一定会存在,总之别生搬硬套。
每个线程堆栈都包含一些信息可以检测死锁,线程的状态通常有:Runnable、Sleeping、Waiting、Native或Blocked,当ANR发生时,如果对应的线程已经处于Blocked,意味着被标记为Blocked的线程正试图获取什么互斥锁,以及持有该锁的线程的线程ID (tid)。然后,你可以向下滚动到列表中对应该线程的条目,如果你发现该线程也是Blocked,你可以查看它试图获取的互斥量以及哪个线程持有该互斥量。通常这是第一个线程,这意味着您可能已经检测到存在死锁。典型的日志如下:
"main" prio=5 tid=1 Blocked
| group="main" sCount=1 dsCount=0 obj=0x7477dea0 self=0x5597d71b70
| sysTid=25967 nice=-1 cgrp=top_visible sched=0/0 handle=0x7f7dcb5000
| state=S schedstat=( 688872496 20759648 497 ) utm=57 stm=11 core=0 HZ=100
| stack=0x7fc4bc9000-0x7fc4bcb000 stackSize=8MB
| held mutexes=
at com.xxx.xx.x.zzp.zzav(unavailable:-1)
- waiting to lock <0x08362446> (a com.xxx.xx.x.zzp) held by thread 8
at com.xxx.xx.x.zzp.zza(unavailable:-1)
at com.xxx.xx.x.zzp$zzd.zzOE(unavailable:-1)
at com.xxx.xx.x.zzo.refresh(unavailable:-1)
- locked <0x023ef607> (a com.xxx.xx.x.zzo)
at com.xx.xxs.x$1.onSuccess(MyApplication.java:176)
at com.xx.xxs.x$1.onSuccess(MyApplication.java:169)
at com.example.callback.GenericCallBack.handleSuccess(GenericCallBack.java:39)
at com.example.service.AnalyticsServiceImpl$1.onResult(AnalyticsServiceImpl.java:74)
at com.example.service.AnalyticsServiceImpl$1.onResult(AnalyticsServiceImpl.java:65)
at com.xxz.xxs.xy.internal.zzzx$zza.zzb(unavailable:-1)
at com.xxz.xxs.xy.internal.zzzx$zza.handleMessage(unavailable:-1)
at android.os.Handler.dispatchMessage(Handler.java:102)
at android.os.Looper.loop(Looper.java:150)
at android.app.ActivityThread.main(ActivityThread.java:5546)
at java.lang.reflect.Method.invoke!(Native method)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:794)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:684)
"cmo-threadpool-1" prio=5 tid=8 Blocked
| group="main" sCount=1 dsCount=0 obj=0x12c0d4c0 self=0x5598cd6440
| sysTid=26006 nice=0 cgrp=top_visible sched=0/0 handle=0x7f61646450
| state=S schedstat=( 64174864 5461664 62 ) utm=6 stm=0 core=3 HZ=100
| stack=0x7f61544000-0x7f61546000 stackSize=1037KB
| held mutexes=
at com.xxx.xx.x.zzo.zza(unavailable:-1)
- waiting to lock <0x023ef607> (a com.xxx.xx.x.zzo) held by thread 1
at com.xxx.xx.x.zzp.zza(unavailable:-1)
- locked <0x08362446> (a com.xxx.xx.x.zzp)
at com.xxx.xx.x.zzp.zza(unavailable:-1)
at com.xxx.xx.x.zzp$zzc.zzb(unavailable:-1)
- locked <0x08362446> (a com.xxx.xx.x.zzp)
at com.xxx.xx.x.zzp$zzc.onSuccess(unavailable:-1)
at com.xxx.xx.x.zzct.zzPD(unavailable:-1)
at com.xxx.xx.x.zzct.run(unavailable:-1)
at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:423)
at java.util.concurrent.FutureTask.run(FutureTask.java:237)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:154)
at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:269)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1113)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:588)
at java.lang.Thread.run(Thread.java:833)
首先通过检索Blocked
关键字,发现main 和 cmo-threadpool-1线程都是阻塞态,发现嫌弃人,接着继续从main分析,
| held mutexes=
at com.xxx.xx.x.zzp.zzav(unavailable:-1)
- waiting to lock <0x08362446> (a com.xxx.xx.x.zzp) held by thread 8
at com.xxx.xx.x.zzp.zza(unavailable:-1)
由此可知主线程已经被阻塞且正持有地址为0x023ef607
的锁了,有一行代码正在试图获取一个由线程8(tid=8)持有的锁 (地址为0x08362446),首先第一个条件满足一个线程持有互斥锁并在等待另一个锁,接着继续查看线程tid为8的cmo-threadpool-1,也是已经被阻塞且正持有地址为0x08362446的锁了,有一行代码正在试图获取一个由线程1(tid=1)持有的锁 (地址为0x023ef607
),第二个条件满足,典型的死锁,然后就是根据堆栈到代码中去优化处理,可能还需要先还原混淆前的包名。
07-21 04:43:21.573 1000 1488 12756 E Binder : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 388568 (data: 1, 32, 7274595)
07-21 04:43:21.573 1000 1488 12756 E Binder : android.util.Log$TerribleFailure: Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 388568 (data: 1, 32, 7274595)
07-21 04:43:21.607 1000 1488 2951 E Binder : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 211848 (data: 1, 23, 7274595)
07-21 04:43:21.607 1000 1488 2951 E Binder : android.util.Log$TerribleFailure: Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 211848 (data: 1, 23, 7274595)
07-21 04:43:21.662 1000 1488 6258 E Binder : Unreasonably large binder reply buffer: on android.content.pm.BaseParceledListSlice$1@770c74f calling 1 size 259300 (data: 1, 33, 7274595)
07-21 06:04:35.580 <6>[32837.690321] binder: 1698:2362 transaction failed 29189/-3, size 100-0 line 3042
07-21 06:04:35.594 <6>[32837.704042] binder: 1765:4071 transaction failed 29189/-3, size 76-0 line 3042
07-21 06:04:35.899 <6>[32838.009132] binder: 1765:4067 transaction failed 29189/-3, size 224-8 line 3042
07-21 06:04:36.018 <6>[32838.128903] binder: 1765:2397 transaction failed 29189/-22, size 348-0 line 2916
以 BroadCastReceiver 广播接收超时为例,广播可以分为:
同时又有前台广播和后台广播之分。但只针对有序广播设置超时监控机制并根据前台广播和后台广播的广播类型决定了超时时长(其中后台广播超时时长 60S,前台广播超时时长只有 10S)。
总结下基本分析流程: 根据log确认发生ANR的进程、发生时间、大概在做什么操作,同时关注此时CPU、内存、IO的情况。 分析trace,先看时间是否能对的上,判断是不是案发现场,然后关注主线程是否存在耗时、死锁、等锁等问题,可以基本看出是APP问题还是系统问题。 如果是系统问题导致的,再结合binder_sample、dvm_lock_sample来分别定位下binder call耗时 和 系统持锁耗时的问题。 结合代码或源码来具体分析有问题的点。
Copyright © 2003-2013 www.wpsshop.cn 版权所有,并保留所有权利。