记录一次三方App ANR分析过程

溜溜1024

于 2024-07-24 16:58:39 发布

阅读量515

点赞数 1

文章标签： android

本文链接：https://blog.csdn.net/weixin_43761183/article/details/140667670

版权

Monkey 测试出现多次com.google.android.apps.adm ANR

1.在Monkey error中查看com.google.android.apps.adm ANR时候的cpu loading，cpu loading都比较低，大概在20%-30%，应该跟系统负载无关。

// NOT RESPONDING: com.google.android.apps.adm (pid 28188) Time Longth Since Monkey Start: 271764
ANR in com.google.android.apps.adm (com.google.android.apps.adm/.activities.MainActivity)
PID: 28188
Reason: Input dispatching timed out (Application does not have a focused window)
Parent: com.google.android.apps.adm/.activities.MainActivity

CPU usage from 2ms to 7270ms later (2024-07-05 19:08:47.419 to 2024-07-05 19:08:54.688):
27% TOTAL: 13% user + 12% kernel + 0.7% iowait + 0.8% irq + 0.2% softirq

2.分析了两次ANR，发现都是com.google.android.apps.adm的MainActivity的绘制存在异常，导致input超时。

第一份：

012-0707_160625--0707_194326\traces\07-07_175635--anr_2024-07-07-17-56-28-145.log
----- pid 1746 at 2024-07-07 17:56:27.963584411+0800 -----
Cmd line: com.google.android.apps.adm
主线程没有异常
"main" prio=5 tid=1 Native
  | group="main" sCount=1 ucsCount=0 flags=1 obj=0x725686d8 self=0xb4000074f1e3bc00
  | sysTid=1746 nice=-20 cgrp=top-app sched=0/0 handle=0x759a6484f8
  
  at android.os.MessageQueue.nativePollOnce(Native method)
  at android.os.MessageQueue.next(MessageQueue.java:335)
  at android.os.Looper.loopOnce(Looper.java:162)
  at android.os.Looper.loop(Looper.java:294)
  at android.app.ActivityThread.main(ActivityThread.java:8376)
  at java.lang.reflect.Method.invoke(Native method)
  at com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run(RuntimeInit.java:640)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:982)

