Android机顶盒M1上ANR问题的排查方法和应对方案

安卓 专栏收录该内容
6 篇文章 0 订阅

1. ANR的理论背景

1.1 ANR的定义

ANR是Application Not Response的英文缩写,即应用程序无响应。当某个应用(非visible)出现ANR时,会在主界面中弹出一个“应用无响应”的弹出框,严重影响用户体验。

ANR是Android自身消息调度逻辑中的一套针对应用的耗时检测机制,每一个应用都是依靠UI主线程去绘制画面从而展现给用户,但是,这其中就可能出现某些应用的UI主线程

中由于逻辑太过复杂或者UI主线程未能在有限的时间内处理完四大组件(Activity、Service、Broadcast和Content Provider)的特定逻辑,Android为了防止不影响其自身消息调度

逻辑中的其他消息的传递,于是通过ANR的机制来报告给用户,用户在其弹出的窗口中可以选择“等待”或者“关闭应用”。

1.2 ANR的机制

Android定义了四大组件的ANR机制,具体如下表:

组件名称耗时字段定义耗时字耗时阈值含义
 Activity KEY_DISPATCHING_TIMEOUT 5秒针对某个应用进行有效按键后,其未在该阈值内响应则会出现ANR
 Service

SERVICE_TIMEOUT

SERVICE_BACKGROUND_TIMEOUT

前台服务20秒

后台服务200秒

Service的主线程(如onCreate、onStartCommand等)中执行逻辑的时间超过此阈值时则会出现ANR
Broadcast

BROADCAST_BG_TIMEOUT

BROADCAST_FG_TIMEOUT

后台广播60秒

前台广播10秒

广播的主线程(onReceive)中执行逻辑的时间超过此阈值时则会出现ANR
Content ProviderCONTENT_PROVIDER_PUBLISH_TIMEOUT 10秒Content Provider的主线程(onReceive)中执行逻辑的时间超过此阈值时则会出现ANR

一旦上述组件出现ANR时,其最终会调用

final void appNotResponding(ProcessRecord app, ActivityRecord activity,  ActivityRecord parent, boolean aboveSystem, final String annotation) {

该方法中有如下2个问题值得关注:

(1)是否所有应用出现ANR时都会弹出“应用无响应”的弹出框呢?

答案是否,简而言之,对于后台无可见的应用出现ANR时,Android就不会弹出“应用无响应”的弹出框,如下代码所示

// Don't dump other PIDs if it's a background ANR
isSilentANR = !showBackground && !app.isInterestingToUserLocked() && app.pid != MY_PID;
synchronized (mService) {
    mService.mBatteryStatsService.noteProcessAnr(app.processName, app.uid);

 if (isSilentANR) {
        app.kill("bg anr", true);
 return;
 }

    // Set the app's notResponding state, and look up the errorReportReceiver
 makeAppNotRespondingLocked(app,
 activity != null ? activity.shortComponentName : null,
 annotation != null ? "ANR " + annotation : "ANR",
 info.toString());

 // Bring up the infamous App Not Responding dialog
 Message msg = Message.obtain();
 HashMap<String, Object> map = new HashMap<String, Object>();
 msg.what = ActivityManagerService.SHOW_NOT_RESPONDING_UI_MSG;
 msg.obj = map;
 msg.arg1 = aboveSystem ? 1 : 0;
 map.put("app", app);
 if (activity != null) {
        map.put("activity", activity);
 }

    mService.mUiHandler.sendMessage(msg);
}

(2)是否有简单的方法设定当任意应用出现ANR时,Android都不会弹出“应用无响应”的弹出框呢?

有方法的,根据上述第(1)点中的代码逻辑,可以指定showBackground的值,设定的方法为  settings put secure anr_show_background 1

2. NunaiM1上的ANR问题

2.1 ANR的监测

为了更好的统计M1上ANR问题的数量和分析ANR问题,我们在上述appNotResponding方法中新增了一个广播(com.mgtv.anrsurveyor.ANREvent),当出现ANR时,系统就会发送该广播;

牛奶管家在接收到该广播后,会将出现ANR的应用相关信息(包括部分trace日志信息)上报到后台,从而方便后台数据统计和分析。具体的统计和分析方法详见下述wiki:

每日ANR追踪手册

TV OS ANR 事件

2.2 M1上ANR问题的处理成效

M1的版本ANR率主要优化点
OTA19.297%M1刚出来的版本,许多自研应用都有ANR现象
OTA34.8293%优化防自启和应用进程清理逻辑
OTA42.2437%优化自研应用占用的内存
OTA52.189%优化语音和若干第三方预置应用
OTA61.790%对自研应用的apk占用大小瘦身,进一步梳理应用占用的内存;将按键耗时阈值更改为8秒;优化LogEx日志逻辑;
OTA7 待观察 修改对第三方应用的dex2oat优化模式为interpret-only;修改Service的耗时阈值为40秒;优化设置中的ContentProvider逻辑;优化MyApp在OTA后首次启动容易出现ANR的逻辑

2.3 ANR问题的分析方法和案例

ANR问题的分析需要足够的日志,主要是如下log,可以按照如下方式获取:

(1)trace日志:该日志会打印出现ANR时的调用栈信息,获取方法为 adb pull data/anr/traces.txt

(2)dropbox日志:dropbox中会记录许多系统问题的log,如watch dog,system_server重启,ANR等,获取方法为  adb pull data/system/dropbox

(3)logcat日志:该日志会记录系统和应用在ANR时间段内的业务逻辑

2.3.1 UI主线程耗时

这块导致的ANR问题比较容易排查,一般都可以在traces.txt中的调用栈中找到耗时的业务逻辑,其解决的办法是优化主线程的耗时逻辑或者将耗时逻辑放入其他子线程中处理;

2.3.2 死锁

理论依据:两个不同的线程相互持有一把锁,从而导致一直在相互等待而出现阻塞的现象,使得UI主线程的逻辑不能够在ANR指定的耗时阈值内处理完成,进而出现ANR现象。

案例:在一次monkey的测试中,发现tvapp的traces.txt文件中存在如下log信息 

"main" prio=5 tid=1 Blocked
  | group="main" sCount=1 dsCount=0 obj=0x740474a0 self=0xa9e84400
  | sysTid=22004 nice=-10 cgrp=default sched=0/0 handle=0xacbf5534
  | state=S schedstat=( 1469603877 91534058 824 ) utm=117 stm=29 core=2 HZ=100
  | stack=0xbe630000-0xbe632000 stackSize=8MB
  | held mutexes=
  at com.mgtv.tv.sdk.reporter.d.a(ErrorReporter.java:70)
  - waiting to lock <0x0a575532> (a java.lang.Class<com.mgtv.tv.sdk.reporter.d>) held by thread 15
  at com.mgtv.tv.a.a.a(AppStartPresenter.java:354)
  at com.mgtv.tv.launcher.LauncherActivity.b(LauncherActivity.java:142)
  at com.mgtv.tv.a.a$2.run(AppStartPresenter.java:90)
  at android.os.Handler.handleCallback(Handler.java:755)
  at android.os.Handler.dispatchMessage(Handler.java:95)
  at android.os.Looper.loop(Looper.java:154)
  at android.app.ActivityThread.main(ActivityThread.java:6125)
  at java.lang.reflect.Method.invoke!(Native method)
  at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:915)
  at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:805)

