ANR分析总结

ANR概念

ANR类型

KeyDispatchTimeout（常见)

BroadcastTimeout

ServiceTimeout

前台Service：onCreate，onStart，onBind等生命周期在20s内没有处理完成发生ANR
后台Service：onCreate，onStart，onBind等生命周期在200s内没有处理完成发生ANR
logcat日志关键字：Timeout executing service

ContentProvider 在10S内没有处理完成发生ANR
logcat日志关键字：timeout publishing content providers

常见ANR出现的原因

ANR分析

前台ANR

后台ANR

前台发生ANR后，系统会马上抓取现场的信息，收集的信息如下

系统会收集 ANR 时的进程堆栈信息，这是最重要的调试信息。它包括主线程和相关线程的堆栈追踪，显示了应用在 ANR 发生时执行的代码路径

• 收集重要进程的各个线程调用栈trace信息，保存在data/anr/traces.txt文件：

• 当前发生ANR的进程，system_server进程以及所有persistent进程

• CPU使用率排名前5的进程

• audioserver, cameraserver, mediaserver, surfaceflinger等重要的native进程

• 对用户可感知的进程则弹出ANR对话框告知用户，对用户不可感知的进程发生ANR则直接杀掉

traces.文件

获取traces.txt文件

1. 直接找手机目录下文件/data/anr/traces.txt

2. 方式1在早期安卓系统可以找到，现在各个厂商修改trace文件的命名以及权限问题已经走不通了。遇到这种情况，可以用命令adb bugreport

adb bugreport /Users/xxx/anrlog/anr.zip

执行命令后会生成一个zip文件，解压打开如下,anr日志保存在/Users/xxxx/anrlog/anr/FS/data/anr下

检测工具

Looper日志检测卡顿

在Android中，主线程（也称为UI线程）通过Looper来维护一个消息队列（Message Queue）。当有消息需要处理时，它们会被放入消息队列中，然后由Looper按照顺序一个一个地处理这些消息。每个消息都会被传递给对应的Handler或者其他注册的回调接口进行处理。如果在handler的dispatchMesaage方法里有耗时操作，就会发生卡顿。

