[068]破局ANR

前言

ANR是Android中经常遇到的问题，常规的ANR问题，一般可以通过adb日志和trace文件，找到导致ANR的原因，但是有很多偶发的ANR问题，难以采用常规的手段来分析的，通过学习字节跳动整治ANR的系列文章，聊聊自己的感悟。

一、工程师的噩梦

如下主线程的trace日志，想必这个日志是工程师的噩梦，为什么是噩梦？因为一般遇到这种日志，如果应用的日志不多，系统的日志不多，基本就是无解的存在。

android.os.MessageQueue.nativePollOnce(Native Method)
android.os.MessageQueue.next(MessageQueue.java:337)
android.os.Looper.loopOnce(Looper.java:184)
android.os.Looper.loop(Looper.java:324)
android.app.ActivityThread.main(ActivityThread.java:8140)
java.lang.reflect.Method.invoke(Native Method)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:559)
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)

二、字节整治ANR法宝

字节整治ANR的两大法宝，Raster和Sliver

2.1 Raster

Raster主要作用：记录主线程Message历史信息

2.2 Sliver

Sliver主要作用：记录线程历史堆栈调用信息

小结

由于这两个功能的代码并没有开源，我自己简单的实现一下部分功能，来验证一下，这两个法宝能否真正的破局ANR。

三、制造一个ANR现场

首先制造一个ANR的现场，方便后面验证，代码也很简单，只需要两个类。
这个代码进入界面以后，按两下back键就可以出现ANR

public class MainActivity extends AppCompatActivity {

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
    }

    @Override
    protected void onResume() {
        super.onResume();
        Intent intent = new Intent(this, Service.class);
        this.startService(intent);
    }
}

public class Service extends android.app.Service {
    @Nullable
    @Override
    public IBinder onBind(Intent intent) {
        return null;
    }

    @Override
    public void onCreate() {
        super.onCreate();
        try {
            Thread.sleep(7000);
        } catch (Exception e) {
            e.printStackTrace();
        }
    }
}

四、简化版Raster和Sliver设计

4.1 简化版Raster

保存并打印历史Message以及待处理的Message

4.2 简化版的Sliver

直接调用如下代码打印主线程的堆栈。

Looper.getMainLooper().getThread().getStackTrace()

4.3 触发的时间

在am_anr和ANR in的两个时机同时触发一次简化版Raster和Sliver，
am_anr比较接近ANR触发点，
ANR in其实是ANR触发以后，过了一段时间了。

五、实践

如下是我使用简化版的Raster和Sliver抓到的日志

5.1 am_anr时候触发

