• 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日志，如下：

    1. //关闭返回
    2. 03-08 04:58:26.820 2588 2588 I XxxxLink_HU :  =>> close click.
    4. //AMS执行切换
    5. 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}
    6. 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
    7. 03-08 04:58:26.831 1038 1101 I am_set_resumed_activity : [0,com.xxxx.launcher/.passenger.PassMainActivity,resumeTopActivityInnerLocked]
    8.  
    9. //桌面响应
    10. 03-08 04:58:26.850 1460 1460 I am_on_resume_called : [0,com.xxxx.launcher.passenger.PassMainActivity,RESUME_ACTIVITY]
    11. //切换完成
    12. 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
    13.  
    14. //再次启动CopyScreenMainActivity
    15. 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
    16.  
    17. //执行newIntent流程
    18. 03-08 04:58:27.835 2588 2588 I am_on_resume_called : [0,com.xxxx.entrance.ui.CopyScreenMainActivity,performNewIntents]
    19.  
    20. //AMS执行切换，这时候PassMainActivity被暂停，CopyScreenMainActivity切换到前台。
    21. 03-08 04:58:27.854 1460 1460 I am_on_paused_called : [0,com.xxxx.launcher.passenger.PassMainActivity,performPause]
    22. 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}
    23. 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
    24. 03-08 04:58:27.854 1038 1101 I am_set_resumed_activity : [0,com.yflink.client/com.xxxx.entrance.ui.CopyScreenMainActivity,resumeTopActivityInnerLocked]
    25. //APP响应
    26. 03-08 04:58:27.903 2588 2588 I am_on_resume_called : [0,com.xxxx.entrance.ui.CopyScreenMainActivity,RESUME_ACTIVITY]
    27.  
    28. //这里缺少APP执行finishDrawingWindow的流程，说明window没有注册上。所以最大的可能性就是桌面没有释放
    29. //桌面的Window响应注册
    30. 03-08 04:58:27.938 1038 7512 I WindowManager : finishDrawingWindow: Window{aba4e14 u0 com.xxxx.launcher} mDrawState=DRAW_PENDING
    31.  
    32. 03-08 04:58:28.219 1460 1460 W IPSurfaceView : surfaceDestroyed
    33. 03-08 04:58:28.219 1460 1460 W IPSurfaceView : pause 清空动画
    34. 03-08 04:58:28.219 1460 1460 W IPSurfaceView : destroyThread called
    35. 03-08 04:58:28.220 1460 29148 W System.err : java.lang.InterruptedException
    36. 03-08 04:58:28.220 1460 29148 W System.err :   at java.lang.Object.wait(Native Method)
    37. 03-08 04:58:28.220 1460 29148 W System.err :   at java.lang.Object.wait(Object.java:422)
    38. 03-08 04:58:28.220 1460 29148 W System.err :   at com.xxxx.ipservicesdk.widget.IPSurfaceView.drawLoop(IPSurfaceView.java:360)
    39. 03-08 04:58:28.220 1460 29148 W System.err :   at com.xxxx.ipservicesdk.widget.IPSurfaceView.updateView(IPSurfaceView.java:284)
    40. 03-08 04:58:28.220 1460 29148 W System.err :   at com.xxxx.ipservicesdk.widget.IPSurfaceView$1.run(IPSurfaceView.java:163)
    41. 03-08 04:58:28.220 1460 29148 W System.err :   at java.lang.Thread.run(Thread.java:764)
    42. 03-08 04:58:28.220 1460 29148 W IPSurfaceView : update thread finished com.xxxx.ipservicesdk.widget.IPSurfaceView$1@e78b18c
    43.  
    44. //这里缺少CopyScreenMainActivity完成渲染的日志finishDrawingWindow，说明其没有正常注册窗口。
    45. 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
    46. 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%以上。

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

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

    1. kernel: (couldn't read /proc/self/task/3582/stack)
    2. native: #00 pc 000000000001f06c  /system/lib64/libc.so (syscall+28)
    3. native: #01 pc 00000000000d724c  /system/lib64/libart.so (art::ConditionVariable::WaitHoldingLocks(art::Thread*)+148)
    4. native: #02 pc 00000000005171b0  /system/lib64/libart.so (offset 449000) (_ZN3artL12GoToRunnableEPNS_6ThreadE.llvm.323061163+448)
    5. native: #03 pc 0000000000516fac  /system/lib64/libart.so (offset 449000) (art::JniMethodEnd(unsigned int, art::Thread*)+28)
    6. at android.os.BinderProxy.transactNative(Native method)
    7. at android.os.BinderProxy.transact(Binder.java:1129)
    8. at com.xxxx.accountstub.IAccountData$Stub$Proxy.isLogin(IAccountData.java:538)
    9. at com.xxxx.accountstub.BeanAccountInfoManager.isLogin(BeanAccountInfoManager.java:250)
    10. at com.xxxx.mediacenter.core_account.AccountInfoHub.isLogin(AccountInfoHub.java:231)
    11. at com.xxxx.mediacenter.core_account.AccountInfoHub.getThirdAccountList(AccountInfoHub.java:156)
    12. at com.xxxx.mediacenter.core_account.AccountInfoHub.access$600(AccountInfoHub.java:45)
    13. 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文件中的堆栈：

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

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

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

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

    1. onCreate方法并不耗时，onStartCommand中有调用startForeground的方法但是并未执行，推测执行onStartCommand方法前，有耗时操作。大概率应该是onCreate中post了耗时操作，并且阻塞了超过（30+10=40）秒。

    2. onStartCommand中没有调用startForeground方法，前30S主线程有可能并不阻塞，30S后主线程被阻塞住，从而产生了ANR。

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

    案例结论：

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

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

    案例编号：76621

    案例描述：

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

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

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

    案例分析：

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

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

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

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

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

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

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

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

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

    1. <LinearLayout>
    2.     <com.xxxx.widget.loading.XxxxLoading
    3.     android:id="@+id/loading"
    4.     android:layout_alignBottom="@+id/xxx"
    5.     android:layout_marginEnd="16dp"
    6.     android:layout_toStartOf="@+id/xxxx" />
    7. </LinearLayout>

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

    1. public void onAnimationUpdate(@Nullable PAGView view) {
    2.    this.tryCover();
    3. }
    4.  
    5. private final void tryCover() {
    6.    if (XxxxLoading.this.willDraw) {
    7.       XxxxLoading.this.setWillNotDraw(true);
    8.       XxxxLoading.this.postInvalidate();
    9.    }
    10. }

    案例结论：

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

  • 相关阅读:
    【虚拟机】Windows主机复制的内容，无法粘贴到Ubuntu虚拟机
    JavaScript学习Day005(操作节点)
    易点易动设备管理系统：打通采购管理的智能化设备管理解决方案
    java学习之spirng的aop
    独一无二的设计模式——单例模式（Java实现）
    第六章 数据流建模
    Hadoop之HDFS分布式文件系统
    docker启动，解决jenkins内存占用过高
    剑指-020
    Unity与C#
  • 原文地址：https://blog.csdn.net/AA5279AA/article/details/133965206