从上述调用栈来看,ANR的主要原因是死锁导致的阻塞,结合源码去分析,发现Sdk-Reporter模块com/mgtv/tv/sdk/reporter/ErrorReporter.java 文件中,通过synchronized设定了ErrorReporter的全局锁,

这样就导致其他类在使用该类reportReportCache或者writeReportCache方法时,很容易出现死锁。这个问题的解决办法是在ErrorReporter类中新建一个对象锁(Object mReportCacheLock = new Object();)。

    /**
     * 上报缓存埋点数据
     */
    public void reportReportCache(){
        MGLog.i(TAG,"reportReportCache");
        ThreadUtils.startRunInThread(new Runnable() {
            @Override
            public void run() {
                synchronized (ErrorReporter.class){
                    String cacheDirPath = ContextProvider.getApplicationContext().getFilesDir().getAbsolutePath() +
                            File.separator + REPORT_CACHE_FILE;
                    File dir = new File(cacheDirPath);
                    if (!dir.exists() || !dir.isDirectory()){
                        return;
                    }
                    File[] files = dir.listFiles();
                    if (files == null || files.length <= 0){
                        return;
                    }
                    MGLog.i(TAG,"reportReportCache files size = "+files.length);
                    for (int i = files.length - 1; i >= 0; i--) {
                        try {
                            if (files[i] == null || !files[i].exists()){
                                continue;
                            }
                            //网络连接成功时,才能上报缓存错误信息
                            if (NetWorkUtils.isNetAvailable(ContextProvider.getApplicationContext())
                                    && NetWorkUtils.isRouteAvailable(ServerSideConfigs.getOutnetPingIps())){
                                MGLog.i(TAG,"reportReportCache files path = "+files[i].getAbsolutePath());
                                ErrorReportParameter reportParameter = (ErrorReportParameter) FileUtils.
                                        readObjectByAbsolutePath(files[i].getAbsolutePath());
                                files[i].delete();
                                report(reportParameter);
                            }
                        } catch (Exception e) {
                            e.printStackTrace();
                        }
                    }
                }
            }
        });
    }

    private void writeReportCache(final ErrorReportParameter parameter){
        if (parameter == null){
            return;
        }
        ThreadUtils.startRunInThread(new Runnable() {
            @Override
            public void run() {
                synchronized (ErrorReporter.class){
                    try {
                        //超过缓存错误上报条数时,删除历史报错缓存
                        String cacheDirPath = new StringBuilder()
                                .append(ContextProvider.getApplicationContext().getFilesDir().getAbsolutePath())
                                .append(File.separator)
                                .append(REPORT_CACHE_FILE).toString();
                        File[] files = FileUtils.orderByDate(cacheDirPath);
                        if (files != null){
                            int length = files.length;
                            MGLog.i(TAG,"writeReportCache cache file count:" + length);
                            if (length >= CACHE_MAX_NUM){
                                for (int i = 0; i <= length - CACHE_MAX_NUM; i++) {
                                    files[i].delete();
                                }
                            }
                        }
                        String fileName = MD5Util.MD5(parameter.getErrorCode() + parameter.getErrorMessage());
                        String filePath = new StringBuilder().append(cacheDirPath)
                                .append(File.separator)
                                .append(fileName)
                                .toString();
                        if (FileUtils.isFileExist(filePath)){
                            MGLog.i(TAG,"writeReportCache fileName:"+fileName + "is exist.");
                            return;
                        }
                        FileUtils.writeObject(parameter,new StringBuilder().append(REPORT_CACHE_FILE)
                                .append(File.separator).append(fileName).toString());
                    } catch (Exception e) {
                        e.printStackTrace();
                    }
                }
            }
        });

    }

2.3.3 静态广播

理论依据:此处仅描述后台广播,因为绝大多数的场景下,我们都是使用的后台广播,在ANR的机制中,后台广播的超时时长是60秒

案例:在RT2969机器(性能低)上,monkey测试(throttle = 1秒)的场景下发现牛奶桌面出现ANR的概率较高,从log中看,出现许多类似下面的信息 

08-13 12:38:10.489  4999  4999 I TVOSApplication: TVOSApplication onCreate:com.mgtv.mgui,OUTPUT_TIME=20190802_182835Build flavor=DZ_RT2969,Device channel=DZ

08-13 12:39:09.719   477   491 W BroadcastQueue: Timeout of broadcast BroadcastRecord{42a017d0 u0 com.mgtv.mgui.ALARM_RECEIVER_ACTION} - receiver=android.os.BinderProxy@42a59c20, started 60009ms ago
08-13 12:39:09.719   477   491 W BroadcastQueue: Receiver during timeout: ResolveInfo{429de308 com.mgtv.mgui/com.mgtv.tvos.launcher.home.service.NunaiAlarmReceiver m=0x108000}

