ANR系列之八：疑难ANR问题处理记录

前言：

本文仅是记录作者自身处理过的ANR问题，以及帮助他人解决过的ANR问题。本文中所介绍的ANR处理记录仅供参考，并不适用所有场景。并且最终结论和分析并不一定就是绝对正确的。

案例1.页面切换时前台应用焦点未获得

案例编号：略

案例描述：

自动化验证的时候，偶现ANR，ANR提示如下：

Subject: Input dispatching timed out (Waiting because no window has focus but there is a focused application that may eventually add a window when it finishes starting up.)

案例分析：

这个ANR错误代表应用切换到了前台，但是被切换到前台的应用并没有获取到焦点。仔细查看相关的log日志，如下：

//关闭返回
03-08 04:58:26.820 2588 2588 I XxxxLink_HU :  =>> close click.

//AMS执行切换
03-08 04:58:26.830 1038 1101 W ActivityManager : Resuming top, waiting visible to hide: ActivityRecord{5480ff u0 com.yflink.client/com.xxxx.entrance.ui.CopyScreenMainActivity t40}
03-08 04:58:26.830 1038 1101 W ActivityManager : Resume running: ActivityRecord{8e973ce u0 com.xxxx.launcher/.passenger.PassMainActivity t27} stopped=true visible=false
03-08 04:58:26.831 1038 1101 I am_set_resumed_activity : [0,com.xxxx.launcher/.passenger.PassMainActivity,resumeTopActivityInnerLocked]

//桌面响应
03-08 04:58:26.850 1460 1460 I am_on_resume_called : [0,com.xxxx.launcher.passenger.PassMainActivity,RESUME_ACTIVITY]
//切换完成
03-08 04:58:26.875 1038 2730 I WindowManager : finishDrawingWindow: Window{1632bf9 u0 com.xxxx.launcher/com.xxxx.launcher.passenger.PassMainActivity} mDrawState=DRAW_PENDING

//再次启动CopyScreenMainActivity
03-08 04:58:27.823 1038 2431 I ActivityManager : START u0 {flg=0x10000000 cmp=com.yflink.client/com.xxxx.entrance.ui.CopyScreenMainActivity} from uid 1000 from pid 1460

//执行newIntent流程
03-08 04:58:27.835 2588 2588 I am_on_resume_called : [0,com.xxxx.entrance.ui.CopyScreenMainActivity,performNewIntents]

//AMS执行切换，这时候PassMainActivity被暂停，CopyScreenMainActivity切换到前台。
03-08 04:58:27.854 1460 1460 I am_on_paused_called : [0,com.xxxx.launcher.passenger.PassMainActivity,performPause]
03-08 04:58:27.854 1038 1101 W ActivityManager : Resuming top, waiting visible to hide: ActivityRecord{8e973ce u0 com.xxxx.launcher/.passenger.PassMainActivity t27}
03-08 04:58:27.854 1038 1101 W ActivityManager : Resume running: ActivityRecord{5480ff u0 com.yflink.client/com.xxxx.entrance.ui.CopyScreenMainActivity t40} stopped=false visible=false
03-08 04:58:27.854 1038 1101 I am_set_resumed_activity : [0,com.yflink.client/com.xxxx.entrance.ui.CopyScreenMainActivity,resumeTopActivityInnerLocked]
//APP响应
03-08 04:58:27.903 2588 2588 I am_on_resume_called : [0,com.xxxx.entrance.ui.CopyScreenMainActivity,RESUME_ACTIVITY]

//这里缺少APP执行finishDrawingWindow的流程，说明window没有注册上。所以最大的可能性就是桌面没有释放
//桌面的Window响应注册
03-08 04:58:27.938 1038 7512 I WindowManager : finishDrawingWindow: Window{aba4e14 u0 com.xxxx.launcher} mDrawState=DRAW_PENDING

