写这篇文章的契机是因为一个实际遇到的问题 , 这个问题其实不难 , 不过在分析了这个问题然后写日记的时候 , 我突然觉得这个问题分析的过程有必要记录一下 , 分享给大家。分析过程中有用到一些工具 , 一些方法 , 也从另外一个聪明的小伙伴那里学到了一些分析技巧和工具的使用技巧
这篇文章中分析过程包括我之前在 Android 中的卡顿丢帧原因概述 - 方法论 里面提到的一些工具 , 包括 : 复现视频 \ Event Log \ Android Studio 源码和 App Debug \ Android Studio Profile \ Systrace \ Dumpsys \ PS 等 . 大多数工具大家都在开发过程中使用过 , 这次分析正是使用了这些工具相互配合 , 最终找到的问题的原因。
大家看下来可能会觉得 , 这么简单一个问题还需要写一篇文章 ? 我写这篇文章的目的一是为了记录给自己 , 二是觉得分析过程比较有普遍性 , 包括分析思路和工具的使用 , 如果可以帮助到大家 , 那么最好不过了 , 如果你也有好的思路或者独家调试技巧 , 欢迎大家扫描关于我 里面的讨论群二维码加入群聊 , 共同进步!
这个问题是测试直接报过来的 , Bug 描述是典型的按现象描述 : “ 从应用返回桌面 , 桌面图标加载慢 “. 测试这边提供了录制的视频和抓取的 Log , 以及对应的 Systrace 等. 既然现象和 Log 都在 , 那么就开始分析吧.
1.由于测试提供的复现视频 , 首先看复现视频 , 确定时间发生的时间
2.根据视频里面的大概时间(精确到分) , 查看对应的 EventLog ，跟视频比对，确定发生的确切时间点 (精确到秒)
3.查看 EventLog 和 MainLog ， 还原发生时候的用户操作 ，这个例子里面就发现启动和我信这个 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
// 重新创建桌面进程
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]
那么这里就可以简单还原问题了 , 测试报的是 从应用返回桌面 , 桌面图标加载慢 , 从 Event Log 来看 , 桌面显示慢 , 是因为 桌面被杀了, 所以从 App 返回的时候 , 桌面需要重新加载 , 从桌面进程创建到桌面完全显示 , 花费了 413ms(实际到桌面完全显示,花费了至少 2s 左右,因为 Launcher 冷启动还要重新加载内容).
从上面的分析来看 , 我们需要找到 Launcher 被杀的原因 , 从现象上来看 , 似乎是和 com.jx.cmcc.ict.ibelieve 这个进程有关系 , 但是我们目前是没有办法确认的 .
这里我们重点看这个这个 Event Log
am_kill : [0,13509,com.meizu.flyme.launcher,600,kill background]
这里可以看到 Launcher 被杀的原因是 kill background , 查看对应的源码可知，reason = kill background 是 AMS.killBackgroundProcesses 这里发出的.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 这个接口会提供给三方应用去调用 , 其 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();
}
}
知道了上面的代码逻辑 , 我们需要做的就是找到在这个场景下 , 是哪个应用调用 ActivityManager.killBackgroundProcesses 杀掉了桌面. 由于不知道具体是哪个应用(这里虽然我们怀疑是 com.jx.cmcc.ict.ibelieve , 但是没有证据) , 我们先对 SystemServer 进程进行 Debug .
1.首先对源码进行 debug , 首先在 Android 中点击 debug 按钮 , 选择 system_process 这个进程(就是我们所说的 SystemServer) , 然后点击 OK . 代码的断点我们打在上面列出的 ActivityManagerService.killBackgroundProcesses 方法里面。
2.点击启动怀疑的 App ( 可以从 EventLog 和视频里面倒推，找到比较可疑的 App , 安装后进行本地测试复现 , 这里选择了视频中出现的几个应用,包括我们之前怀疑的 com.jx.cmcc.ict.ibelieve- 和我信 ) , 点击其他的应用都不会进入到这个断点, 而在点击 和我信 这个 App 启动后走到的断点。
3.这里我们可以看到调用栈是一个 Binder 调用 , 我们需要找到这个 Binder 调用的客户端. 在 AS 里面继续操作 , 点击如下图的计算器按钮 , 输入 getRealCallingPid() 点击下面的 Evaluate , 就可以看到结果. result = 29771
4.通过 PS 命令 , 查看这个 pid 对应的 app。
可以看到就是这个应用调用的 killBackgroundProcesses。
为了进一步调查，我们对这个 app 进行 debug ， 由于没有源码，我们直接把断点打到 android/app/ActivityManager.killBackgroundProcesses 这里(因为这里是客户端代码 , 所以调试 App 进程的时候 , 可以直接打断点 )。
本地安装这个应用进行调试， 发现登录后，再次启动， 桌面必会被杀 ，确定就是这个 App 的问题
到了这一步我们已经基本上确定问题就是这个 App 引起的了 , 不过如果我们想看比较详细的调用情况 , 可以使用 Android Studio Profile。
打开 Android Studio , 点击 Profiler 按钮 , 点击 + 号 , 选择 com.jx.cmcc.ict.ibelieve 这个进程 , 然后点击 CPU 这一栏。
这里选择了 Trace Java Methods , 然后点击旁边的 Record , 就可以开始进行操作 , 操作结束后 , 点击 Stop , AS 会自动开始解析。
解析结果我们可以看这里：
最下面就是刚刚操作所对应的详细函数调用栈 , 以真正运行的顺序展示在我们面前(我经常会用这个工具来查看源码逻辑和三方应用的代码逻辑 , 不管是学习还是解决问题 , 都是一个非常好的方法)。
我们使用 ctrl+f 进行搜索 killBackgroundProcesses , 如果有的话 , 会以高亮显示, 我们只需要用鼠标放大就可以看到详细的调用栈。
可以看到这个 App 在 loadComplete 回调里面执行了 killBackground 方法.(到了这里，应用开发者就已经知道是哪里的问题了，修复起来飞快)。
如上面所示 , 调用 killBackgroundProcesses 是需要Manifest.permission.KILL_BACKGROUND_PROCESSES 这个权限的。
@RequiresPermission(Manifest.permission.KILL_BACKGROUND_PROCESSES)
public void killBackgroundProcesses(String packageName) {
}
执行 adb shell dumpsys package com.jx.cmcc.ict.ibelieve 查看 com.jx.cmcc.ict.ibelieve 这个进程所申请的权限 , 发现这个应用在安装的时候就申请了KILL_BACKGROUND_PROCESSES 这个权限 , 且默认是授予的。
install permissions:
......
android.permission.ACCESS_NETWORK_STATE: granted=true
android.permission.KILL_BACKGROUND_PROCESSES: granted=true
android.permission.WRITE_USER_DICTIONARY: granted=true
......
对应的权限级别为 normal。
也就是说 , 所有的第三方应用都可以默认有这个权限 , 只要你申请 . 这个案例里面 , 就是因为这个 App 申请了这个权限 , 且执行了错误的行为 , 导致把桌面杀掉 , 严重影响用户体验. Sad !
由于经常使用 Systrace , 那么 Systrace 是否可以找到元凶呢? 答案是可以 (这里如果对如何在 Systrace 上查看唤醒信息不了解 , 可以看一下这篇文章 分析 Systrace 预备知识 ). 我们录制一段 Systrace , 安装下面的顺序去看
1.首先看 system_server 进程对应的 trace ,找到 killProcessGroup 对应的点 , 查看其唤醒情况 , 可以看到是 19688 这个线程唤醒执行 AMS 的 killProcessGroup。
在 Systrace 中搜索 19688 , 可以看到是 Binder:1295_1E , 1295 就是 SystemServer。
查看对应的 Binder:1295_1E , 看看是哪个线程唤醒这个线程。
搜索 7289这个线程 ， 可以看到这个线程就是和我信这个 App 的主线程。
查看 7289 , 确定就是 com.jx.cmcc.ict.ibelieve 这个进程 . 也就是 和我信 这个 App(瘤子)。
这里也可以反推出来这个 Kill 是 和我信 这个 App 发起的 ， 进一步确认可以使用上面 AS 的 MethodTrace。
从上面的分析来看 , 这个问题是由于应用申请了不恰当的权限并错误使用对应的函数导致的一个严重影响用户使用的问题. 一般分析到这一步 , 我们的工作就基本上结束了 , 后续只需要和商店沟通 , 跟 App 开发者联系进行修改即可。
不过令我感到意外的是 android.permission.KILL_BACKGROUND_PROCESSES 这个权限 Google 居然放的这么松 , 我一直以为这个权限是要专门申请以防止 App 滥用或者卵用的(毕竟涉及到其他 App 的生死存亡).
更多信息可以点击关于我 , 非常希望和大家一起交流 , 共同进步