08-13 12:39:11.069   477   491 I Process : Sending signal. PID: 4999 SIG: 9
08-13 12:39:11.069   477   491 E ActivityManager: ANR in com.mgtv.mgui
08-13 12:39:11.069   477   491 E ActivityManager: PID: 4999
08-13 12:39:11.069   477   491 E ActivityManager: Reason: Broadcast of Intent { act=com.mgtv.mgui.ALARM_RECEIVER_ACTION flg=0x14 cmp=com.mgtv.mgui/com.mgtv.tvos.launcher.home.service.NunaiAlarmReceiver (has extras) }
08-13 12:39:11.069   477   491 E ActivityManager: Load: 0.16 / 0.25 / 0.91
08-13 12:39:11.069   477   491 E ActivityManager: CPU usage from 55015ms to 0ms ago:
08-13 12:39:11.069   477   491 E ActivityManager:   1.1% 82/keypad: 0.2% user + 0.9% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0.7% 4094/com.cibn.tv: 0.5% user + 0.1% kernel / faults: 427 minor
08-13 12:39:11.069   477   491 E ActivityManager:   0.6% 1297/top: 0% user + 0.5% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0.1% 86/surfaceflinger: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0.1% 477/system_server: 0% user + 0% kernel / faults: 8 minor
08-13 12:39:11.069   477   491 E ActivityManager:   0.1% 4763/com.mango.dangbeimarket: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0% 51/mmcqd/0: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0% 2881/com.cibn.tv:channel: 0% user + 0% kernel / faults: 17 minor
08-13 12:39:11.069   477   491 E ActivityManager:   0% 1679/kworker/u3:2: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0% 133/sdcard: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0% 50/cp_hotplug: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0% 591/com.android.systemui: 0% user + 0% kernel / faults: 5 minor
08-13 12:39:11.069   477   491 E ActivityManager:   0% 1295/logcat: 0% user + 0% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   0% 4999/com.mgtv.mgui: 0% user + 0% kernel / faults: 167 minor
08-13 12:39:11.069   477   491 E ActivityManager: 1.8% TOTAL: 0.7% user + 0.9% kernel + 0% iowait
08-13 12:39:11.069   477   491 E ActivityManager: CPU usage from 824ms to 1334ms later:
08-13 12:39:11.069   477   491 E ActivityManager:   1.5% 82/keypad: 0% user + 1.5% kernel
08-13 12:39:11.069   477   491 E ActivityManager:   1.9% 477/system_server: 0% user + 1.9% kernel
08-13 12:39:11.069   477   491 E ActivityManager:     1.9% 491/ActivityManager: 0% user + 1.9% kernel
08-13 12:39:11.069   477   491 E ActivityManager: 2% TOTAL: 0% user + 2% kernel
08-13 12:39:11.099   477  4919 I ActivityManager: Process com.mgtv.mgui (pid 4999) has died.

通过查看牛奶桌面中有关NunaiAlarmReceiver的源码后,发现com.mgtv.mgui.ALARM_RECEIVER_ACTION是一个静态注册广播,NunaiAlarmManagerService会每隔5min发送一个PendingIntent(包含该action),

当桌面进程因ANR被系统干掉之后,由于有序广播队列中还存在com.mgtv.mgui.ALARM_RECEIVER_ACTION广播,继而会拉活牛奶桌面,此时在启动牛奶桌面的过程中也需要耗时,再加上该monkey场景下的

可用内存已经只有80-100MB了(低内存状态下),系统整体性能偏低了,所以在没有在60秒的时间内执行完onReceive中的逻辑(尽管该逻辑未存在耗时逻辑,但也可能由于CPU资源调度未能执行到该逻辑),

所以很容易导致广播耗时(超过20s)从而出现ANR。

2.3.4 系统可用内存不足

理论依据:在系统的可用内存不足(若干应用需要申请的内存不够)时,系统会频繁的触发GC(当然,系统内存足够的情况下,也可能会触发GC),如GC_CONCURRENT,而GC_CONCURRENT会导致线程阻塞;

另外,在这种场景下,系统的整体性能偏低,CPU等资源的调度不及时,容易导致ANR

案例:在RT2969机器(性能低)上,monkey测试(throttle = 1秒)的场景下发现牛奶桌面出现ANR的概率较高,从log中看,出现许多类似下面的信息 

从logcat.rar日志来看,牛奶桌面(com.mgtv.mgui)总共有10处ANR,其中6处来自广播(com.mgtv.mgui/com.mgtv.tv.contentDesktop.core.NetStatusReceiver)耗时超过60s,

4处来自service(com.mgtv.mgui/com.mgtv.apkmanager.service.ApkManagerService)耗时超过20s。其出现ANR的主要原因是系统可用内存不足,GC频繁会引起内存频繁抖动,

消耗太多系统资源,容易引起卡顿(GC阻塞,dalvikvm: WAIT_FOR_CONCURRENT_GC blocked)。

这种场景下,优化的建议是:

(1)从优化内存的角度去考虑,如从framework层去禁止不该在后台启动的应用;增加应用进程清理机制(调用forceStopPackage或者killBackgroundProcesses方法,其中forceStopPackage方法需要调用者有系统签名或者system权限);

(2)重构应用的逻辑,比如因为广播而ANR(这种情况下,大概率不是因为广播onReceive的业务逻辑耗时导致),则考虑该广播是否一定需要?

(3)如果可以调整framework,则可以考虑延长ANR的阈值(BROADCAST_BG_TIMEOUT、KEY_DISPATCHING_TIMEOUT、SERVICE_TIMEOUT)

08-22 21:48:25.439 23832 23832 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 4ms
08-22 21:48:25.699 23832 23832 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 7ms
08-22 21:48:25.999 23832 23832 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 5ms
08-22 21:48:26.099 23832 23832 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 8ms
08-22 21:49:25.739 15417 15451 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 38ms
08-22 21:49:25.739 15417 23863 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 38ms
08-22 21:49:25.749 15417 23864 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 13ms
08-22 21:49:27.159   479   493 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 63ms
08-22 21:49:35.589 22354 22377 D dalvikvm: WAIT_FOR_CONCURRENT_GC blocked 17ms

2.3.5 CPU调度不及时

理论依据:任何逻辑都需要CPU的调度才能够被执行,在某种CPU资源很紧张的情况下,某些逻辑很可能迟迟得不到执行

案例:在NunaiM1机器上,monkey测试(throttle = 1秒)的场景下会出现若干应用的ANR,例如如下日志信息中的net.myvst.v2出现的ANR,从表面上来分析,它是因为广播超时导致的ANR,

由于看不到该应用的源码,我们也不能排除其广播接收者中是否真的有耗时逻辑,但是从这份log信息中还发现一点非常可以的现象,即在2019-08-26 18:52:50.808 to 2019-08-26 18:54:11.323

的时间段内,net.myvst.v2占用的CPU是0,而广播耗时的阈值时60秒,这60秒中,net.myvst.v2应用未能得到CPU的调度,初步可以断定,此时系统的CPU资源已经非常紧张了。从日志来看,

com.iflytek.xiri占用84%,由于M1是4核CPU,com.iflytek.xiri占用21%,从讯飞处了解,这个程度的CPU占用率是必须的,因此这块优化空间不大;system_server和mmcqd占用的CPU较多,

这块应该主要与logservice进程将log写到sdcard或者还有其他进程操作sdcard所致(monkey场景下,这种现象可以理解);com.cibn.tv占用较多CPU,由于牛奶管家中的应用进程清理不清理酷喵,

因此允许酷喵活跃在后台。综上分析,这类ANR的问题,暂无有效的应对方法,如果一定要解决,只能往“调整ANR阈值”的方向去考虑了。