03-08 04:58:28.219 1460 1460 W IPSurfaceView : surfaceDestroyed
03-08 04:58:28.219 1460 1460 W IPSurfaceView : pause 清空动画
03-08 04:58:28.219 1460 1460 W IPSurfaceView : destroyThread called
03-08 04:58:28.220 1460 29148 W System.err : java.lang.InterruptedException
03-08 04:58:28.220 1460 29148 W System.err :   at java.lang.Object.wait(Native Method)
03-08 04:58:28.220 1460 29148 W System.err :   at java.lang.Object.wait(Object.java:422)
03-08 04:58:28.220 1460 29148 W System.err :   at com.xxxx.ipservicesdk.widget.IPSurfaceView.drawLoop(IPSurfaceView.java:360)
03-08 04:58:28.220 1460 29148 W System.err :   at com.xxxx.ipservicesdk.widget.IPSurfaceView.updateView(IPSurfaceView.java:284)
03-08 04:58:28.220 1460 29148 W System.err :   at com.xxxx.ipservicesdk.widget.IPSurfaceView$1.run(IPSurfaceView.java:163)
03-08 04:58:28.220 1460 29148 W System.err :   at java.lang.Thread.run(Thread.java:764)
03-08 04:58:28.220 1460 29148 W IPSurfaceView : update thread finished com.xxxx.ipservicesdk.widget.IPSurfaceView$1@e78b18c

//这里缺少CopyScreenMainActivity完成渲染的日志finishDrawingWindow，说明其没有正常注册窗口。
03-08 04:58:34.423 1038 2861 I WindowManager : finishDrawingWindow: Window{41c1228 u0 com.gameloft.android.BTCN.GloftA9BT/com.gameloft.android.BTCN.GloftA9BT.MainActivity} mDrawState=DRAW_PENDING
03-08 04:58:34.580 1038 7512 I WindowManager : finishDrawingWindow: Window{41c1228 u0 com.gameloft.android.BTCN.GloftA9BT/com.gameloft.android.BTCN.GloftA9BT.MainActivity} mDrawState=HAS_DRAWN

我们发现，页面切换的时候，理应被切换到前台的Activity执行了resume流程后，却没有执行finishDrawingWindow的流程，并且此时的CPU负载并不高。

详细查看页面切换后5S内的日志，发现有一个桌面悬浮框报错，并且是在渲染更新的时候，所以怀疑是这个悬浮框占据了焦点未释放。

在过去了6S之后，又跳转了下一个页面，这个页面是正常的流程。所以中间那5S的时间PassMainActivity并没有获取到焦点。

问题结论：

应用的Activity是复用的，切换到前台的时候，焦点被上一个应用的延时操作占据，所以导致注册了window之后并没有整的走dispatchDraw流程完成焦点的切换。

其实这个时候如果使用命令：adb shell dumpsys window 获取当前屏幕window的话，焦点应该在IPSurfaceView上面，不过因为是偶现，所以也只能推测。

解决方案是给IPSurfaceView的实现类添加Window的Flag:FLAG_NOT_FOCUSABLE。

案例2.跨进程通信的问题

案例编号：略

案例描述：

开机启动后不久，某些应用直接发生ANR，ANR提示如下：

Subject: Context.startForegroundService() did not then call Service.startForeground()

值得注意的是，此时的CPU负载是很高的。

问题分析：

首先看发生ANR时的负载，此时的CPU负载是很高的，总负载达到了70%以上。

CPU usage from 0ms to 20784ms later (2023-03-10 21:03:42.371 to 2023-03-10 21:04:03.155):
73% 514/surfaceflinger: 45% user + 28% kernel / faults: 5073 minor
51% 3075/com.xxxx.voice: 42% user + 9.4% kernel / faults: 202836 minor 131 major
30% 1483/com.xxxx.beanmap: 17% user + 13% kernel / faults: 49570 minor 12 major
24% 1167/system_server: 11% user + 12% kernel / faults: 20432 minor 2 major
23% 458/android.hardware.graphics.composer@2.2-service: 10% user + 12% kernel / faults: 36 minor
20% 1439/com.xxxx.adapterservice.server: 17% user + 3% kernel / faults: 26796 minor

接下来看ANR时的主线程堆栈，内容如下：