/** * Run the message queue in this thread. Be sure to call * {@link #quit()} to end the loop. */public static void loop() {    //......    for (;;) {        //......        // This must be in a local variable, in case a UI event sets the logger        final Printer logging = me.mLogging;        if (logging != null) {            logging.println(">>>>> Dispatching to " + msg.target + " " +                    msg.callback + ": " + msg.what);        }        //......        try {            msg.target.dispatchMessage(msg);        } finally {            if (traceTag != 0) {                Trace.traceEnd(traceTag);            }        }        if (logging != null) {            logging.println("<<<<< Finished to " + msg.target + " " + msg.callback);        }        // ......    }}

检测 msg.target.dispatchMessage(msg) 的执行时间，就能检测到部分UI线程是否有耗时的操作。

 msg.target.dispatchMessage(msg)这行执行代码的前后，有两个logging.println函数。

如果设置了logging，会分别打印出>>>>> Dispatching to和<<<<< Finished to 日志。

这样我们就可以通过两次log的时间差值，来计算dispatchMessage的执行时间，从而设置阈值判断是否发生了卡顿。

通过实现Printer接口，设定耗时阀值，超过阀值打印当前堆栈。

public class LogMonitor implements Printer {    //......    private StackSampler mStackSampler;    private Handler mLogHandler;    public LogMonitor() {        mStackSampler = new StackSampler(mSampleInterval);        HandlerThread handlerThread = new HandlerThread("block-detect");        handlerThread.start();        mLogHandler = new Handler(handlerThread.getLooper());    }    @Override    public void println(String x) {        //从if到else会执行 dispatchMessage，如果执行耗时超过阈值，输出卡顿信息        if (!mPrintingStarted) {            //记录开始时间            mStartTimestamp = System.currentTimeMillis();            mPrintingStarted = true;            mStackSampler.startDump();        } else {            final long endTime = System.currentTimeMillis();            mPrintingStarted = false;            //出现卡顿            if (isBlock(endTime)) {                notifyBlockEvent(endTime);            }            mStackSampler.stopDump();        }    }    private void notifyBlockEvent(final long endTime) {        mLogHandler.post(new Runnable() {            @Override            public void run() {                //获得卡顿时主线程堆栈                List<String> stacks = mStackSampler.getStacks(mStartTimestamp, endTime);                for (String stack : stacks) {                    Log.e("block-detect", stack);                }            }        });    }    private boolean isBlock(long endTime) {        return endTime - mStartTimestamp > mBlockThresholdMillis;    }}

应用初始化的时候，把自定义Printer设置到Looper中。

LogMonitor logMonitor = new LogMonitor();Looper.getMainLooper().setMessageLogging(logMonitor);

Choreographer回调

Android系统每隔16ms发出VSYNC信号，来通知界面进行重绘、渲染，每一次同步的周期约为16.6ms，代表一帧的刷新频率。

Choreographer会和设备的VSync信号进行同步，Choreographer允许应用注册一个回调，用于在每个VSync信号到达时进行回调。

这个回调称为"Choreographer.FrameCallback"。

当应用发生卡顿时，VSync信号到达时，Choreographer会发现在上一个VSync信号到达时注册的回调尚未执行完毕，或者回调执行时间超过了一个VSync周期（即超过了16毫秒）。

这时，Choreographer就会认定发生了卡顿。frameTimeNanos是底层VSYNC信号到达的时间戳。

public class ChoreographerHelper {    static long lastFrameTimeNanos = 0;    public static void start() {        if (Build.VERSION.SDK_INT >= Build.VERSION_CODES.JELLY_BEAN) {            Choreographer.getInstance().postFrameCallback(new Choreographer.FrameCallback() {                @Override                public void doFrame(long frameTimeNanos) {                    //上次回调时间                    if (lastFrameTimeNanos == 0) {                        lastFrameTimeNanos = frameTimeNanos;                        Choreographer.getInstance().postFrameCallback(this);                        return;                    }                    long diff = (frameTimeNanos - lastFrameTimeNanos) / 1_000_000;                    if (diff > 16.6f) {                        //掉帧数                        int droppedCount = (int) (diff / 16.6);                    }                    lastFrameTimeNanos = frameTimeNanos;                    Choreographer.getInstance().postFrameCallback(this);                }            });        }    }}

通过 ChoreographerHelper 可以实时计算帧率和掉帧数，实时监测App页面的帧率数据，发现帧率过低，还可以自动保存现场堆栈信息。需要注意的是，Choreographer回调检测卡顿是基于VSync信号的时间间隔，因此它对于检测较小的卡顿非常有效，但是对于一些较大范围或长时间的卡顿可能会有一定限制。

Matrix工具

Matrix是腾讯开源的Android性能监控工具，其中Trace Canary模块用于监听监控ANR、界面流畅性、启动耗时、页面切换耗时、慢函数及卡顿等问题。其中LooperAnrTracer、SignalAnrTracer可检测ANR、界面卡顿等功能。

LooperAnrTracer

替换主线程Looper的Printer，从而监控dispatchMessage的执行时间，LooperAnrTracer也是使用这种方案。首先反射获取 Looper 的 mLogging 对象，定义LooperPrinter 包裹了 Looper 中的 Printer 对象，LooperPrinter 同时也是一个 Printer。利用装饰者模式，通过 setMessageLogging() 替换 Looper 中的 mLogging 对象为 LooperPrinter，在原有功能的基础上增加了自己的监控。

SignalAnrTracer

通过注册SIGQUIT信号处理器来捕获ANR事件的。当一个应用发生ANR的时候，其他的应用也有可能收到SIGQUIT信号。所以监控SIGQUIT时，可能是监听到了其他进程产生的ANR，从而产生误报。Matrix 在判别是否发生 ANR 事件时，在 NOT_RESPONDING 的基础上，增加了【主线程是否阻塞】这一条件，增大了 ANR 捕获率。当发生ARN时，Matrix 并没有自己去 dump anr 日志，而是通过 hook 系统调用后重新发送 SIGQUIT 给 Signal Catcher 线程，让它去执行系统的 ANR 处理流程，从而自己也能拿到一份 ANR 日志，避免了重复 dump anr。

案例分析

死锁问题

最近分析游戏包ANR日志，发现firebase出现的一个死锁问题

main (blocked):tid=1 systid=9247 | waiting to lock <0x0891a599>(java.lang.Object) held by thread 25 at com.google.firebase.messaging.WakeLockHolder.completeWakefulIntent(WakeLockHolder.java:141) at com.google.firebase.messaging.WakeLockHolder$$ExternalSyntheticLambda0.onComplete(R8$$SyntheticClass:3) at com.google.android.gms.tasks.zzi.run(zzi.java:1) at com.google.android.gms.measurement.internal.zzl.run$bridge(com.google.android.gms:play-services-measurement-sdk@@21.1.1:27) at com.google.firebase.messaging.FcmBroadcastProcessor$$InternalSyntheticLambda$1$20ad64d025a971aa803b176a540e5710ff1caab22d62957ae57bd1390f50ccfd$0.execute(FcmBroadcastProcessor.java) at com.google.android.gms.tasks.zzj.zzd(com.google.android.gms:play-services-tasks@@18.0.1:3) at com.google.android.gms.tasks.zzr.zzb(com.google.android.gms:play-services-tasks@@18.0.1:5) at com.google.android.gms.tasks.zzw.zze(zzw.java:3) at com.google.android.gms.tasks.TaskCompletionSource.trySetResult(com.google.android.gms:play-services-tasks@@18.0.1:1) at com.google.firebase.messaging.WithinAppServiceConnection$BindRequest.finish(WithinAppServiceConnection.java:88) at com.google.firebase.messaging.WithinAppServiceBinder.lambda$send$0(WithinAppServiceBinder.java:55) at com.google.firebase.messaging.WithinAppServiceBinder$$InternalSyntheticLambda$2$28aec3a1d612c50761b821163886dacf3adcb6f56220725f43c11adc87a189da$1.onComplete$bridge(WithinAppServiceBinder.java:14) at com.google.android.gms.tasks.zzi.run(zzi.java:1) at com.google.android.gms.measurement.internal.zzl.run$bridge(com.google.android.gms:play-services-measurement-sdk@@21.1.1:27) at com.google.firebase.messaging.FcmBroadcastProcessor$$InternalSyntheticLambda$1$20ad64d025a971aa803b176a540e5710ff1caab22d62957ae57bd1390f50ccfd$0.execute(FcmBroadcastProcessor.java) at com.google.android.gms.tasks.zzj.zzd(com.google.android.gms:play-services-tasks@@18.0.1:3) at com.google.android.gms.tasks.zzr.zzb(com.google.android.gms:play-services-tasks@@18.0.1:5) at com.google.android.gms.tasks.zzw.zzi(com.google.android.gms:play-services-tasks@@18.0.1:3) at com.google.android.gms.tasks.zzw.addOnCompleteListener(com.google.android.gms:play-services-tasks@@18.0.1:9) at com.google.firebase.messaging.WithinAppServiceBinder.send(WithinAppServiceBinder.java:55) at com.google.firebase.messaging.WithinAppServiceConnection.flushQueue(WithinAppServiceConnection.java:152) at com.google.firebase.messaging.WithinAppServiceConnection.onServiceConnected(WithinAppServiceConnection.java:209) at android.app.LoadedApk$ServiceDispatcher.doConnected(LoadedApk.java:2084) at android.app.LoadedApk$ServiceDispatcher$RunConnection.run(LoadedApk.java:2116) at android.os.Handler.handleCallback(Handler.java:938) at android.os.Handler.dispatchMessage(Handler.java:99) at android.os.Looper.loop(Looper.java:246) at android.app.ActivityThread.main(ActivityThread.java:8653) at java.lang.reflect.Method.invoke(Method.java) at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:602) at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1130)firebase-iid-executor (blocked):tid=25 systid=9957 | waiting to lock <0x01fdfb47> (t7c) held by thread 1 at com.google.firebase.messaging.WithinAppServiceConnection.b(WithinAppServiceConnection.java:1) at com.google.firebase.messaging.WakeLockHolder.sendWakefulServiceIntent(WakeLockHolder.java:112) at com.google.firebase.messaging.FcmBroadcastProcessor.bindToMessagingService(FcmBroadcastProcessor.java:122) at com.google.firebase.messaging.FcmBroadcastProcessor.startMessagingService(FcmBroadcastProcessor.java:90) at com.google.firebase.messaging.FcmBroadcastProcessor.process(FcmBroadcastProcessor.java:73) at com.google.firebase.iid.FirebaseInstanceIdReceiver.onMessageReceive(FirebaseInstanceIdReceiver.java:52) at com.google.android.gms.cloudmessaging.CloudMessagingReceiver.zzb(com.google.android.gms:play-services-cloud-messaging@@17.0.0:9) at com.google.android.gms.cloudmessaging.CloudMessagingReceiver.zza(CloudMessagingReceiver.java:4) at com.google.android.gms.cloudmessaging.zze.run(com.google.android.gms:play-services-cloud-messaging@@17.0.0:35) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1167) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:641) at com.google.android.gms.common.util.concurrent.zza.run(zza.java:2) at com.google.android.gms.ads.zzd.run$bridge(com.google.android.gms:play-services-ads-lite@@21.2.0:52) at java.lang.Thread.run(Thread.java:923)

看到主线程处于阻塞状态，正在等待锁<0x0891a599>，并且锁被thread 25持有。

看线程tid=25，发现该线程也在等待锁<0x01fdfb47>，并且被其他线程持有。

线程25持有锁又同时去请求锁，持有他人等待的资源并等待着他人释放，这里发生死锁了。
看到更新日志，firebase messaging库在23.1.1修复这个死锁问题。后续SDK可以更新修复这个ANR问题

主线程等待锁，发生阻塞

以上日志可以看到主线程等待锁<0x0c2c5bc1>发生阻塞。搜索以上内存地址，可以定位到以下日志

线程名为“RiverSDK #4”的线程，锁住以上内存地址。

分析原因是：请求数据复用时主线程等待锁出现阻塞了。

在第一次构造请求数据时，其中一项获取广告代码比较耗时，导致锁不能释放，第二次主线程从缓存池中获取数据就发生ANR了。

主线程无卡顿，处于正常状态堆栈

"main" tid=1 Native  #00  pc 0x000000000004b48c  /apex/com.android.runtime/lib64/bionic/libc.so (syscall+28)  #01  pc 0x00000000001af92c  /apex/com.android.art/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)  #02  pc 0x000000000039f27c  /apex/com.android.art/lib64/libart.so (art::JNI<false>::CallObjectMethodV(_JNIEnv*, _jobject*, _jmethodID*, std::__va_list)+504)  #03  pc 0x0000000000004040  /apex/com.android.art/lib64/libnativehelper.so (_JNIEnv::CallObjectMethod(_jobject*, _jmethodID*, ...)+124)  #04  pc 0x00000000000eb1dc  /system/lib64/libandroid_runtime.so (android::NativeInputEventReceiver::consumeEvents(_JNIEnv*, bool, long, bool*)+256)  #05  pc 0x00000000000eaea4  /system/lib64/libandroid_runtime.so (android::NativeInputEventReceiver::handleEvent(int, int, void*)+128)  #06  pc 0x0000000000019da8  /system/lib64/libutils.so (android::Looper::pollInner(int)+916)  #07  pc 0x00000000000199ac  /system/lib64/libutils.so (android::Looper::pollOnce(int, int*, int*, void**)+112)  #08  pc 0x0000000000112b5c  /system/lib64/libandroid_runtime.so (android::android_os_MessageQueue_nativePollOnce(_JNIEnv*, _jobject*, long, int)+44)  at android.os.MessageQueue.nativePollOnce (Native method)  at android.os.MessageQueue.next (MessageQueue.java:335)  at android.os.Looper.loop (Looper.java:183)  at android.app.ActivityThread.main (ActivityThread.java:7721)  at java.lang.reflect.Method.invoke (Native method)  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run (RuntimeInit.java:592)  at com.android.internal.os.ZygoteInit.main (ZygoteInit.java:952)

上述主线程堆栈就是一个很正常的空闲堆栈，表明主线程正在等待新的消息。如果ANR日志里主线程是这样一个状态，那可能有两个原因：

1. ANR 是由于其他因素引起的：
   CPU 抢占：其他高优先级的任务或进程抢占了主线程的执行时间，导致主线程在等待 CPU 资源。
   内存紧张：系统内存不足，导致主线程无法继续执行，因为需要等待内存资源释放。

2. 主线程在 ANR 日志抓取时已经恢复正常：
   ANR 日志是在系统检测到应用无响应后抓取的，但抓取时主线程可能已经恢复了正常的执行状态。这种情况下，分析 ANR 日志可能无法准确定位问题。在分析 ANR日志时，确保抓取日志的时间和ANR 发生的实际时间之间的差异是很重要的。如果时间间隔过久，主线程可能已经执行了其他任务，导致抓取的堆栈不再反映 ANR 发生时的状态，从而给分析带来困难。
   

遇到这种空闲堆栈，可以按照第4节的方法去分析CPU、内存的情况。其次可以关注抓取日志的时间和ANR发生的时间是否相隔过久，时间过久这个堆栈就没有分析意义了。

主线程做耗时的操作：比如数据库读写

"main" prio=5 tid=1 Nativeheld mutexes=kernel: (couldn't read /proc/self/task/11003/stack)native: #00 pc 000492a4 /system/lib/libc.so (nanosleep+12)native: #01 pc 0002dc21 /system/lib/libc.so (usleep+52)native: #02 pc 00009cab /system/lib/libsqlite.so (???)native: #03 pc 00011119 /system/lib/libsqlite.so (???)native: #04 pc 00016455 /system/lib/libsqlite.so (???)native: #16 pc 0000fa29 /system/lib/libsqlite.so (???)native: #17 pc 0000fad7 /system/lib/libsqlite.so (sqlite3_prepare16_v2+14)native: #18 pc 0007f671 /system/lib/libandroid_runtime.so (???)native: #19 pc 002b4721 /system/framework/arm/boot-framework.oat (Java_android_database_sqlite_SQLiteConnection_nativePrepareStatement__JLjava_lang_String_2+116)at android.database.sqlite.SQLiteConnection.setWalModeFromConfiguration(SQLiteConnection.java:294)at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:215)at android.database.sqlite.SQLiteConnection.open(SQLiteConnection.java:193)at android.database.sqlite.SQLiteConnectionPool.openConnectionLocked(SQLiteConnectionPool.java:463)at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:185)at android.database.sqlite.SQLiteConnectionPool.open(SQLiteConnectionPool.java:177)at android.database.sqlite.SQLiteDatabase.openInner(SQLiteDatabase.java:808)locked <0x0db193bf> (a java.lang.Object)at android.database.sqlite.SQLiteDatabase.open(SQLiteDatabase.java:793)at android.database.sqlite.SQLiteDatabase.openDatabase(SQLiteDatabase.java:696)at android.app.ContextImpl.openOrCreateDatabase(ContextImpl.java:690)at android.content.ContextWrapper.openOrCreateDatabase(ContextWrapper.java:299)at android.database.sqlite.SQLiteOpenHelper.getDatabaseLocked(SQLiteOpenHelper.java:223)at android.database.sqlite.SQLiteOpenHelper.getWritableDatabase(SQLiteOpenHelper.java:163)locked <0x045a4a8c> (a com.xxxx.video.common.data.DataBaseHelper)at com.xxxx.video.common.data.DataBaseORM.<init>(DataBaseORM.java:46)at com.xxxx.video.common.data.DataBaseORM.getInstance(DataBaseORM.java:53)locked <0x017095d5> (a java.lang.Class<com.xxxx.video.common.data.DataBaseORM>

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)

binder 通信失败

内存紧张导致ANR

如果在分析 ANR 日志时，发现 CPU 使用率和主线程堆栈信息都显示正常，但仍然ANR，那么可以考虑内存紧张可能是导致 ANR 的原因之一。

在分析 ANR 日志时，可以使用关键字 "am_meminfo" 搜索日志文件：

04-02 22:00:08.195  1531  1544 I am_meminfo: [350937088,41086976,492830720,427937792,291887104]

以上4个值分别是 Cached, Free,Zram, Kernel, NativeCached + Free 的内存代表着当前整个手机的可用内存，如果值很小，意味着处于内存紧张状态。

一般低内存的判定阈值为：4G 内存

手机以下阀值：350MB，以上阀值则为：450MB。

另外，如果通过关键字 am_meminfo 搜索不出任何日志，那么我们可以通过 onTrimMemory 搜索，如：

10-31 22:37:33.458 20733 20733 E Runtime : onTrimMemory level:80,pid:com.xxx.xxx:Launcher0

它也可以作为内存紧张的一个参考判断，可见，这里的 level 为 80 ，我们看看 Android 中是怎么定义这个 level 的：

由此可知，80 是一个很严重的级别，如果没有很快找到更多内存，进程将被杀死。

系统服务超时

如果系统服务超时，日志中一般会包含 BinderProxy.transactNative 关键字，如下：

如果其他应用占用了 Binder 线程，那么当前应用只能等待，可进一步搜索  blockUntilThreadAvailable  关键字，看看是哪个线程包含此字样，进一步看其调用了什么系统服务。

三七互娱技术团队

扫码关注 了解更多