08-26 18:54:14.517   483   497 E ActivityManager: ANR in net.myvst.v2
08-26 18:54:14.517   483   497 E ActivityManager: PID: 3537
08-26 18:54:14.517   483   497 E ActivityManager: Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x50000014 (has extras) }
08-26 18:54:14.517   483   497 E ActivityManager: Load: 0.0 / 0.0 / 0.0
08-26 18:54:14.517   483   497 E ActivityManager: CPU usage from 80515ms to 0ms ago (2019-08-26 18:52:50.808 to 2019-08-26 18:54:11.323):
08-26 18:54:14.517   483   497 E ActivityManager:   84% 27641/com.iflytek.xiri: 80% user + 4.3% kernel / faults: 13753 minor 3 major
08-26 18:54:14.517   483   497 E ActivityManager:   19% 483/system_server: 12% user + 7% kernel / faults: 43756 minor 439 major
08-26 18:54:14.517   483   497 E ActivityManager:   14% 111/mmcqd/0: 0% user + 14% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   13% 1368/com.cibn.tv: 9% user + 4.3% kernel / faults: 26705 minor 563 major
08-26 18:54:14.517   483   497 E ActivityManager:   11% 75/kswapd0: 0% user + 11% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   7.8% 17468/com.mgtv.mgui: 6.3% user + 1.4% kernel / faults: 25195 minor 275 major
08-26 18:54:14.517   483   497 E ActivityManager:   7% 158/surfaceflinger: 2.3% user + 4.7% kernel / faults: 1777 minor
08-26 18:54:14.517   483   497 E ActivityManager:   4.9% 713/sdcard: 0.3% user + 4.6% kernel / faults: 184 minor 1 major
08-26 18:54:14.517   483   497 E ActivityManager:   2% 192/logd: 0.7% user + 1.3% kernel / faults: 757 minor 16 major
08-26 18:54:14.517   483   497 E ActivityManager:   1.2% 662/com.mgtv.surveyor: 0.7% user + 0.4% kernel / faults: 9052 minor 79 major
08-26 18:54:14.517   483   497 E ActivityManager:   1.1% 201/audioserver: 0.7% user + 0.4% kernel / faults: 461 minor
08-26 18:54:14.517   483   497 E ActivityManager:   1% 32161/com.mgtv.tv.userpaycenter: 0.6% user + 0.3% kernel / faults: 10112 minor 32 major
08-26 18:54:14.517   483   497 E ActivityManager:   0.6% 210/netd: 0.1% user + 0.5% kernel / faults: 1353 minor 1 major
08-26 18:54:14.517   483   497 E ActivityManager:   0.6% 1753/com.android.commands.monkey: 0.4% user + 0.1% kernel / faults: 4041 minor 126 major
08-26 18:54:14.517   483   497 E ActivityManager:   0.6% 76/ksmd: 0% user + 0.6% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.3% 57/cfinteractive: 0% user + 0.3% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.2% 52/vmalloc: 0% user + 0.2% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.2% 157/servicemanager: 0% user + 0.1% kernel / faults: 533 minor
08-26 18:54:14.517   483   497 E ActivityManager:   0.2% 8/rcu_preempt: 0% user + 0.2% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 55/fb-vsync: 0% user + 0.1% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 56/rk-fb: 0% user + 0.1% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 198/zygote: 0% user + 0.1% kernel / faults: 2523 minor 15 major
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 3/ksoftirqd/0: 0% user + 0.1% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 151/jbd2/mmcblk0p14: 0% user + 0.1% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 2568/kworker/u9:2: 0% user + 0.1% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 870/com.mgtv.surveyor:log: 0% user + 0% kernel / faults: 2058 minor 237 major
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 1210/com.sohu.inputmethod.sogou.tv: 0% user + 0% kernel / faults: 992 minor 19 major
08-26 18:54:14.517   483   497 E ActivityManager:   0.1% 34/kconsole: 0% user + 0.1% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 24/ksoftirqd/3: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 862/kworker/u9:0: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 25148/kworker/3:0: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 946/com.mgtv.voice: 0% user + 0% kernel / faults: 800 minor 172 major
08-26 18:54:14.517   483   497 E ActivityManager:   0% 124/kworker/0:1H: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 209/mediaserver: 0% user + 0% kernel / faults: 506 minor 9 major
08-26 18:54:14.517   483   497 E ActivityManager:   0% 31509/kworker/u8:4: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 14/ksoftirqd/1: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 19/ksoftirqd/2: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 3123/kworker/u8:5: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 156/lmkd: 0% user + 0% kernel / faults: 118 minor
08-26 18:54:14.517   483   497 E ActivityManager:   0% 1897/kworker/u8:2: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 22180/kworker/u8:6: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 30568/kworker/0:2: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 32/kworker/2:1: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 362/kworker/1:0: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 20496/kworker/u8:3: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:   0% 1//init: 0% user + 0% kernel / faults: 64 minor
08-26 18:54:14.517   483   497 E ActivityManager:   0% 197/sh: 0% user + 0% kernel / faults: 378 minor 2 major
08-26 18:54:14.517   483   497 E ActivityManager:   0% 17661/com.mgtv.ota: 0% user + 0% kernel / faults: 233 minor
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3478/com.mgtv.mediaplayer: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3537/net.myvst.v2: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3583/logcat: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3626/logcat: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3778/net.myvst.v2:guard: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3829/com.pptv.tvsports.preinstall.a: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3870/com.pptv.tvsports.preinstall:ppdata: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 3909/com.pptv.tvsports.preinstall:guard: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 4081/com.moretv.android: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager:  +0% 4101/com.moretv.android:moretvService: 0% user + 0% kernel
08-26 18:54:14.517   483   497 E ActivityManager: 89% TOTAL: 43% user + 17% kernel + 26% iowait + 1.4% softirq
08-26 18:54:14.517   483   497 E ActivityManager: CPU usage from 9119233ms to 9119233ms ago (1970-01-01 08:00:00.000 to 1970-01-01 08:00:00.000) with 0% awake:
08-26 18:54:14.517   483   497 E ActivityManager: 0% TOTAL: 0% user + 0% kernel

2.3.6 CPU Loading或者IO Wait高

理论依据:当出现ANR时,logcat日志中会输出CPU占用率的信息,但是这个占用率会与CPU的核数相关,例如通过top命令查看某个进程的CPU占用率为1%,则在该logcat日志中

展现的CPU占用率为4%,所以,从这个来看,logcat日志中输出的某个应用的CPU usage有可能达到400%。

案例:M1中monkey测试的log中有如下信息,设置的CPU占用率微高,但是从Load来看(14.81 / 11.55 / 9.45分别表示1min、5min、15min中的CPU负载,其值超过4就算高的了),也就是说在15min内,