kernel: (couldn't read /proc/self/task/3582/stack)
native: #00 pc 000000000001f06c  /system/lib64/libc.so (syscall+28)
native: #01 pc 00000000000d724c  /system/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
native: #02 pc 00000000005171b0  /system/lib64/libart.so (offset 449000) (_ZN3artL12GoToRunnableEPNS_6ThreadE.llvm.323061163+448)
native: #03 pc 0000000000516fac  /system/lib64/libart.so (offset 449000) (art::JniMethodEnd(unsigned int, art::Thread*)+28)
at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:1129)
at com.xxxx.accountstub.IAccountData$Stub$Proxy.isLogin(IAccountData.java:538)
at com.xxxx.accountstub.BeanAccountInfoManager.isLogin(BeanAccountInfoManager.java:250)
at com.xxxx.mediacenter.core_account.AccountInfoHub.isLogin(AccountInfoHub.java:231)
at com.xxxx.mediacenter.core_account.AccountInfoHub.getThirdAccountList(AccountInfoHub.java:156)
at com.xxxx.mediacenter.core_account.AccountInfoHub.access$600(AccountInfoHub.java:45)
at com.xxxx.mediacenter.core_account.AccountInfoHub$3.run(AccountInfoHub.java:142)

很明显，主线程中此时被阻塞了，阻塞的原因是正在通过binder进行跨进程通讯，但是作为binder的server端迟迟没有响应。

在仔细排查日志，发现作为server一方的那个进程，也正在执行初始化的流程中，所以没有办法响应。总结下来，其实就是开机启动后，有大量的进程执行自启动操作导致CPU被强占，并且由于相关之间还存在依赖关系，从而导致一些本来其实负载并不到的应用也产生了ANR问题。

案例结论：

这种问题，解决方案有两种，从技术上解决和从业务上解决。

从技术上解决：

1.binder通讯放到子线程处理，这样就不会阻塞主线程，但是这样治标不治本，用户仍然无法正常使用业务功能。

2.改为启动后台服务，后台服务的超时时间为200S。但是高版本对后台服务启动有很多限制，而且service未能按时启动仍然会影响业务。

所以从技术上解决，多是治标不治本的方案，并不是太好。

从业务逻辑上解决：

统一收口开机启动的应用，然后通过按需拉起和梯队拉起来解决。

1.取消各个应用的persistent属性，由一个三方应用应用来管控开机之后的拉起操作。至于为什么不放system_server，大家可以自行考虑下原因。

2.按需拉起。自然就是要看是否需要拉起，尤其是在开机阶段是否有必要拉起。

3.梯队拉起。则需要先梳理一下应用之间的相互依赖关系以及相关业务优先级，被依赖的应用以及业务优先级价值较高的被优先拉起。

我们选择的是后者，当然，这需要拉齐所有相关方，成本还是蛮高的，但是我们认为是值得的。

案例3.前台服务启动超时

案例编号：略

案例描述：

应用ANR，异常reason为：

Context.startForegroundService() did not then call Service.startForeground(): ServiceRecord{9c69e1d u0 com.xxxx.mediacenter.passenger/com.xxxx.mediacenter.mediacentermodel.BeanMediaStartService}

这个错误代表被第三方应用通过直接拉起service的方式启动前台服务，并且在service的onStartCommand被调用后的30秒内没有调用startForeground方法，此时系统会通知应用产生一个异常崩溃，但此时主线程卡顿超10S以上，就会出现这种类型的ANR。如果此时主线程不卡顿，那么就会产生一个崩溃。

案例分析：

这个仍然是启动前台服务导致的超时，但是分析下来，和问题2还是有区别的，因为此时整体负载并算很高。

查看ANR文件中的堆栈：

