Android 框架問題分析案例 - 誰殺了桌面?
寫這篇文章的契機是因為一個實際遇到的問題 , 這個問題其實不難 , 不過在分析了這個問題然后寫日記的時候 , 我突然覺得這個問題分析的過程有必要記錄一下 , 分享給大家。分析過程中有用到一些工具 , 一些方法 , 也從另外一個聰明的小伙伴梅明那里學到了一些分析技巧和工具的使用技巧 。
這篇文章中分析過程包括我之前在 Android 中的卡頓丟幀原因概述 - 方法論 里面提到的一些工具 , 包括 : 復(fù)現(xiàn)視頻 \ Event Log \ Android Studio 源碼和 App Debug \ Android Studio Profile \ Systrace \ Dumpsys \ PS 等 . 大多數(shù)工具大家都在開發(fā)過程中使用過 , 這次分析正是使用了這些工具相互配合 , 最終找到的問題的原因。
大家看下來可能會覺得 , 這么簡單一個問題還需要寫一篇文章 ? 我寫這篇文章的目的一是為了記錄給自己 , 二是覺得分析過程比較有普遍性 , 包括分析思路和工具的使用 , 如果可以幫助到大家 , 那么最好不過了 , 如果你也有好的思路或者獨家調(diào)試技巧 , 歡迎大家掃描關(guān)于我 里面的討論群二維碼加入群聊 , 共同進步!
現(xiàn)象
這個問題是測試直接報過來的 , Bug 描述是典型的按現(xiàn)象描述 : “ 從應(yīng)用返回桌面 , 桌面圖標加載慢 “. 測試這邊提供了錄制的視頻和抓取的 Log , 以及對應(yīng)的 Systrace 等. 既然現(xiàn)象和 Log 都在 , 那么就開始分析吧.
分析過程
確定問題發(fā)生的時間點
- 由于測試提供的復(fù)現(xiàn)視頻 , 首先看復(fù)現(xiàn)視頻 , 確定時間發(fā)生的時間
- 根據(jù)視頻里面的大概時間(精確到分) , 查看對應(yīng)的 EventLog ,跟視頻比對,確定發(fā)生的確切時間點 (精確到秒)
- 查看 EventLog 和 MainLog , 還原發(fā)生時候的用戶操作 ,這個例子里面就發(fā)現(xiàn)啟動和我信這個 App 之后,Launcher 被殺了
- EventLog
- // 啟動 com.jx.cmcc.ict.ibelieve 這個 App
- 09-10 10:14:48.877 1456 2269 I am_set_resumed_activity: [0,com.jx.cmcc.ict.ibelieve/.ui.MainTabActivity,resumeTopActivityInnerLocked]
- 09-10 10:14:48.886 1456 2269 I am_resume_activity: [0,80317506,54938,com.jx.cmcc.ict.ibelieve/.ui.MainTabActivity]
- 09-10 10:14:48.891 1456 1485 I sysui_count: [window_time_0,0]
- 09-10 10:14:48.891 1456 1485 I sysui_multi_action: [757,803,799,window_time_0,802,0]
- 09-10 10:14:48.902 1456 2269 I am_uid_stopped: 10021
- // 這里桌面被殺
- 09-10 10:14:48.903 1456 2269 I am_kill : [0,13509,com.meizu.flyme.launcher,600,kill background]
- // 這里開始從 App 返回桌面
- 09-10 10:14:51.990 1456 1791 I am_pause_activity: [0,80317506,com.jx.cmcc.ict.ibelieve/.ui.MainTabActivity]
- 09-10 10:14:51.994 1456 1791 I am_task_to_front: [0,54923]
- 09-10 10:14:51.996 13674 13674 I am_on_paused_called: [0,com.jx.cmcc.ict.ibelieve.ui.MainTabActivity,handlePauseActivity]
- 09-10 10:14:52.013 1456 2270 I am_uid_running: 10021
- // 重新創(chuàng)建桌面進程
- 09-10 10:14:52.025 1456 2270 I am_proc_start: [0,14013,10021,com.meizu.flyme.launcher,activity,com.meizu.flyme.launcher/.Launcher]
- 09-10 10:14:52.045 1456 2270 I am_proc_bound: [0,14013,com.meizu.flyme.launcher]
- 09-10 10:14:52.069 1456 2270 I am_uid_active: 10021
- 09-10 10:14:52.069 1456 2270 I am_restart_activity: [0,238217861,54923,com.meizu.flyme.launcher/.Launcher]
- // 桌面顯示
- 09-10 10:14:52.071 1456 2270 I am_set_resumed_activity: [0,com.meizu.flyme.launcher/.Launcher,minimalResumeActivityLocked]
- 09-10 10:14:52.335 14013 14013 I am_on_resume_called: [0,com.meizu.flyme.launcher.Launcher,LAUNCH_ACTIVITY]
- 09-10 10:14:52.437 1456 1504 I am_activity_launch_time: [0,238217861,com.meizu.flyme.launcher/.Launcher,413,413]
那么這里就可以簡單還原問題了 , 測試報的是 從應(yīng)用返回桌面 , 桌面圖標加載慢 , 從 Event Log 來看 , 桌面顯示慢 , 是因為 桌面被殺了 , 所以從 App 返回的時候 , 桌面需要重新加載 , 從桌面進程創(chuàng)建到桌面完全顯示 , 花費了 413ms(實際到桌面完全顯示,花費了至少 2s 左右,因為 Launcher 冷啟動還要重新加載內(nèi)容).
分析被殺原因
從上面的分析來看 , 我們需要找到 Launcher 被殺的原因 , 從現(xiàn)象上來看 , 似乎是和 com.jx.cmcc.ict.ibelieve 這個進程有關(guān)系 , 但是我們目前是沒有辦法確認的 .
這里我們重點看這個這個 Event Log
- am_kill : [0,13509,com.meizu.flyme.launcher,600,kill background]
這里可以看到 Launcher 被殺的原因是 kill background , 查看對應(yīng)的源碼可知,reason = kill background 是 AMS.killBackgroundProcesses 這里發(fā)出的.
ActivityManagerService.killBackgroundProcesses
- public void killBackgroundProcesses(final String packageName, int userId) {
- ......
- synchronized (this) {
- killPackageProcessesLocked(packageName, appId, targetUserId,
- ProcessList.SERVICE_ADJ, false, true, true, false, "kill background");
- }
- }
對源碼比較熟悉的同學可以很快知道 , AMS.killBackgroundProcesses 這個接口會提供給三方應(yīng)用去調(diào)用 , 其 Binder 的客戶端在 ActivityManager.killBackgroundProcesses 這里
ActivityManager.killBackgroundProcesses
- /**
- * Have the system immediately kill all background processes associated
- * with the given package. This is the same as the kernel killing those
- * processes to reclaim memory; the system will take care of restarting
- * these processes in the future as needed.
- *
- * @param packageName The name of the package whose processes are to
- * be killed.
- */
- @RequiresPermission(Manifest.permission.KILL_BACKGROUND_PROCESSES)
- public void killBackgroundProcesses(String packageName) {
- try {
- getService().killBackgroundProcesses(packageName,
- mContext.getUserId());
- } catch (RemoteException e) {
- throw e.rethrowFromSystemServer();
- }
- }
對 SystemServer 進程進行斷點 Debug
知道了上面的代碼邏輯 , 我們需要做的就是找到在這個場景下 , 是哪個應(yīng)用調(diào)用 ActivityManager.killBackgroundProcesses 殺掉了桌面. 由于不知道具體是哪個應(yīng)用(這里雖然我們懷疑是 com.jx.cmcc.ict.ibelieve , 但是沒有證據(jù)) , 我們先對 SystemServer 進程進行 Debug .
1.首先對源碼進行 debug , 首先在 Android 中點擊 debug 按鈕 , 選擇 system_process 這個進程(就是我們所說的 SystemServer) , 然后點擊 OK . 代碼的斷點我們打在上面列出的 ActivityManagerService.killBackgroundProcesses 方法里面。
2.點擊啟動懷疑的 App ( 可以從 EventLog 和視頻里面倒推,找到比較可疑的 App , 安裝后進行本地測試復(fù)現(xiàn) , 這里選擇了視頻中出現(xiàn)的幾個應(yīng)用,包括我們之前懷疑的 com.jx.cmcc.ict.ibelieve- 和我信 ) , 點擊其他的應(yīng)用都不會進入到這個斷點, 而在點擊 和我信 這個 App 啟動后走到的斷點。
3.這里我們可以看到調(diào)用棧是一個 Binder 調(diào)用 , 我們需要找到這個 Binder 調(diào)用的客戶端. 在 AS 里面繼續(xù)操作 , 點擊如下圖的計算器按鈕 , 輸入 getRealCallingPid() 點擊下面的 Evaluate , 就可以看到結(jié)果. result = 29771
可以看到就是這個應(yīng)用調(diào)用的 killBackgroundProcesses。
對 App 進程進行斷點 Debug
為了進一步調(diào)查,我們對這個 app 進行 debug , 由于沒有源碼,我們直接把斷點打到 android/app/ActivityManager.killBackgroundProcesses 這里(因為這里是客戶端代碼 , 所以調(diào)試 App 進程的時候 , 可以直接打斷點 )。
到了這一步我們已經(jīng)基本上確定問題就是這個 App 引起的了 , 不過如果我們想看比較詳細的調(diào)用情況 , 可以使用 Android Studio Profile。
使用 Android Studio Profiler 工具
最下面就是剛剛操作所對應(yīng)的詳細函數(shù)調(diào)用棧 , 以真正運行的順序展示在我們面前(我經(jīng)常會用這個工具來查看源碼邏輯和三方應(yīng)用的代碼邏輯 , 不管是學習還是解決問題 , 都是一個非常好的方法)。
可以看到這個 App 在 loadComplete 回調(diào)里面執(zhí)行了 killBackground 方法.(到了這里,應(yīng)用開發(fā)者就已經(jīng)知道是哪里的問題了,修復(fù)起來飛快)。
權(quán)限問題分析
如上面所示 , 調(diào)用 killBackgroundProcesses 是需要Manifest.permission.KILL_BACKGROUND_PROCESSES 這個權(quán)限的。
- @RequiresPermission(Manifest.permission.KILL_BACKGROUND_PROCESSES)
- public void killBackgroundProcesses(String packageName) {
- }
執(zhí)行 adb shell dumpsys package com.jx.cmcc.ict.ibelieve 查看 com.jx.cmcc.ict.ibelieve 這個進程所申請的權(quán)限 , 發(fā)現(xiàn)這個應(yīng)用在安裝的時候就申請了KILL_BACKGROUND_PROCESSES 這個權(quán)限 , 且默認是授予的。
- install permissions:
- ......
- android.permission.ACCESS_NETWORK_STATE: granted=true
- android.permission.KILL_BACKGROUND_PROCESSES: granted=true
- android.permission.WRITE_USER_DICTIONARY: granted=true
- ......
對應(yīng)的權(quán)限級別為 normal。
也就是說 , 所有的第三方應(yīng)用都可以默認有這個權(quán)限 , 只要你申請 . 這個案例里面 , 就是因為這個 App 申請了這個權(quán)限 , 且執(zhí)行了錯誤的行為 , 導(dǎo)致把桌面殺掉 , 嚴重影響用戶體驗. Sad !
Systrace 工具可以找出來 Kill 桌面的元兇么?
由于經(jīng)常使用 Systrace , 那么 Systrace 是否可以找到元兇呢? 答案是可以 (這里如果對如何在 Systrace 上查看喚醒信息不了解 , 可以看一下這篇文章 分析 Systrace 預(yù)備知識 ). 我們錄制一段 Systrace , 安裝下面的順序去看
1.首先看 system_server 進程對應(yīng)的 trace ,找到 killProcessGroup 對應(yīng)的點 , 查看其喚醒情況 , 可以看到是 19688 這個線程喚醒執(zhí)行 AMS 的 killProcessGroup。
這里也可以反推出來這個 Kill 是 和我信 這個 App 發(fā)起的 , 進一步確認可以使用上面 AS 的 MethodTrace。
總結(jié)
從上面的分析來看 , 這個問題是由于應(yīng)用申請了不恰當?shù)臋?quán)限并錯誤使用對應(yīng)的函數(shù)導(dǎo)致的一個嚴重影響用戶使用的問題. 一般分析到這一步 , 我們的工作就基本上結(jié)束了 , 后續(xù)只需要和商店溝通 , 跟 App 開發(fā)者聯(lián)系進行修改即可。
不過令我感到意外的是 android.permission.KILL_BACKGROUND_PROCESSES 這個權(quán)限 Google 居然放的這么松 , 我一直以為這個權(quán)限是要專門申請以防止 App 濫用或者卵用的(畢竟涉及到其他 App 的生死存亡).
5. 關(guān)于我
小廠系統(tǒng)研發(fā)工程師 , 更多信息可以點擊關(guān)于我 , 非常希望和大家一起交流 , 共同進步。