CPU的负载始终比较高。从日志中也没能看出是设置的某个类或者逻辑导致CPU较高的信息,这类ANR问题,初步只能定位到是monkey场景导致的CPU loading高所致,系机器自身性能瓶颈问题,

暂没有有效的应对方案。

另外,如果在日志信息中有发现某个进程的iowait较高,则需要去排查该应用是否存在操作io的耗时逻辑。

08-26 09:57:14.276   491   525 E ActivityManager: ANR in com.mgtv.setting (com.mgtv.setting/.home.HomeActivity)
08-26 09:57:14.276   491   525 E ActivityManager: PID: 17274
08-26 09:57:14.276   491   525 E ActivityManager: Reason: 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.)
08-26 09:57:14.276   491   525 E ActivityManager: Load: 14.81 / 11.55 / 9.45
08-26 09:57:14.276   491   525 E ActivityManager: CPU usage from 0ms to 6331ms later (2019-08-26 09:57:07.919 to 2019-08-26 09:57:14.251):
08-26 09:57:14.276   491   525 E ActivityManager:   87% 1594/com.iflytek.xiri: 83% user + 3.7% kernel / faults: 1913 minor 57 major
08-26 09:57:14.276   491   525 E ActivityManager:   48% 17274/com.mgtv.setting: 38% user + 10% kernel / faults: 10338 minor 61 major
08-26 09:57:14.276   491   525 E ActivityManager:   30% 491/system_server: 17% user + 12% kernel / faults: 2533 minor 527 major
08-26 09:57:14.276   491   525 E ActivityManager:   16% 159/surfaceflinger: 5% user + 11% kernel / faults: 187 minor 2 major
08-26 09:57:14.276   491   525 E ActivityManager:   9.6% 1517/com.mgtv.mgui: 6.3% user + 3.3% kernel / faults: 1374 minor 1277 major
08-26 09:57:14.276   491   525 E ActivityManager:   7.2% 111/mmcqd/0: 0% user + 7.2% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   7.2% 1334/com.sohu.inputmethod.sogou.tv: 5% user + 2.2% kernel / faults: 2821 minor 553 major
08-26 09:57:14.276   491   525 E ActivityManager:   6.4% 16716/com.mgtv.tv.character: 3.8% user + 2.6% kernel / faults: 1471 minor 283 major
08-26 09:57:14.276   491   525 E ActivityManager:   4.4% 991/com.android.systemui: 3% user + 1.4% kernel / faults: 2725 minor 87 major
08-26 09:57:14.276   491   525 E ActivityManager:   4.1% 200/audioserver: 0.9% user + 3.1% kernel / faults: 34 minor 52 major
08-26 09:57:14.276   491   525 E ActivityManager:   4.1% 976/com.mgtv.surveyor: 3% user + 1.1% kernel / faults: 994 minor 70 major
08-26 09:57:14.276   491   525 E ActivityManager:   3.6% 75/kswapd0: 0% user + 3.6% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   2.5% 16861/com.pptv.tvsports.preinstall:ppdata: 1.7% user + 0.7% kernel / faults: 716 minor 50 major
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 965/com.mgtv.remote: 0.1% user + 0% kernel / faults: 1157 minor 234 major
08-26 09:57:14.276   491   525 E ActivityManager:   1.5% 1009/sdcard: 0.1% user + 1.4% kernel / faults: 12 minor 5 major
08-26 09:57:14.276   491   525 E ActivityManager:   1.1% 193/logd: 0.9% user + 0.1% kernel / faults: 14 minor 4 major
08-26 09:57:14.276   491   525 E ActivityManager:   1.1% 881/adbd: 0.3% user + 0.7% kernel / faults: 183 minor
08-26 09:57:14.276   491   525 E ActivityManager:   1.1% 16334/com.cibn.tv: 0.7% user + 0.3% kernel / faults: 141 minor 4 major
08-26 09:57:14.276   491   525 E ActivityManager:   1.1% 16820/com.pptv.tvsports.preinstall.a: 0.1% user + 0.9% kernel / faults: 544 minor 23 major
08-26 09:57:14.276   491   525 E ActivityManager:   0.9% 2287/logcat: 0.6% user + 0.3% kernel / faults: 18 minor
08-26 09:57:14.276   491   525 E ActivityManager:   0.9% 16332/logcat: 0.1% user + 0.7% kernel / faults: 12 minor
08-26 09:57:14.276   491   525 E ActivityManager:   0.7% 2288/com.android.commands.monkey: 0.6% user + 0.1% kernel / faults: 382 minor 1 major
08-26 09:57:14.276   491   525 E ActivityManager:   0.6% 56/rk-fb: 0% user + 0.6% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.6% 1405/com.mgtv.tv.userpaycenter: 0.3% user + 0.3% kernel / faults: 17 minor 1 major
08-26 09:57:14.276   491   525 E ActivityManager:   0% 182/debuggerd: 0% user + 0% kernel / faults: 254 minor 35 major
08-26 09:57:14.276   491   525 E ActivityManager:   0.3% 34/kconsole: 0% user + 0.3% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.3% 55/fb-vsync: 0% user + 0.3% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.3% 57/cfinteractive: 0% user + 0.3% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.3% 76/ksmd: 0% user + 0.3% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 3/ksoftirqd/0: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 8/rcu_preempt: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 14/ksoftirqd/1: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 19/ksoftirqd/2: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 24/ksoftirqd/3: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 41/kworker/u8:1: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 52/vmalloc: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 124/kworker/0:1H: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 158/servicemanager: 0.1% user + 0% kernel / faults: 2 minor
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 209/netd: 0% user + 0.1% kernel / faults: 13 minor
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 2957/kworker/u8:3: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   0.1% 13929/kworker/u9:2: 0% user + 0.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager: 69% TOTAL: 45% user + 19% kernel + 4.3% iowait + 0.4% softirq
08-26 09:57:14.276   491   525 E ActivityManager: CPU usage from 3741ms to 4296ms later (2019-08-26 09:57:11.661 to 2019-08-26 09:57:12.215):
08-26 09:57:14.276   491   525 E ActivityManager:   88% 1594/com.iflytek.xiri: 86% user + 1.7% kernel / faults: 55 minor
08-26 09:57:14.276   491   525 E ActivityManager:     41% 1662/om.iflytek.xiri: 39% user + 1.7% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     39% 1661/om.iflytek.xiri: 37% user + 1.7% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     3.5% 1696/cae_w_audio: 3.5% user + 0% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     1.7% 1755/read_audio: 1.7% user + 0% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   31% 17274/com.mgtv.setting: 23% user + 7.8% kernel / faults: 336 minor 1 major
08-26 09:57:14.276   491   525 E ActivityManager:     12% 17274/om.mgtv.setting: 9.4% user + 3.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     9.4% 17279/Jit thread pool: 6.2% user + 3.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     9.4% 17350/RenderThread: 6.2% user + 3.1% kernel
08-26 09:57:14.276   491   525 E ActivityManager:   23% 159/surfaceflinger: 5.3% user + 17% kernel / faults: 21 minor
08-26 09:57:14.276   491   525 E ActivityManager:     8.9% 159/surfaceflinger: 3.5% user + 5.3% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     3.5% 162/Binder:159_1: 0% user + 3.5% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     3.5% 174/EventThread: 0% user + 3.5% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     3.5% 305/Binder:159_3: 0% user + 3.5% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     3.5% 1072/Binder:159_5: 1.7% user + 1.7% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     1.7% 164/Binder:159_2: 0% user + 1.7% kernel
08-26 09:57:14.276   491   525 E ActivityManager:     1.7%