"main" prio=5 tid=1 Runnable
  | group="main" sCount=0 dsCount=0 flags=0 obj=0x7449cb08 self=0x71e9614c00
  | sysTid=3471 nice=0 cgrp=default sched=0/0 handle=0x726f25a550
  | state=R schedstat=( 2284943688 9496195780 2668 ) utm=174 stm=53 core=0 HZ=100
  | stack=0x7feac82000-0x7feac84000 stackSize=8MB
  | held mutexes= "mutator lock"(shared held)
  at java.lang.StringBuilder.append(StringBuilder.java:137)
  at java.util.Arrays.toString(Arrays.java:4511)
  at dalvik.system.DexPathList.toString(DexPathList.java:201)
  at java.lang.String.valueOf(String.java:2896)
  at java.lang.StringBuilder.append(StringBuilder.java:132)
  at dalvik.system.BaseDexClassLoader.findClass(BaseDexClassLoader.java:134)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:379)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:312)
  at com.iqy.iv.plugin.server.core.PluginClassLoader.findClass(PluginClassLoader.java:37)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:379)
  at java.lang.ClassLoader.loadClass(ClassLoader.java:312)
  at java.lang.Class.classForName(Native method)
  at java.lang.Class.forName(Class.java:453)
  at java.lang.Class.forName(Class.java:378)
  at com.qiyi.baselib.utils.device.DeviceUtil.isHarmonyOSByOsBrand(DeviceUtil.java:1089)
  at com.qiyi.baselib.utils.device.DeviceUtil.isHarmonyOs(DeviceUtil.java:1079)
  at org.qiyi.android.coreplayer.utils.CupidAdTool.setCupidSdkStatus(CupidAdTool.java:182)
  at org.qiyi.android.coreplayer.bigcore.BigCoreLibLoader.loadAndInitCup(BigCoreLibLoader.java:402)
  at org.qiyi.android.coreplayer.bigcore.BigCoreLibLoader.loadBigCoreSo(BigCoreLibLoader.java:114)
  at org.qiyi.android.coreplayer.bigcore.DLController.loadLib(DLController.java:533)
  at org.iqiyi.video.facade.LoadLibJob.doInitAndLoadLib(LoadLibJob.java:43)
  at org.iqiyi.video.facade.CarPlayerInit.initLibConfig(CarPlayerInit.java:69)
  at org.iqiyi.video.facade.CommonPlayerInit.initAppForQiyi(CommonPlayerInit.java:91)
  at org.iqiyi.video.facade.CarPlayerInit.initAppForQiyi(CarPlayerInit.java:48)
  at org.iqiyi.video.facede.QYAppFacede.init(QYAppFacede.java:142)
  at org.iqiyi.video.facede.QYAppFacede.initAppForQiyi(QYAppFacede.java:153)
  at com.qiyi.ivsdk.init.InitHelper.initNecessaryForPlayerSync(InitHelper.java:399)
  at com.qiyi.ivsdk.init.InitHelper.init(InitHelper.java:145)
  at com.iqy.iv.sdk.PlayerSdkImpl.initialize(unavailable:104)
  at com.iqy.iv.sdk.PlayerSdkProxy.initSDK(PlayerSdkProxy.java:159)
  at com.iqy.iv.sdk.PlayerSdkProxy$2.handleMessage(PlayerSdkProxy.java:78)
  at android.os.Handler.dispatchMessage(Handler.java:106)
  at android.os.Looper.loop(Looper.java:193)
  at android.app.ActivityThread.main(ActivityThread.java:6734)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:506)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:858)

在进行爱奇艺SDK的初始化，并且在主线程，但是调用堆栈并不是在application或者service的onCreate方法，说明应该是通过handler.post等方法进行过切换。

上面说到，这种ANR，是30S内service中没有调用startForeground方法，并且30S后主线程处于阻塞状态无法处理系统传递过来的崩溃。出现了这种ANR，如果主线程不阻塞，那么就会Crash。

所以推测应该是下面两种场景之一导致的：

onCreate方法并不耗时，onStartCommand中有调用startForeground的方法但是并未执行，推测执行onStartCommand方法前，有耗时操作。大概率应该是onCreate中post了耗时操作，并且阻塞了超过（30+10=40）秒。
onStartCommand中没有调用startForeground方法，前30S主线程有可能并不阻塞，30S后主线程被阻塞住，从而产生了ANR。

最终通过查看相关日志，确定属于上面的场景1，并且通过分析确定，单单PlayerSdkProxy.initSDK方法耗时并不是很多，但是onCreate中通过post添加了很多耗时任务，导致累计超时。

案例结论：

解决方案很简单，按需加载，没有必要在service启动的时候一下子初始化那么多的SDK。改成懒加载机制，等service走完生命周期创建后在初始化。

问题4.隐藏的动画导致ANR

案例编号：76621

案例描述：

仍然是自动化验证，发现进入某个应用之后，很容易发生ANR问题，并且该应用ANR之后，进入其它应用也极易发生ANR问题。

发生ANR的堆栈，指向系统注册窗口的时机。

at android.os.BinderProxy.transactNative(Native method)
at android.os.BinderProxy.transact(Binder.java:1129)
at android.view.IWindowSession$Stub$Proxy.addToDisplay(IWindowSession.java:825)
at android.view.ViewRootImpl.setView(ViewRootImpl.java:757)
locked <0x06fcde80> (a android.view.ViewRootImpl)
at android.view.WindowManagerGlobal.addView(WindowManagerGlobal.java:356)
locked <0x0c75ecb9> (a java.lang.Object)
at android.view.WindowManagerImpl.addView(WindowManagerImpl.java:95)