-----------HISTORY MSG-----------
Current Time:70022
Working Message:start=64631 delay=278ms took=0ms repeat=0 { when=0 what=114 obj=CreateServiceData{token=android.os.BinderProxy@2d85d09 className=com.kobe.fpstest.Service packageName=com.kobe.fpstest intent=null} target=android.app.ActivityThread$H }
Message 0 :start=64150 delay=5ms took=3ms repeat=0 { when=0 what=162 obj=/data/user/0/com.kobe.fpstest target=android.app.ActivityThread$H }
Message 1 :start=64153 delay=2ms took=1ms repeat=0 { when=0 what=138 obj=Bundle[mParcelledData.dataSize=1172] target=android.app.ActivityThread$H }
Message 2 :start=64154 delay=3ms took=73ms repeat=0 { when=0 what=110 obj=AppBindData{appInfo=ApplicationInfo{a8c29d6 com.kobe.fpstest}} target=android.app.ActivityThread$H }
Message 3 :start=64227 delay=75ms took=151ms repeat=0 { when=0 what=159 obj=android.app.servertransaction.ClientTransaction@5058edb0 target=android.app.ActivityThread$H }
Message 4 :start=64378 delay=225ms took=0ms repeat=0 { when=0 what=159 obj=android.app.servertransaction.ClientTransaction@3f67e3d1 target=android.app.ActivityThread$H }
Message 5 :start=64378 delay=154ms took=1ms repeat=0 { when=0 what=164 obj=com.kobe.fpstest target=android.app.ActivityThread$H }
Message 6 :start=64379 delay=33ms took=0ms repeat=0 { when=0 callback=androidx.core.content.res.ResourcesCompat$FontCallback$2 target=android.os.Handler }
-----------TODO MSG-----------
Message 0 :{ when=-5s670ms what=115 obj=ServiceArgsData{token=android.os.BinderProxy@2d85d09 startId=1 args=Intent { cmp=com.kobe.fpstest/.Service }} target=android.app.ActivityThread$H }
Message 1 :{ when=-5s659ms callback=android.view.ViewRootImpl$4 target=android.view.ViewRootImpl$ViewRootHandler }
Message 2 :{ when=-5s653ms barrier=0 }
Message 3 :{ when=-5s643ms callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
Message 4 :{ when=-5s91ms what=8 arg1=1 target=android.view.ViewRootImpl$ViewRootHandler }
Message 5 :{ when=-5s91ms what=149 obj=android.os.BinderProxy@fd199f1 target=android.app.ActivityThread$H }
Message 6 :{ when=-4s873ms callback=android.app.ActivityThread$$ExternalSyntheticLambda1 target=android.app.ActivityThread$H }
-----------MAIN THREAD STACK-----------
java.lang.Thread.sleep(Native Method)
java.lang.Thread.sleep(Thread.java:451)
java.lang.Thread.sleep(Thread.java:356)
com.kobe.fpstest.Service.onCreate(Service.java:25)
android.app.ActivityThread.handleCreateService(ActivityThread.java:4664)
android.app.ActivityThread.access$1700(ActivityThread.java:281)
android.app.ActivityThread$H.handleMessage(ActivityThread.java:2212)
android.os.Handler.dispatchMessage(Handler.java:106)
android.os.Looper.loopOnce(Looper.java:231)
android.os.Looper.loop(Looper.java:324)
android.app.ActivityThread.main(ActivityThread.java:8140)
java.lang.reflect.Method.invoke(Native Method)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:559)
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)

可以看到Working Message的start是64631，Current Time是70022，也就说这个Message目前已经运行了70022-64631=5391，也就是5.3秒。

正好堆栈抓到了java.lang.Thread.sleep(Native Method)，这个堆栈又是属于Working Message。

5.2 ANR in时候触发

-----------HISTORY MSG-----------
Current Time:75887
Working Message:null
Message 0 :start=64631 delay=278ms took=7002ms repeat=0 { when=0 what=114 obj=CreateServiceData{token=android.os.BinderProxy@2d85d09 className=com.kobe.fpstest.Service packageName=com.kobe.fpstest intent=null} target=android.app.ActivityThread$H }
Message 1 :start=71633 delay=7280ms took=2ms repeat=0 { when=0 what=115 obj=ServiceArgsData{token=android.os.BinderProxy@2d85d09 startId=1 args=Intent { cmp=com.kobe.fpstest/.Service }} target=android.app.ActivityThread$H }
Message 2 :start=71635 delay=7270ms took=2ms repeat=0 { when=0 callback=android.view.ViewRootImpl$4 target=android.view.ViewRootImpl$ViewRootHandler }
Message 3 :start=71637 delay=7255ms took=137ms repeat=0 { when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
Message 4 :start=71774 delay=71774ms took=1ms repeat=0 { when=0 callback=android.view.ViewRootImpl$$ExternalSyntheticLambda12 target=android.view.ViewRootImpl$ViewRootHandler }
Message 5 :start=71775 delay=6841ms took=0ms repeat=0 { when=0 what=8 arg1=1 target=android.view.ViewRootImpl$ViewRootHandler }
Message 6 :start=71775 delay=6841ms took=0ms repeat=0 { when=0 what=149 obj=android.os.BinderProxy@fd199f1 target=android.app.ActivityThread$H }
Message 7 :start=71775 delay=6622ms took=1ms repeat=0 { when=0 callback=android.app.ActivityThread$$ExternalSyntheticLambda1 target=android.app.ActivityThread$H }
Message 8 :start=71776 delay=136ms took=49ms repeat=0 { when=0 callback=androidx.appcompat.app.AppCompatDelegateImpl$2 target=android.view.ViewRootImpl$ViewRootHandler }
Message 9 :start=71826 delay=139ms took=2ms repeat=0 { when=0 what=31 obj=com.android.internal.os.SomeArgs@bd1a441 target=android.view.ViewRootImpl$ViewRootHandler }
Message 10 :start=71832 delay=21ms took=2ms repeat=0 { when=0 callback=android.view.Choreographer$FrameDisplayEventReceiver target=android.view.Choreographer$FrameHandler }
Message 11 :start=71834 delay=8ms took=0ms repeat=0 { when=0 what=6 target=android.view.ViewRootImpl$ViewRootHandler }
Message 12 :start=71834 delay=5ms took=0ms repeat=0 { when=0 what=13 target=android.view.ViewRootImpl$ViewRootHandler }
Message 13 :start=71834 delay=3ms took=0ms repeat=0 { when=0 what=4 arg1=1 obj=false target=android.view.inputmethod.InputMethodManager$H }
Message 14 :start=71840 delay=0ms took=1ms repeat=0 { when=0 what=2 obj=InputBindResult{result=SUCCESS_WITH_IME_SESSION method=com.android.internal.view.IInputMethodSession$Stub$Proxy@394ede6 id=com.google.android.inputmethod.latin/com.android.inputmethod.latin.LatinIME sequence=2 isInputMethodSuppressingSpellChecker=false} target=android.view.inputmethod.InputMethodManager$H }
Message 15 :start=71842 delay=0ms took=0ms repeat=0 { when=0 what=10 target=android.view.inputmethod.InputMethodManager$H }
Message 16 :start=71850 delay=0ms took=1ms repeat=0 { when=0 what=31 obj=com.android.internal.os.SomeArgs@bd1a441 target=android.view.ViewRootImpl$ViewRootHandler }
-----------TODO MSG-----------
-----------MAIN THREAD STACK-----------
android.os.MessageQueue.nativePollOnce(Native Method)
android.os.MessageQueue.next(MessageQueue.java:337)
android.os.Looper.loopOnce(Looper.java:184)
android.os.Looper.loop(Looper.java:324)
android.app.ActivityThread.main(ActivityThread.java:8140)
java.lang.reflect.Method.invoke(Native Method)
com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:559)
com.android.internal.os.ZygoteInit.main(ZygoteInit.java:1009)