2.3.7 dex2oat优化导致ANR

理论依据:在应用首次启动的时候,可能会进行dex2oat的优化,其目的是预编译应用,从而加快应用在后续使用过程中的执行,提升用户体验;但是,应用在进行dex2oat的过程中,dex2oat进程本身会消耗系统许多资源,

此时应用的相关逻辑也还没准备好,得不到执行。

案例:M1上OTA升级后的首次启动,MyAPP应用容易出现ANR,从下面的日志信息中发现,主要的原因是MyAPP的dex2oat优化导致的;为了规避这类ANR,在M1上首次进行了一个尝试,具体如下两点,分别是

(1)OTA后的首次开机过程中,不允许MyAPP启动;

(2)修改包扫描时针对MyAPP的dex2oat的模式为speed,修改的代码为frameworks/base/services/core/java/com/android/server/pm/PackageDexOptimizer.java中的performDexOptLI方法;

这样修改后,在OTA升级后首次启动的场景中,MyAPP不会被拉活且在包扫描的时候就会对MyAPP进行dex2oat的优化,那么在下次重启机器的场景中,MyAPP被拉活后将不会再因为做dex2oat优化而导致ANR。

05-31 08:53:46.157   481   497 I libprocessgroup: Killing pid 1268 in uid 1000 as part of process group 1231
05-31 08:53:46.162   481   495 E ActivityManager: ANR in com.mgtv.myapp
05-31 08:53:46.162   481   495 E ActivityManager: PID: 1231
05-31 08:53:46.162   481   495 E ActivityManager: Reason: Broadcast of Intent { act=com.mgtv.mgui.action.BOOT_COMPLETED flg=0x10 cmp=com.mgtv.myapp/com.mgtv.apkmanager.receiver.GlobalReceiver }
05-31 08:53:46.162   481   495 E ActivityManager: Load: 0.0 / 0.0 / 0.0
05-31 08:53:46.162   481   495 E ActivityManager: CPU usage from 21514ms to 0ms ago (2019-05-31 08:53:23.585 to 2019-05-31 08:53:45.100):
05-31 08:53:46.162   481   495 E ActivityManager:   93% 1268/dex2oat: 92% user + 1% kernel / faults: 2888 minor
05-31 08:53:46.162   481   495 E ActivityManager:   13% 1074/com.mgtv.mgui: 10% user + 2.6% kernel / faults: 1107 minor
05-31 08:53:46.162   481   495 E ActivityManager:   11% 159/surfaceflinger: 4.5% user + 6.8% kernel / faults: 921 minor
05-31 08:53:46.162   481   495 E ActivityManager:   5.6% 481/system_server: 3.4% user + 2.2% kernel / faults: 2840 minor 4 major

