Android机顶盒M1上ANR问题的排查方法和应对方案
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 Provider | CONTENT_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 errorReportReceivermakeAppNotRespondingLocked(app,activity != null ? activity.shortComponentName : null,annotation != null ? "ANR " + annotation : "ANR",info.toString());// Bring up the infamous App Not Responding dialogMessage 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問題的處理成效
| OTA1 | 9.297% | M1剛出來的版本,許多自研應用都有ANR現象 |
| OTA3 | 4.8293% | 優化防自啟和應用進程清理邏輯 |
| OTA4 | 2.2437% | 優化自研應用占用的內存 |
| OTA5 | 2.189% | 優化語音和若干第三方預置應用 |
| OTA6 | 1.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
總結
以上是生活随笔為你收集整理的Android机顶盒M1上ANR问题的排查方法和应对方案的全部內容,希望文章能夠幫你解決所遇到的問題。
- 上一篇: 每个创业者都是一本小说
- 下一篇: linux企鹅吉祥物的名字,让我来告诉你