当前位置:   article > 正文

Android 进阶——Framework 核心ANR( Applicatipon No Response)机制设计思想详解_android framework anra

android framework anra

引言

一、一些与ANR有关的计算机理论

在Android 的开发性能优化领域常常会和trace.txt文件打交道,里面包含一些线程的堆栈信息:Blocked、TimedWaiting、mutexes等等关键字,那么这些信息是想要告诉我们什么呢?在本文中,我们将从简要介绍一下相关计算机知识。

1、互斥锁(Mutexes)概述

在计算机科学中,互斥是一种机制,通过互斥对象是在代码的关键部分期间,使得一次只允许一个线程访问共享资源,而在Java中被称为Lock。互斥机制通常依赖两类方法:获取和释放(有时称为lock和unlock)。操作系统内核保证,一旦一个线程成功地获得了锁,在第一个线程释放它之前,没有其他线程可以获得它,如果第二个线程尝试获取就会被阻塞住,直到这个锁再次可用。因此,如果所有线程都确保只在获取和释放调用之间使用共享资源,则保证它们会轮流使用该资源。

2、死锁(Deadlocks )概述

虽然互斥对象在正确使用时非常强大,但它们确实有可能导致一个罕见的、难以捉摸的问题,即死锁。这通常发生在两个线程都试图获取另一个线程持有的互斥对象时,这将导致它们被永久阻塞。简而言之,如果两个线程之间都需要同时获取到两个或者多个共享资源才能正常工作,而当线程A持有了共享资源A正申请共享资源B,与此用时线程B持有共享资源B正申请共享资源A,但两个线程互不相让,最终就会进入死锁状态。在Android中线程对运行应用程序至关重要(如果其中一个线程是主线程),它很可能导致ANR(应用程序不响应)和应用程序崩溃。

二、ANR 设计目的概述

ANR设计基于系统对与之交互的四大组件(Activity,Service,Receiver,Provider、BroadcastReceiver)以及用户交互系统(InputEvent)进行超时监控,以判断应用进程(主线程)是否存在卡死或响应过慢的问题,就相当于是Android系统中的看门狗(watchdog)的设计思想。

三、Android 组件ANR超时机制

在这里插入图片描述

JVM Finalizer机制,当根可达性算法进行第一次检索完成后,并非所有不可达的对象都意味着即将消亡。因为当GC开始时会触发两次标记过程,第一次首先标记处没有必要执行finalize方法的对象,这部分对象被直接宣布“死刑”;而那些重写了finallize方法的对象则得到一次救赎的机会的,相当于是目前只是判了“死缓”,还有机会在finalize方法中重获新生(比如让他重新连上"GC"链),所以第二次标记才是真正执行“死刑”——真正开始回收不可达的对象。

1、Activity 切换处理超时

2、Broadcast 广播处理超时

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;
  • 1
  • 2
  • 3
  • 前台Broadcast:onReceiver在10S内没有处理完成发生ANR。

    发送时添加上前台广播标志 intent.addFlags(Intent.FLAG_RECEIVER_FOREGROUND)即位前台广播

  • 后台Broadcast:onReceiver在60s内没有处理完成发生ANR。

logcat日志关键字:Timeout of broadcast BroadcastRecord

3、Service 服务处理超时

/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;
  • 1
  • 2
  • 3
  • 4
  • 5
  • 前台Service在20s内没有处理完成发生ANR。

    即App处于用户态(即App中的某个Activity正处于前台、以Foreground Service 方式启动或者有前台广播正在执行)时正在运行的Service则为前台Service。

  • 后台Service在200s内没有处理完成发生ANR。

logcat日志关键字:Timeout executing service:/executing service XXX

4、ContentProvider 处理超时

ContentProvider publish在10S内没有处理完成发生ANR。

logcat日志关键字:timeout publishing content providers

5、Input 输入系统处理超时

KeyDispatchTimeout,InputDispatcher 分发keyEvent 到对应进程的Focused Window,当对应的Window 不存在、处于暂停态或者Input Chanel 占满、Input Chanel 未注册、渠道异常或5s内没有处理完这个keyEvent 就会导致ANR。简而言之,input事件在5S内没有处理完成导致ANR。

日志关键字:Input event dispatching timed out

6、Finalizer 处理超时

四、ANR的定位和排查

ANR的定位和排查是需要具体问题具体分析的,

1、 查看events_log

查看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.)]
  • 1

从上面的log我们可以看出: 应用com.xxxx.moblie07-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 }
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11