案例分析：

乍一看，既然阻塞到向系统注册的时候，那么应该是系统问题。但是这里有一个疑点，那就是为什么每次这个应用甲ANR之后（我们暂且称之为应用甲），都会影响到其它的，理论上应用之间是相互独立的才对。所以，就把方向放到应用甲和系统窗口交互之间的原因上，怀疑有可能应用甲和系统过分的交互导致系统侧过载，从而间接的影响了其他的应用。

我们观察当时的日志，发现多次ANR都是发生在从MainActivity跳转WebViewActivity的时候。

//1. MainActivity pasue，准备跳转
09-30 01:39:27.803 1112 2086 I am_pause_activity : [0,111178572,com.xxxx.scenemanage/.MainActivity,userLeaving=true]
09-30 01:39:27.808 8046 8046 I am_on_paused_called : [0,com.xxxx.scenemanage.MainActivity,performPause]
//2. 进入WebViewActivity
09-30 01:39:27.857 8046 8046 I am_on_create_called : [0,com.xxxx.scenemanage.webkit.WebViewActivity,performCreate]
09-30 01:39:30.505 8046 8046 I am_on_resume_called : [0,com.xxxx.scenemanage.webkit.WebViewActivity,RESUME_ACTIVITY]
//3. 发生ANR了
09-30 01:39:33.799 1112 1198 I InputDispatcher : Application is not responding: Window
{91f7011 u0 com.xxxx.scenemanage/com.xxxx.scenemanage.WebViewActivity}

所以，缩小范围，应该是MainActivity页面WebViewActivity的onResume之前，有大量和系统侧的交互。

虽然我们不能复现当时的ANR场景，但是我们按照这个流程走一遍，并且通过top命令和systemtrace进行观察，还是能发现一些端倪的。我们发现进入到MainActivity，并且切换到FragmentB之后，TOP中SF和应用甲的负载会持续维持在高位，这是很不正常的，因为此时页面是静止的。

600%cpu  67%user   2%nice  51%sys 511%idle   0%iow   7%irq   2%sirq   0%host    
  PID USER         PR  NI VIRT  RES  SHR S[%CPU] %MEM     TIME+ ARGS            
  500 system       -2  -8 2.0G  34M  26M S 44.6   0.3 679:20.26 surfaceflinger
  20461 system       -3  -3  57M  17M  13M S  29.3   0.1 269:44.60 com.xxxx.scenemanage
...

结合systemtrace的线程分析，发现即使页面处于静止状态，RenderThread仍持续在跑，说明应用甲的代码中有地方在持续请求刷新的操作。最简单的方案，自然是断点打到ThreadedRender的draw方法中，看看到底谁在调用，但是发现，静止状态下，这里并没有被执行，所以说明是另外的地方直接请求native的方法进行请求刷新操作。

所以怀疑方向有两个：1.代码中是否有调用SO的地方；2.是否有执行相关的动画。

查完代码后，发现方向1不存在这种可能性。于是查看动画相关的代码，这时候，终于发现了根因。

<LinearLayout>
    <com.xxxx.widget.loading.XxxxLoading
    android:id="@+id/loading"
    android:layout_alignBottom="@+id/xxx"
    android:layout_marginEnd="16dp"
    android:layout_toStartOf="@+id/xxxx" />
</LinearLayout>

切换到FragmentB后，XxxxLoading处于visible状态，但是由于不再屏幕范围内，所以对用户是无感的。但是其一直有执行相关的动作操作，从而导致不断的请求执行绘制流程，从而导致了系统侧SF处于高负载状态，最终从而导致了ANR的发生。

public void onAnimationUpdate(@Nullable PAGView view) {
   this.tryCover();
}

private final void tryCover() {
   if (XxxxLoading.this.willDraw) {
      XxxxLoading.this.setWillNotDraw(true);
      XxxxLoading.this.postInvalidate();
   }
}

案例结论：

解决方案很简单，默认隐藏XxxxLoading即可，XxxxLoading中设置为gone就不会走invalidate流程。