E:\project\E6707SM\HS63L011XA4617000204\ylog\ap\1\012-0707_160625--0707_194326\2-android.log
InputDispatcher等待MainActivity的Window，从17:56:22.890 开始等待5000ms
M0B2C2D  07-07 17:56:22.890  1145  1281 W InputDispatcher: Waiting because no window has focus but ActivityRecord{a911d67 u0 com.google.android.apps.adm/.activities.MainActivity t7305 d0} may eventually add a window when it finishes starting up. Will wait for 5000ms
MainActivity的OnResumed方法被调用
E0B2C38  07-07 17:56:22.951  1746  1746 I wm_on_resume_called: [177282407,com.google.android.apps.adm.activities.MainActivity,RESUME_ACTIVITY,7]
栈顶
E0B2C69  07-07 17:56:23.012  1746  1746 I wm_on_top_resumed_gained_called: [177282407,com.google.android.apps.adm.activities.MainActivity,topStateChangedWhenResumed]
Input focus要从Settings的WifiSettingsActivity切到MainActivity的window
0B2C89  07-07 17:56:23.034  1145  1574 I WindowManager: Input focus has changed to Window{ea68aca u0 com.google.android.apps.adm/com.google.android.apps.adm.activities.MainActivity}, [type=1]-[Surface(name=*Title#238292)/@0xda57dda, shown=false, alpha=0.0, windowType=1] from c679d61 com.android.settings/com.android.settings.Settings$WifiSettingsActivity mDisplayId 0 updateInputWindows true
请求MainActivity window
E0B2C9D  07-07 17:56:23.037  1145  1186 I input_focus: [Focus request ea68aca com.google.android.apps.adm/com.google.android.apps.adm.activities.MainActivity,reason=UpdateInputWindows]
执行到View的绘制Q:\SPRO_14_SYS\SPRDROID14_SYS_MAIN_W2x.xx.x\idh.code\frameworks\base\core\java\android\view\ViewRootImpl.java的relayoutWindow方法
M0B2C9E  07-07 17:56:23.037  1746  1746 D VRI[MainActivity]: relayoutWindow: maybeSyncSeqId=-1, relayoutResult=3, mLastSyncSeqId=0, mRelayoutSeq=1

cancelDueToPreDrawListener 返回值为true，skip draw
M0B2CC5  07-07 17:56:23.054  1746  1746 D VRI[MainActivity]: reportNextDraw: reason=first_relayoutandroid.view.ViewRootImpl.performTraversals:3992 android.view.ViewRootImpl.doTraversal:2640 android.view.ViewRootImpl$TraversalRunnable.run:9766 android.view.Choreographer$CallbackRecord.run:1399 android.view.Choreographer$CallbackRecord.run:1408 
M0B2CC6  07-07 17:56:23.055  1746  1746 D VRI[MainActivity]: performtraversals: cancelAndRedraw not createSyncIfNeeded, cancelDueToPreDrawListener = true, cancelDraw = false, mDrewOnceForSync = false
M0B2CC7  07-07 17:56:23.055  1746  1746 D VRI[MainActivity]: performtraversals: skip draw, reason=predraw_ham
M0B2CC8  07-07 17:56:23.065  1746  1746 D VRI[MainActivity]: performtraversals: cancelAndRedraw not createSyncIfNeeded, cancelDueToPreDrawListener = true, cancelDraw = false, mDrewOnceForSync = false
M0B2CC9  07-07 17:56:23.065  1746  1746 D VRI[MainActivity]: performtraversals: skip draw, reason=predraw_diy
.......
M0B3963  07-07 17:56:27.886  1746  1746 D VRI[MainActivity]: performtraversals: cancelAndRedraw not createSyncIfNeeded, cancelDueToPreDrawListener = true, cancelDraw = false, mDrewOnceForSync = false
M0B3964  07-07 17:56:27.887  1746  1746 D VRI[MainActivity]: performtraversals: skip draw, reason=predraw_diy
从 07-07 17:56:23.054 到07-07 17:56:27.887  MainActivity的View一直都被skip draw

InputDispatcher等不到可以focus的window，通知WindowManager
WindowManager上报的ANR的事件
M0B3968  07-07 17:56:27.892  1145  1281 W InputDispatcher: ActivityRecord{a911d67 u0 com.google.android.apps.adm/.activities.MainActivity t7305 d0} does not have a focused window,start notifyNoFocusedWindowAnr

下面需要详细分析下MainActivity的View一直被skip draw的原因：

Q:\SPRO_14_SYS\SPRDROID14_SYS_MAIN_W2x.xx.x\idh.code\frameworks\base\core\java\android\view\ViewRootImpl.java
        boolean cancelDueToPreDrawListener = mAttachInfo.mTreeObserver.dispatchOnPreDraw();
        boolean cancelAndRedraw = cancelDueToPreDrawListener
                 || (cancelDraw && mDrewOnceForSync);
                 
        if (!cancelAndRedraw) {
        //这里没有走进去，没有开始draw
        
        } else if (true) {
            Log.d(mTag, "performtraversals: cancelAndRedraw not createSyncIfNeeded"
                    + ", cancelDueToPreDrawListener = " + cancelDueToPreDrawListener
                    + ", cancelDraw = " + cancelDraw + ", mDrewOnceForSync = " + mDrewOnceForSync);
        }
        这个log打印
cancelDueToPreDrawListener 为true，mAttachInfo.mTreeObserver.dispatchOnPreDraw()为true
具体需要看app的注册的Listener为什么返回为true
Q:\SPRO_14_SYS\SPRDROID14_SYS_MAIN_W2x.xx.x\idh.code\frameworks\base\core\java\android\view\ViewTreeObserver.java
    @SuppressWarnings("unchecked")
    public final boolean dispatchOnPreDraw() {
                         final OnPreDrawListener preDrawListener = access.get(i);
                    cancelDraw |= !(preDrawListener.onPreDraw());
                    if (cancelDraw) {
                        mLastDispatchOnPreDrawCanceledReason = preDrawListener.getClass().getName();
                    }
                    }
 cancelDraw 为true,preDrawListener.onPreDraw() 返回为false

M39CD8A  07-24 13:53:37.604 27693 27693 D ViewTreeObserver: addOnPreDrawListener, listener name: diy, listener = diy@858c78b, callers = com.google.android.apps.adm.activities.MainActivity.onCreate:26 android.app.Activity.performCreate:8646 android.app.Activity.performCreate:8624 android.app.Instrumentation.callActivityOnCreate:1459 android.app.ActivityThread.performLaunchActivity:3869 android.app.ActivityThread.handleLaunchActivity:4028 android.app.servertransaction.LaunchActivityItem.execute:103 android.app.servertransaction.TransactionExecutor.executeCallbacks:139 android.app.servertransaction.TransactionExecutor.execute:96 android.app.ActivityThread$H.handleMessage:2535 android.os.Handler.dispatchMessage:106 android.os.Looper.loopOnce:205 android.os.Looper.loop:294 android.app.ActivityThread.main:8376 java.lang.reflect.Method.invoke:-2 com.android.internal.os.RuntimeInit$MethodAndArgsCaller.run:640 
注册的是diy

ps:

Q:\SPRO_14_SYS\SPRDROID14_SYS_MAIN_W2x.xx.x\idh.code\frameworks\base\core\java\android\app\EventLogTags.logtags

# The activity's onTopResumedActivityChanged(true) has been called.
30064 wm_on_top_resumed_gained_called (Token|1|5),(Component Name|3),(Reason|3)
# The activity's onTopResumedActivityChanged(false) has been called.
30065 wm_on_top_resumed_lost_called (Token|1|5),(Component Name|3),(Reason|3)

Q:\SPRO_14_SYS\SPRDROID14_SYS_MAIN_W2x.xx.x\idh.code\frameworks\base\core\java\android\app\Activity.java
    public void onTopResumedActivityChanged(boolean isTopResumedActivity) {
    }
  在Android Q之后会出现多窗口的情况，多个Activity可能同时处于Resume状态，
  Called when activity gets or loses the top resumed position in the system.