---------------------------------------------------------------------------------------Line 877: 05-31 08:53:22.653  1268  1268 W dex2oat : Compilation of com.bumptech.glide.load.engine.Resource com.bumptech.glide.load.engine.DecodePath.decodeResourceWithList(com.bumptech.glide.load.data.DataRewinder, int, int, com.bumptech.glide.load.Options, java.util.List) took 124.267ms
 Line 879: 05-31 08:53:23.053  1268  1268 W dex2oat : Compilation of void com.bumptech.glide.load.model.ModelLoader$LoadData.<init>(com.bumptech.glide.load.Key, java.util.List, com.bumptech.glide.load.data.DataFetcher) took 101.744ms
 Line 879: 05-31 08:53:23.053  1268  1268 W dex2oat : Compilation of void com.bumptech.glide.load.model.ModelLoader$LoadData.<init>(com.bumptech.glide.load.Key, java.util.List, com.bumptech.glide.load.data.DataFetcher) took 101.744ms
 Line 882: 05-31 08:53:23.338  1268  1268 W dex2oat : Compilation of void com.bumptech.glide.load.resource.bitmap.Downsampler.calculateScaling(com.bumptech.glide.load.ImageHeaderParser$ImageType, java.io.InputStream, com.bumptech.glide.load.resource.bitmap.Downsampler$DecodeCallbacks, com.bumptech.glide.load.engine.bitmap_recycle.BitmapPool, com.bumptech.glide.load.resource.bitmap.DownsampleStrategy, int, int, int, int, int, android.graphics.BitmapFactory$Options) took 197.100ms
 Line 882: 05-31 08:53:23.338  1268  1268 W dex2oat : Compilation of void com.bumptech.glide.load.resource.bitmap.Downsampler.calculateScaling(com.bumptech.glide.load.ImageHeaderParser$ImageType, java.io.InputStream, com.bumptech.glide.load.resource.bitmap.Downsampler$DecodeCallbacks, com.bumptech.glide.load.engine.bitmap_recycle.BitmapPool, com.bumptech.glide.load.resource.bitmap.DownsampleStrategy, int, int, int, int, int, android.graphics.BitmapFactory$Options) took 197.100ms
 Line 896: 05-31 08:53:23.714  1268  1352 W dex2oat : Compilation of java.util.List com.bumptech.glide.module.ManifestParser.parse() took 108.138ms
 Line 1228: 05-31 08:53:24.648   481   495 E ActivityManager:  +0% 1268/dex2oat: 0% user + 0% kernel
 Line 1251: 05-31 08:53:25.091  1268  1353 W dex2oat : Compilation of void com.dangbeimarket.downloader.e.a() took 357.033ms
 Line 1252: 05-31 08:53:25.784  1268  1352 W dex2oat : Compilation of void com.google.zxing.oned.EANManufacturerOrgSupport.initIfNeeded() took 145.784ms
 Line 1253: 05-31 08:53:26.986  1268  1352 W dex2oat : Compilation of com.j256.ormlite.field.DatabaseFieldConfig com.j256.ormlite.misc.JavaxPersistence.createFieldConfig(com.j256.ormlite.db.DatabaseType, java.lang.reflect.Field) took 171.162ms
 Line 1254: 05-31 08:53:26.997  1268  1268 W dex2oat : Compilation of void com.j256.ormlite.field.FieldType.<init>(com.j256.ormlite.support.ConnectionSource, java.lang.String, java.lang.reflect.Field, com.j256.ormlite.field.DatabaseFieldConfig, java.lang.Class) took 292.634ms
 Line 1254: 05-31 08:53:26.997  1268  1268 W dex2oat : Compilation of void com.j256.ormlite.field.FieldType.<init>(com.j256.ormlite.support.ConnectionSource, java.lang.String, java.lang.reflect.Field, com.j256.ormlite.field.DatabaseFieldConfig, java.lang.Class) took 292.634ms
 Line 1255: 05-31 08:53:27.298  1268  1268 W dex2oat : Compilation of void com.j256.ormlite.field.FieldType.configDaoInformation(com.j256.ormlite.support.ConnectionSource, java.lang.Class) took 105.889ms
 Line 1255: 05-31 08:53:27.298  1268  1268 W dex2oat : Compilation of void com.j256.ormlite.field.FieldType.configDaoInformation(com.j256.ormlite.support.ConnectionSource, java.lang.Class) took 105.889ms
 Line 1256: 05-31 08:53:27.653  1268  1268 W dex2oat : Compilation of com.mgtv.apkmanager.ResultInfo com.mgtv.apkmanager.network.HttpUtil.doFileDownload(android.content.Context, java.lang.String, int, java.lang.String) took 114.486ms
 Line 1256: 05-31 08:53:27.653  1268  1268 W dex2oat : Compilation of com.mgtv.apkmanager.ResultInfo com.mgtv.apkmanager.network.HttpUtil.doFileDownload(android.content.Context, java.lang.String, int, java.lang.String) took 114.486ms
 Line 1257: 05-31 08:53:28.871  1268  1353 W dex2oat : Compilation of void com.mgtv.framework.db.sqlite.WhereBuilder.appendCondition(java.lang.String, java.lang.String, java.lang.String, java.lang.Object) took 136.705ms
 Line 1258: 05-31 08:53:29.101  1268  1268 W dex2oat : Compilation of java.lang.String com.mgtv.mgui.upgrade.UpdateService$DownloadApk.doInBackground(java.lang.String[]) took 131.515ms
 Line 1258: 05-31 08:53:29.101  1268  1268 W dex2oat : Compilation of java.lang.String com.mgtv.mgui.upgrade.UpdateService$DownloadApk.doInBackground(java.lang.String[]) took 131.515ms
 Line 1259: 05-31 08:53:29.241  1268  1353 W dex2oat : Compilation of int com.mgtv.mgui.upgrade.utils.PackageUtils.installSilent(android.content.Context, java.lang.String, java.lang.String) took 105.728ms
 Line 1260: 05-31 08:53:31.521  1268  1352 W dex2oat : Compilation of java.lang.String com.mgtv.tv.adapter.config.api.ServerSideConfigs.getSupport() took 101.324ms
 Line 1261: 05-31 08:53:31.600  1268  1353 W dex2oat : Compilation of java.util.List com.mgtv.myapp.utils.PermissionUtils.getPermissionList(android.content.pm.PackageManager, java.lang.String) took 778.659ms
 Line 1262: 05-31 08:53:32.284  1268  1352 W dex2oat : Compilation of java.lang.String com.mgtv.tv.base.core.MacUtil.getMacLevel9(java.lang.String) took 147.680ms
 Line 1263: 05-31 08:53:32.304  1268  1268 W dex2oat : Compilation of boolean com.mgtv.tv.base.core.NetWorkUtils.isServerAvailable(java.lang.String[], java.util.HashMap, java.lang.String) took 125.763ms
 Line 1263: 05-31 08:53:32.304  1268  1268 W dex2oat : Compilation of boolean com.mgtv.tv.base.core.NetWorkUtils.isServerAvailable(java.lang.String[], java.util.HashMap, java.lang.String) took 125.763ms
 Line 1264: 05-31 08:53:32.713  1268  1352 W dex2oat : Compilation of void com.mgtv.tv.base.core.log.LogManager.recordLog(java.lang.String) took 111.482ms
 Line 1265: 05-31 08:53:32.882  1268  1350 W dex2oat : Compilation of java.lang.String com.mgtv.tv.base.core.device.DeviceInfoFetcher.getDeviceId() took 180.961ms
 Line 1266: 05-31 08:53:33.798  1268  1352 W dex2oat : Compilation of void com.mgtv.tv.lib.network.ReportJsonHttpUtil.doPost(java.lang.String, java.lang.String) took 132.778ms
 Line 1267: 05-31 08:53:39.026  1268  1353 W dex2oat : Compilation of void android.support.v4.app.FragmentManagerImpl.moveToState(android.support.v4.app.Fragment, int, int, int, boolean) took 171.547ms
 Line 1274: 05-31 08:53:40.846  1268  1353 W dex2oat : Compilation of void android.support.v7.widget.SearchView.<init>(android.content.Context, android.util.AttributeSet, int) took 124.598ms
 Line 1302: 05-31 08:53:41.734  1268  1268 W dex2oat : Compilation of void com.alibaba.fastjson.JSONPath.paths(java.util.Map, java.lang.String, java.lang.Object, com.alibaba.fastjson.serializer.SerializeConfig) took 104.286ms
 Line 1302: 05-31 08:53:41.734  1268  1268 W dex2oat : Compilation of void com.alibaba.fastjson.JSONPath.paths(java.util.Map, java.lang.String, java.lang.Object, com.alibaba.fastjson.serializer.SerializeConfig) took 104.286ms
 Line 1303: 05-31 08:53:42.568  1268  1350 W dex2oat : Compilation of void com.alibaba.fastjson.parser.deserializer.ASMDeserializerFactory._deserialze(com.alibaba.fastjson.asm.ClassWriter, com.alibaba.fastjson.parser.deserializer.ASMDeserializerFactory$Context) took 666.676ms
 Line 1304: 05-31 08:53:42.752  1268  1268 W dex2oat : Compilation of java.lang.Object com.alibaba.fastjson.parser.deserializer.JavaBeanDeserializer.deserialze(com.alibaba.fastjson.parser.DefaultJSONParser, java.lang.reflect.Type, java.lang.Object, java.lang.Object, int, int[]) took 502.108ms
 Line 1304: 05-31 08:53:42.752  1268  1268 W dex2oat : Compilation of java.lang.Object com.alibaba.fastjson.parser.deserializer.JavaBeanDeserializer.deserialze(com.alibaba.fastjson.parser.DefaultJSONParser, java.lang.reflect.Type, java.lang.Object, java.lang.Object, int, int[]) took 502.108ms
 Line 1305: 05-31 08:53:42.893  1268  1353 W dex2oat : Compilation of void com.alibaba.fastjson.serializer.ASMSerializerFactory._list(java.lang.Class, com.alibaba.fastjson.asm.MethodVisitor, com.alibaba.fastjson.util.FieldInfo, com.alibaba.fastjson.serializer.ASMSerializerFactory$Context) took 118.515ms
 Line 1306: 05-31 08:53:43.178  1268  1350 W dex2oat : Compilation of void com.alibaba.fastjson.parser.deserializer.ASMDeserializerFactory._deserialzeArrayMapping(com.alibaba.fastjson.asm.ClassWriter, com.alibaba.fastjson.parser.deserializer.ASMDeserializerFactory$Context) took 608.864ms
 Line 1307: 05-31 08:53:43.336  1268  1350 W dex2oat : Compilation of void com.alibaba.fastjson.parser.deserializer.ASMDeserializerFactory._deserialze_list_obj(com.alibaba.fastjson.parser.deserializer.ASMDeserializerFactory$Context, com.alibaba.fastjson.asm.MethodVisitor, com.alibaba.fastjson.asm.Label, com.alibaba.fastjson.util.FieldInfo, java.lang.Class, java.lang.Class, int) took 157.908ms
 Line 1308: 05-31 08:53:43.410  1268  1353 W dex2oat : Compilation of void com.alibaba.fastjson.serializer.ASMSerializerFactory.generateWriteAsArray(java.lang.Class, com.alibaba.fastjson.asm.MethodVisitor, com.alibaba.fastjson.util.FieldInfo[], com.alibaba.fastjson.serializer.ASMSerializerFactory$Context) took 281.050ms
 Line 1309: 05-31 08:53:43.606  1268  1353 W dex2oat : Compilation of void com.alibaba.fastjson.serializer.ASMSerializerFactory.generateWriteMethod(java.lang.Class, com.alibaba.fastjson.asm.MethodVisitor, com.alibaba.fastjson.util.FieldInfo[], com.alibaba.fastjson.serializer.ASMSerializerFactory$Context) took 195.943ms
 Line 1310: 05-31 08:53:43.670  1268  1352 W dex2oat : Compilation of void com.alibaba.fastjson.serializer.JavaBeanSerializer.write(com.alibaba.fastjson.serializer.JSONSerializer, java.lang.Object, java.lang.Object, java.lang.reflect.Type, int, boolean) took 239.687ms
 Line 1311: 05-31 08:53:43.755  1268  1268 W dex2oat : Compilation of void com.alibaba.fastjson.serializer.MapSerializer.write(com.alibaba.fastjson.serializer.JSONSerializer, java.lang.Object, java.lang.Object, java.lang.reflect.Type, int, boolean) took 197.544ms
 Line 1311: 05-31 08:53:43.755  1268  1268 W dex2oat : Compilation of void com.alibaba.fastjson.serializer.MapSerializer.write(com.alibaba.fastjson.serializer.JSONSerializer, java.lang.Object, java.lang.Object, java.lang.reflect.Type, int, boolean) took 197.544ms
 Line 1312: 05-31 08:53:43.891  1268  1353 W dex2oat : Compilation of com.alibaba.fastjson.serializer.JavaBeanSerializer com.alibaba.fastjson.serializer.ASMSerializerFactory.createJavaBeanSerializer(com.alibaba.fastjson.serializer.SerializeBeanInfo) took 284.208ms
 Line 1355: 05-31 08:53:45.293  1268  1352 W dex2oat : Compilation of int com.bumptech.glide.load.resource.bitmap.DefaultImageHeaderParser.parseExifSegment(com.bumptech.glide.load.resource.bitmap.DefaultImageHeaderParser$RandomAccessReader) took 246.739ms
 Line 1398: 05-31 08:53:45.949  1268  1350 W dex2oat : Compilation of void com.bumptech.glide.request.SingleRequest.begin() took 100.641ms
 Line 1402: 05-31 08:53:46.027  1268  1268 W dex2oat : Compilation of void com.dangbeimarket.downloader.h$1.onResponse(okhttp3.Call, okhttp3.Response) took 127.925ms
 Line 1402: 05-31 08:53:46.027  1268  1268 W dex2oat : Compilation of void com.dangbeimarket.downloader.h$1.onResponse(okhttp3.Call, okhttp3.Response) took 127.925ms

