[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-14，如有侵权请联系 cloudcommunity@tencent.com 删除
评论
登录后参与评论
推荐阅读
目录