从上面我们可以知道,在时间 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。
  • 1

原来是应用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
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17

我已经在log 中标志了相关的含义。com.xxxx.moblie 占用了11%的CPU,其实这并不算多。现在的手机基本都是多核CPU。假如你的CPU是4核,那么上限是400%,以此类推。既然不是CPU负载的原因,那么到底是什么原因呢? 这时就要看我们的终极大杀器——traces.txt

2、 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)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21
  • 22
  • 23
  • 24
  • 25
  • 26
  • 27

解析一下traces.txt里面的一些字段,看看它到底能给我们提供什么信息.

mainmain标识是主线程,如果是线程,那么命名成“Thread-X”的格式,x表示线程id,逐步递增。
prio线程优先级,默认是5
tidtid本质上不是线程的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的堆栈信息定位代码位置,最后查看源码,分析与解决问题。

3、bugreport 分析

执行adb bugreport 后会在当前路径下生成一个异常报告压缩包(保存着所有进程的堆栈快照),文件名以bugreport_开头的压缩包,里面包含所有进程的mountinfo、完整堆栈和内存信息等。

windows最好以管理员模式运行cmd

4、adb shell debuggerd -b pid 获取堆栈信息

五、ANR 典型日志

HeapTaskDaemon——GC的守护进程,为了脱敏隐藏了相关的库名和包名,还加了混淆。当然这些日志并不是一定会存在,总之别生搬硬套。

1、死锁

每个线程堆栈都包含一些信息可以检测死锁,线程的状态通常有: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)
  • 1
  • 2
  • 3
  • 4
  • 5
  • 6
  • 7
  • 8
  • 9
  • 10
  • 11
  • 12
  • 13
  • 14
  • 15
  • 16
  • 17
  • 18
  • 19
  • 20
  • 21
  • 22
  • 23
  • 24
  • 25
  • 26
  • 27
  • 28
  • 29
  • 30
  • 31
  • 32
  • 33
  • 34
  • 35
  • 36
  • 37
  • 38
  • 39
  • 40
  • 41
  • 42
  • 43
  • 44
  • 45
  • 46
  • 47
  • 48
  • 49

首先通过检索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)
  • 1
  • 2
  • 3
  • 4

由此可知主线程已经被阻塞且正持有地址为0x023ef607的锁了,有一行代码正在试图获取一个由线程8(tid=8)持有的锁 (地址为0x08362446),首先第一个条件满足一个线程持有互斥锁并在等待另一个锁,接着继续查看线程tid为8的cmo-threadpool-1,也是已经被阻塞且正持有地址为0x08362446的锁了,有一行代码正在试图获取一个由线程1(tid=1)持有的锁 (地址为0x023ef607,第二个条件满足,典型的死锁,然后就是根据堆栈到代码中去优化处理,可能还需要先还原混淆前的包名。

1、binder数据量过大

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)
  • 1
  • 2
  • 3
  • 4
  • 5

2、binder 通信失败

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
  • 1
  • 2
  • 3
  • 4

六、超时监控的设计原理

以 BroadCastReceiver 广播接收超时为例,广播可以分为:

  • 有序广播
  • 无序广播

同时又有前台广播后台广播之分。但只针对有序广播设置超时监控机制并根据前台广播和后台广播的广播类型决定了超时时长(其中后台广播超时时长 60S,前台广播超时时长只有 10S)。

七、常见ANR原因

  • 主线程耗时操作,如复杂的layout,庞大的for循环,IO等。
  • 主线程被子线程同步锁block
  • 主线程被Binder 对端block
  • Binder被占满导致主线程无法和SystemServer通信
  • 得不到系统资源(CPU/Memory/IO)

总结下基本分析流程: 根据log确认发生ANR的进程、发生时间、大概在做什么操作,同时关注此时CPU、内存、IO的情况。 分析trace,先看时间是否能对的上,判断是不是案发现场,然后关注主线程是否存在耗时、死锁、等锁等问题,可以基本看出是APP问题还是系统问题。 如果是系统问题导致的,再结合binder_sample、dvm_lock_sample来分别定位下binder call耗时 和 系统持锁耗时的问题。 结合代码或源码来具体分析有问题的点。

声明:本文内容由网友自发贡献,不代表【wpsshop博客】立场,版权归原作者所有,本站不承担相应法律责任。如您发现有侵权的内容,请联系我们。转载请注明出处:https://www.wpsshop.cn/w/笔触狂放9/article/detail/227921
推荐阅读
相关标签
  

闽ICP备14008679号