可以发现这个堆栈就是前面提到程序员的噩梦堆栈，由于发生anr之后，dump应用的线程堆栈，会有延迟，有时候dump到的堆栈就是导致ANR的Message运行结束之后，拿到的trace的日志就是这样子。

单单从堆栈已经无法找到罪魁祸首了，但是可以从HISTORY MSG可以看到这个Message运行了7002毫秒，这个就是前面am_anr中打印的Working Message，也就是导致这次ANR的罪魁祸首。

Message 0 :start=64631 delay=278ms took=7002ms repeat=0 { when=0 what=114 obj=CreateServiceData{token=android.os.BinderProxy@2d85d09 className=com.kobe.fpstest.Service packageName=com.kobe.fpstest intent=null} target=android.app.ActivityThread$H }

小结

通过简单的实践，展示了简化版的Raster和Sliver是如何发挥作用的。

六、总结

对于很多偶发ANR问题，其实都是主线程的代码，在极端的情况下，无法高效的被执行，同时手机状态又是处于比较卡顿的状态，导致dump的堆栈无法抓到导致ANR的单个或者Message的有效堆栈，从而导致很多问题基本无解。

其实Raster和Sliver的作用就是尽可能地还原发生ANR前，主线程在干什么，为什么运行那么久。

顺着这个思路，我在思考排除代码设计层面的，就是假设你的代码常规运行没有什么问题。
在极端情况下，可能运行耗时的原因可能有IO，内存，CPU调度，如果尽可能还原发生ANR问题前，主线程的IO，内存，CPU调度的状态，以及影响他们的其他进程线程，那样子很多ANR问题就可以迎刃而解。

我第一个想到的就是抓Perfetto Trace，可惜抓trace会影响一定性能，不能一直抓，等到ANR发生了再抓，又有可能来不及，除非可以预判即将发生ANR，然后提前抓Trace，就可以解决这个问题。

尾巴

本文是在研究字节的文章以后，加上自己一些小实践以后的感悟，要彻底消灭ANR，目前还没有一个非常牛逼手段。由于字节的Raster和Sliver并没有开源，很多信息是我从文章里面推测出来的，如果有理解不到位的点，请大家多多指正。

希望我的文章对你破局ANR问题有一些启发的意义。

最后编辑于：2022.05.13 15:15:52

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