2.4 从延长ANR阈值的角度去降低ANR率的思路尝试

从前面的分析中,我们可以看到,有许多的ANR是因为机器自身性能低使得应用的某些逻辑在某段时间内未能完成导致,例如广播接收者必须在60s内完成,但实际上该逻辑可能会在80s的时候才能完成。

那么,我们实际上完全可以适当的延长广播ANR timeout的阈值,目前来看,类似broadcast、service和content provider组件都属于后台逻辑,在一些ANR较高(确认是机器性能瓶颈导致的ANR)的机器上是可行的。

在M1上进行过实际的测试,效果还可以,具体还需要更多的测试case才能得出更加客观的结论。主要的调整如下:

(1)调整后台broadcast的timeout

修改frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java,调整 BROADCAST_BG_TIMEOUT = 100*1000

(2)调整service的timeout

修改frameworks/base/services/core/java/com/android/server/am/ActiveServices.java,调整 SERVICE_TIMEOUT = 100*1000 ,后台service也会相应的调整为了 SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;

(3)在M1上因为Content Provider导致的ANR很少(概率非常低),暂未调整其timeout值

(4)调整Activity或者按键的timeout

修改frameworks/base/services/core/java/com/android/server/am/ActivityManagerService.java,调整 KEY_DISPATCHING_TIMEOUT = 20*1000

同时还需要对应的调整 frameworks/native/services/inputflinger/InputDispatcher.cpp 设置 const nsecs_t STALE_EVENT_TIMEOUT = 22000 * 1000000LL; // 22sec

  • 0
    点赞
  • 0
    评论
  • 0
    收藏
  • 一键三连
    一键三连
  • 扫一扫,分享海报

©️2021 CSDN 皮肤主题: 大白 设计师:CSDN官方博客 返回首页
实付
使用余额支付
点击重新获取
扫码支付
钱包余额 0

抵扣说明:

1.余额是钱包充值的虚拟货币,按照1:1的比例进行支付金额的抵扣。
2.余额无法直接购买下载,可以购买VIP、C币套餐、付费专栏及课程。

余额充值