触发原理
1. 概述
ANR(Application Not responding),是指应用程序未响应,Android系统对于一些事件需要在一定的时间范围内完成,如果超过预定时间能未能得到有效响应或者响应时间过长,都会造成ANR。一般地,这时往往会弹出一个提示框,告知用户当前xxx未响应,用户可选择继续等待或者Force Close。
一般的,我们认为如下情况会导致ANR:
- Service Timeout: 前台服务在20s内未执行完成,后台服务200s内未执行完成
- BroadcastQueue Timeout:前台广播在10s内未执行完成,后台广播在60s内未执行完成
- ContentProvider Timeout:内容提供者,publish超过时10s
- InputDispatching Timeout: 输入事件分发超时5s,包括按键和触摸事件
注意,Activity本身不会发生ANR,只是由于Input事件通常会分发到Activity等UI界面中,而Input事件处理超时会导致ANR
我们可以把发生ANR比作是引爆炸弹,那么整个流程包含三部分组成:
- 埋定时炸弹:中控系统(system_server进程)启动倒计时,在规定时间内如果目标(应用进程)没有干完所有的活,则中控系统会定向炸毁(杀进程)目标。
- 拆炸弹:在规定的时间内干完工地的所有活,并及时向中控系统报告完成,请求解除定时炸弹,则幸免于难。
- 引爆炸弹:中控系统立即封装现场,抓取快照,搜集目标执行慢的罪证(traces),便于后续的案件侦破(调试分析),最后是炸毁目标。
本篇文章基于Android 6.0源码分析,新版Android会有一些改动,但整体逻辑区别不大
2. Service场景下的ANR机制
首先,我们来看一下这种场景下埋炸弹与拆炸弹在整个服务启动(startService)过程所处的环节,如图:
图解:
1.客户端(App进程)向中控系统(system_server进程)发起启动服务的请求, 其中在Service进程attach到system_server进程的过程中会调用realStartServiceLocked()方法来埋下炸弹。
private final void realStartServiceLocked(ServiceRecord r, ProcessRecord app, boolean execInFg) throws RemoteException {
...
//发送delay消息
bumpServiceExecutingLocked(r, execInFg, "create");
try {
...
//最终执行Service的onCreate()方法
app.thread.scheduleCreateService(r, r.serviceInfo,
mAm.compatibilityInfoForPackageLocked(r.serviceInfo.applicationInfo),
app.repProcState);
} catch (DeadObjectException e) {
mAm.appDiedLocked(app);
throw e;
} finally {
...
}
}
2.中控系统派出一名空闲的通信员(binder_1线程)接收该请求,紧接着向ActivityManager线程发送消息,埋下定时炸弹。这个过程是在启动服务的过程中完成的,最终由ActiveServices类的scheduleServiceTimeoutLocked发送延迟消息,即埋炸弹
private final void bumpServiceExecutingLocked(ServiceRecord r, boolean fg, String why) {
...
scheduleServiceTimeoutLocked(r.app);
}
void scheduleServiceTimeoutLocked(ProcessRecord proc) {
if (proc.executingServices.size() == 0 || proc.thread == null) {
return;
}
long now = SystemClock.uptimeMillis();
Message msg = mAm.mHandler.obtainMessage(
ActivityManagerService.SERVICE_TIMEOUT_MSG);
msg.obj = proc;
//当超时后仍没有remove该SERVICE_TIMEOUT_MSG消息,则执行service Timeout流程
mAm.mHandler.sendMessageAtTime(msg,
proc.execServicesFg ? (now+SERVICE_TIMEOUT) : (now+ SERVICE_BACKGROUND_TIMEOUT));
}
3.通讯员1号(binder_1)通知工地(service所在进程)的通信员准备开始干活,即开始执行service的启动生命周期,在启动生命周期执行完成之后,通讯员2号(binder_2)通知system_server进程,调用serviceDoneExecutingLocked拆除炸弹,即移除延迟消息
//AT.handleCreateService
private void handleCreateService(CreateServiceData data) {
...
java.lang.ClassLoader cl = packageInfo.getClassLoader();
Service service = (Service) cl.loadClass(data.info.name).newInstance();
...
try {
//创建ContextImpl对象
ContextImpl context = ContextImpl.createAppContext(this, packageInfo);
context.setOuterContext(service);
//创建Application对象
Application app = packageInfo.makeApplication(false, mInstrumentation);
service.attach(context, this, data.info.name, data.token, app,
ActivityManagerNative.getDefault());
//调用服务onCreate()方法
service.onCreate();
//拆除炸弹
ActivityManagerNative.getDefault().serviceDoneExecuting(
data.token, SERVICE_DONE_EXECUTING_ANON, 0, 0);
} catch (Exception e) {
...
}
}
private void serviceDoneExecutingLocked(ServiceRecord r, boolean inDestroying, boolean finishing) {
...
if (r.executeNesting <= 0) {
if (r.app != null) {
r.app.execServicesFg = false;
r.app.executingServices.remove(r);
if (r.app.executingServices.size() == 0) {
//当前服务所在进程中没有正在执行的service
mAm.mHandler.removeMessages(ActivityManagerService.SERVICE_TIMEOUT_MSG, r.app);
...
}
...
}
4.若超时未拆除炸弹,则会引爆炸弹炸毁service所在进程,即发生ANR。在system_server进程中有一个Handler线程, 名叫”ActivityManager”。当倒计时结束便会向该Handler线程发送 一条信息SERVICE_TIMEOUT_MSG
final class MainHandler extends Handler {
public void handleMessage(Message msg) {
switch (msg.what) {
case SERVICE_TIMEOUT_MSG: {
...
mServices.serviceTimeout((ProcessRecord)msg.obj);
} break;
...
}
...
}
}
void serviceTimeout(ProcessRecord proc) {
String anrMessage = null;
synchronized(mAm) {
......
}
if (anrMessage != null) {
//当存在timeout的service,则执行appNotResponding,收集ANR相关信息并输出为Log
mAm.appNotResponding(proc, null, null, false, anrMessage);
}
}
3. Broadcast场景下的ANR机制
Broadcast跟service超时机制大抵相同,对于静态注册的广播在超时检测过程需要检测SharedPreferences,如下图所示:
1.客户端(App进程)向中控系统(system_server进程)发起发送广播的请求
2.中控系统派出一名空闲的通信员(binder_1)接收该请求转交给组件管家(ActivityManager线程)
3.ActivityManager线程执行任务(processNextBroadcast方法)的过程埋下定时炸弹
final void processNextBroadcast(boolean fromMsg) {
synchronized(mService) {
...
r.receiverTime = SystemClock.uptimeMillis();
if (!mPendingBroadcastTimeoutMessage) {
long timeoutTime = r.receiverTime + mTimeoutPeriod;
//埋炸弹
setBroadcastTimeoutLocked(timeoutTime);
}
...
}
}
4.ActivityManager线程通知工地(receiver所在进程)的通信员准备开始干活
5.通讯员3号(binder_3)收到任务后转交给包工头(main主线程),加入包工头的任务队列(MessageQueue)
6.包工头经过一番努力干完活(完成receiver启动的生命周期),发现当前进程还有SharedPreferences正在执行写入文件的操作,便将向中控系统汇报的任务交给SP工人(queued-work-looper线程)
7.SharedPreferences工人历经艰辛终于完成SharedPreferences数据的持久化工作,便可以向中控系统汇报工作完成
8.中控系统的通讯员2号(binder_2)收到包工头的完工汇报后,立刻拆除炸弹。
final void processNextBroadcast(boolean fromMsg) {
...
if (r.receivers == null || r.nextReceiver >= numReceivers
|| r.resultAbort || forceReceive) {
if (r.resultTo != null) {
//处理广播消息消息
performReceiveLocked(r.callerApp, r.resultTo,
new Intent(r.intent), r.resultCode,
r.resultData, r.resultExtras, false, false, r.userId);
r.resultTo = null;
}
//拆炸弹
cancelBroadcastTimeoutLocked();
}
...
}
9.若Broadcast在规定的时间内没有完成任务,则引爆炸弹触发ANR。在BroadcastQueue中有一个Handler, 名叫”BroadcastHandler”。当倒计时结束便会向该Handler线程发送 一条信息BROADCAST_TIMEOUT_MSG
private final class BroadcastHandler extends Handler {
public void handleMessage(Message msg) {
switch (msg.what) {
case BROADCAST_TIMEOUT_MSG: {
synchronized (mService) {
broadcastTimeoutLocked(true);
}
} break;
...
}
...
}
}
final void broadcastTimeoutLocked(boolean fromMsg) {
.....
if (anrMessage != null) {
mHandler.post(new AppNotResponding(app, anrMessage));
}
}
对于动态广播,只是缺少了检查SharedPreferences的流程,如图:
可见,只有XML静态注册的广播超时检测过程会考虑是否有SharedPreferences尚未完成,动态广播并不受其影响。SharedPreferences的apply将修改的数据项更新到内存,然后再异步同步数据到磁盘文件,因此很多地方会推荐在主线程调用采用apply方式,避免阻塞主线程,但静态广播超时检测过程需要SharedPreferences全部持久化到磁盘,如果过度使用apply会增大应用ANR的概率。
4. ContentProvider场景下的ANR机制
ContentProvider的超时是在ContentProvider进程首次启动的时候才会检测,当ContentProvider进程已启动的场景,再次请求ContentProvider并不会触发超时。流程如下图所示:
1.App进程向system_server发起获取内容提供者的请求
2.system_server派出一名空闲的通信员(binder_1)接收该请求,检测到内容提供者尚未启动,则先通过zygote孵化新进程
3.新孵化的provider进程向system_server注册自己的存在
4.system_server的通信员2号接收到该信息后,向ActivityManager线程发送消息,调用attachApplicationLocked,埋下炸弹。
private final boolean attachApplicationLocked(IApplicationThread thread, int pid) {
ProcessRecord app;
if (pid != MY_PID && pid >= 0) {
synchronized (mPidsSelfLocked) {
app = mPidsSelfLocked.get(pid); // 根据pid获取ProcessRecord
}
}
...
//系统处于ready状态或者该app为FLAG_PERSISTENT进程则为true
boolean normalMode = mProcessesReady || isAllowedWhileBooting(app.info);
List<ProviderInfo> providers = normalMode ? generateApplicationProvidersLocked(app) : null;
//app进程存在正在启动中的provider,则超时10s后发送CONTENT_PROVIDER_PUBLISH_TIMEOUT_MSG消息
if (providers != null && checkAppInLaunchingProvidersLocked(app)) {
Message msg = mHandler.obtainMessage(CONTENT_PROVIDER_PUBLISH_TIMEOUT_MSG);
msg.obj = app;
mHandler.sendMessageDelayed(msg, CONTENT_PROVIDER_PUBLISH_TIMEOUT);
}
thread.bindApplication(...);
...
}
5.通信员2号通知工地(provider进程)的通信员准备开始干活
6.通讯员4号(binder_4)收到任务后转交给包工头(main主线程),加入包工头的任务队列(MessageQueue)
7.包工头经过一番努力干完活(完成provider的安装工作)后向中控系统汇报工作已完成
8.中控系统的通讯员3号(binder_3)收到包工头的完工汇报后(即内容提供者发布完成),立刻拆除炸弹。如果在倒计时结束前拆除炸弹则相安无事,否则会引发爆炸(触发ANR)
public final void publishContentProviders(IApplicationThread caller, List<ContentProviderHolder> providers) {
...
synchronized (this) {
final ProcessRecord r = getRecordForAppLocked(caller);
final int N = providers.size();
for (int i = 0; i < N; i++) {
ContentProviderHolder src = providers.get(i);
...
ContentProviderRecord dst = r.pubProviders.get(src.info.name);
if (dst != null) {
//成功pubish则移除该消息
if (wasInLaunchingProviders) {
mHandler.removeMessages(CONTENT_PROVIDER_PUBLISH_TIMEOUT_MSG, r);
}
...
}
}
}
}
5. Input场景下的ANR机制
input的超时检测机制跟service、broadcast、provider截然不同,为了更好的理解input过程先来介绍两个重要线程的相关工作:
① InputReader线程负责通过EventHub(监听目录/dev/input)读取输入事件,一旦监听到输入事件则放入到InputDispatcher的mInBoundQueue队列,并通知其处理该事件;
② InputDispatcher线程负责将接收到的输入事件分发给目标应用窗口,分发过程使用到3个事件队列:
- mInBoundQueue用于记录InputReader发送过来的输入事件;
- outBoundQueue用于记录即将分发给目标应用窗口的输入事件;
- waitQueue用于记录已分发给目标应用,且应用尚未处理完成的输入事件;
input的超时机制并非时间到了一定就会爆炸,而是处理后续上报事件的过程才会去检测是否该爆炸,所以更像是扫雷的过程,具体如下图所示:
- InputReader线程通过EventHub监听底层上报的输入事件,一旦收到输入事件则将其放至mInBoundQueue队列,并唤醒InputDispatcher线程
- InputDispatcher开始分发输入事件,设置埋雷的起点时间。先检测是否有正在处理的事件(mPendingEvent),如果没有则取出mInBoundQueue队头的事件,并将其赋值给mPendingEvent,且重置ANR的timeout;否则不会从mInBoundQueue中取出事件,也不会重置timeout。然后检查窗口是否就绪(checkWindowReadyForMoreInputLocked),满足以下任一情况,则会进入扫雷状态(检测前一个正在处理的事件是否超时),终止本轮事件分发,否则继续执行步骤3。
①对于按键类型的输入事件,则outboundQueue或者waitQueue不为空
②对于非按键的输入事件,则waitQueue不为空,且等待队头时间超时500ms - 当应用窗口准备就绪,则将mPendingEvent转移到outBoundQueue队列
- 当outBoundQueue不为空,且应用管道对端连接状态正常,则将数据从outboundQueue中取出事件,放入waitQueue队列
- InputDispatcher通过socket告知目标应用所在进程可以准备开始干活
- App在初始化时默认已创建跟中控系统双向通信的socketpair,此时App的包工头(main线程)收到输入事件后,会层层转发到目标窗口来处理
- 包工头完成工作后,会通过socket向中控系统汇报工作完成,则中控系统会将该事件从waitQueue队列中移除。
input超时机制为什么是扫雷,而非定时爆炸呢?是由于对于input来说即便某次事件执行时间超过timeout时长,只要用户后续在没有再生成输入事件,则不会触发ANR。 这里的扫雷是指当前输入系统中正在处理着某个耗时事件的前提下,后续的每一次input事件都会检测前一个正在处理的事件是否超时(进入扫雷状态),检测当前的时间距离上次输入事件分发时间点是否超过timeout时长。如果前一个输入事件的处理没有超时,则会重置ANR的timeout,从而不会爆炸。
traces.txt解读
1. 概述
无论是四大组件或者进程等只要发生ANR,最终都会调用AMS.appNotResponding()方法,所以我们直接从这个方法开始研究。
- 基于Android 6.0源码分析,新版Android会有一些改动,但整体逻辑区别不大
2. 信息收集流程
final void appNotResponding(ProcessRecord app, ActivityRecord activity, ActivityRecord parent, boolean aboveSystem, final String annotation) {
...
updateCpuStatsNow(); //第一次 更新cpu统计信息
synchronized (this) {
//PowerManager.reboot() 会阻塞很长时间,因此忽略关机时的ANR
if (mShuttingDown) {
return;
} else if (app.notResponding) {
return;
} else if (app.crashing) {
return;
}
//记录ANR到EventLog
EventLog.writeEvent(EventLogTags.AM_ANR, app.userId, app.pid,
app.processName, app.info.flags, annotation);
// 将当前进程添加到firstPids
firstPids.add(app.pid);
int parentPid = app.pid;
//将system_server进程添加到firstPids
if (MY_PID != app.pid && MY_PID != parentPid) firstPids.add(MY_PID);
for (int i = mLruProcesses.size() - 1; i >= 0; i--) {
ProcessRecord r = mLruProcesses.get(i);
if (r != null && r.thread != null) {
int pid = r.pid;
if (pid > 0 && pid != app.pid && pid != parentPid && pid != MY_PID) {
if (r.persistent) {
firstPids.add(pid); //将persistent进程添加到firstPids
} else {
lastPids.put(pid, Boolean.TRUE); //其他进程添加到lastPids
}
}
}
}
}
// 记录ANR输出到main log
StringBuilder info = new StringBuilder();
info.setLength(0);
info.append("ANR in ").append(app.processName);
if (activity != null && activity.shortComponentName != null) {
info.append(" (").append(activity.shortComponentName).append(")");
}
info.append("\n");
info.append("PID: ").append(app.pid).append("\n");
if (annotation != null) {
info.append("Reason: ").append(annotation).append("\n");
}
if (parent != null && parent != activity) {
info.append("Parent: ").append(parent.shortComponentName).append("\n");
}
//创建CPU tracker对象
final ProcessCpuTracker processCpuTracker = new ProcessCpuTracker(true);
//输出traces信息【见小节2】
File tracesFile = dumpStackTraces(true, firstPids, processCpuTracker,
lastPids, NATIVE_STACKS_OF_INTEREST);
updateCpuStatsNow(); //第二次更新cpu统计信息
//记录当前各个进程的CPU使用情况
synchronized (mProcessCpuTracker) {
cpuInfo = mProcessCpuTracker.printCurrentState(anrTime);
}
//记录当前CPU负载情况
info.append(processCpuTracker.printCurrentLoad());
info.append(cpuInfo);
//记录从anr时间开始的Cpu使用情况
info.append(processCpuTracker.printCurrentState(anrTime));
//输出当前ANR的reason,以及CPU使用率、负载信息
Slog.e(TAG, info.toString());
//将traces文件 和 CPU使用率信息保存到dropbox,即data/system/dropbox目录
addErrorToDropBox("anr", app, app.processName, activity, parent, annotation,
cpuInfo, tracesFile, null);
synchronized (this) {
...
//后台ANR的情况, 则直接杀掉
if (!showBackground && !app.isInterestingToUserLocked() && app.pid != MY_PID) {
app.kill("bg anr", true);
return;
}
//设置app的ANR状态,病查询错误报告receiver
makeAppNotRespondingLocked(app,
activity != null ? activity.shortComponentName : null,
annotation != null ? "ANR " + annotation : "ANR",
info.toString());
//重命名trace文件
String tracesPath = SystemProperties.get("dalvik.vm.stack-trace-file", null);
if (tracesPath != null && tracesPath.length() != 0) {
//traceRenameFile = "/data/anr/traces.txt"
File traceRenameFile = new File(tracesPath);
String newTracesPath;
int lpos = tracesPath.lastIndexOf (".");
if (-1 != lpos)
// 新的traces文件= /data/anr/traces_进程名_当前日期.txt
newTracesPath = tracesPath.substring (0, lpos) + "_" + app.processName + "_" + mTraceDateFormat.format(new Date()) + tracesPath.substring (lpos);
else
newTracesPath = tracesPath + "_" + app.processName;
traceRenameFile.renameTo(new File(newTracesPath));
}
//弹出ANR对话框
Message msg = Message.obtain();
HashMap<String, Object> map = new HashMap<String, Object>();
msg.what = SHOW_NOT_RESPONDING_MSG;
msg.obj = map;
msg.arg1 = aboveSystem ? 1 : 0;
map.put("app", app);
if (activity != null) {
map.put("activity", activity);
}
//向ui线程发送,内容为SHOW_NOT_RESPONDING_MSG的消息
mUiHandler.sendMessage(msg);
}
}
当发生ANR时, 会按顺序依次执行:
① 输出ANR Reason信息到EventLog. 也就是说ANR触发的时间点最接近的就是EventLog中输出的am_anr信息
② 收集并输出重要进程列表中的各个线程的traces信息,该方法较耗时
③ 输出当前各个进程的CPU使用情况以及CPU负载情况
④ 将traces文件和 CPU使用情况信息保存到dropbox,即data/system/dropbox目录
⑤ 根据进程类型,来决定直接后台杀掉,还是弹框告知用户
ANR输出重要进程的traces信息,这些进程包含:
- firstPids队列:第一个是ANR进程,第二个是system_server,剩余是所有persistent进程
- Native队列:是指/system/bin/目录的mediaserver,sdcard 以及surfaceflinger进程
- lastPids队列: 是指mLruProcesses中的不属于firstPids的所有进程
3. log与Traces.txt文件分析
ANR的日志分由2部分组成,普通log和trace.txt。前者主要包含各进程的CPU占用率、IO和ANR原因等信息,后者主要包含各进程的堆栈信息。
3.1. log
①
10-28 16:10:38.560 1346 1471 I am_anr : [0,4881,com.askey.dvr.dashcam,820559815,Input dispatching timed out (Waiting to send key event because the focused window has not finished processing all of the input events that were previously delivered to it. Outbound queue length: 0. Wait queue length: 1.)]
ANR时间:10-28 16:10:38.560
进程pid:4881
进程名:com.askey.dvr.dashcam
ANR类型:KeyDispatchTimeout
ANR原因:Input dispatching timed out
②
10-28 16:10:42.638 1346 1471 E ActivityManager: Load: 5.16 / 4.5 / 4.32
10-28 16:10:42.638 1346 1471 E ActivityManager: CPU usage from 225178ms to 0ms ago (2022-10-28 16:06:53.345 to 2022-10-28 16:10:38.524):
10-28 16:10:42.638 1346 1471 E ActivityManager: 20% 2353/com.jvckenwood.eventdetection: 17% user + 2.6% kernel / faults: 282419 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 18% 700/android.hardware.camera.provider@2.4-service: 11% user + 6.8% kernel / faults: 44508 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 8% 890/media.codec: 3.4% user + 4.6% kernel / faults: 1815 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 6.1% 1346/system_server: 3.2% user + 2.9% kernel / faults: 5732 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 5.1% 511/android.hardware.sensors@1.0-service: 1.9% user + 3.1% kernel / faults: 2675 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 3.2% 702/cameraserver: 1.8% user + 1.4% kernel / faults: 14385 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 2.7% 2245/adbd: 0.5% user + 2.2% kernel / faults: 689672 minor
10-28 16:10:42.638 1346 1471 E ActivityManager: 2.2% 244/kgsl_worker_thr: 0% user + 2.2% kernel
10-28 16:10:42.638 1346 1471 E ActivityManager: 1.6% 497/android.hardware.audio@2.0-service: 0% user + 1.6% kernel / faults: 60 minor
第一行:Load: 0.0 / 0.0 / 0.0 ,Load表示1、5、15 分钟内正在使用和等待使用CPU 的活动进程的平均数
第二行:表示抓取的负载在信息为ANR之前225178ms内的
第三行及以后:这里为各进程的CPU占用率,需要注意的是,对于单核CPU,使用率达到100%就代表CPU资源耗尽;而多核CPU的资源上限为 核心数*100% 。
3.2. Traces.txt
"main" prio=5 tid=1 Sleeping
| group="main" sCount=1 dsCount=0 flags=1 obj=0x73f9bd70 self=0x7da3214c00
| sysTid=4881 nice=-10 cgrp=default sched=0/0 handle=0x7e290e4550
| state=S schedstat=( 1776493054 389701312 2201 ) utm=152 stm=25 core=4 HZ=100
| stack=0x7fe06ed000-0x7fe06ef000 stackSize=8MB
| held mutexes=
第1行:
- 线程名: main(如有daemon则代表守护线程)
- prio: 线程优先级
- tid: 线程内部id
- 线程状态: Sleeping
第2行:
- group: 线程所属的线程组
- sCount: 线程挂起次数
- dsCount: 用于调试的线程挂起次数
- obj: 当前线程关联的java线程对象
- self: 当前线程地址
第3行:
- sysTid:线程真正意义上的tid
- nice: 调度有优先级
- cgrp: 进程所属的进程调度组
- sched: 调度策略
- handle: 函数处理地址
第4行:
- state: 线程状态
- schedstat: CPU调度时间统计
- utm/stm: 用户态/内核态的CPU时间(单位是jiffies)
- core: 该线程的最后运行所在核
- HZ: 时钟频率
第5行:
- stack:线程栈的地址区间
- stackSize:栈的大小
第6行:
- mutex: 所持有mutex类型,有独占锁exclusive和共享锁shared两类
schedstat含义说明:
schedstat括号中的3个数字依次是Running、Runable、Switch,紧接着的是utm和stm:
- Running时间:CPU运行的时间,单位ns
- Runable时间:RQ队列的等待时间,单位ns
- Switch次数:CPU调度切换次数
- utm: 该线程在用户态所执行的时间,单位是jiffies,jiffies定义为sysconf(_SC_CLK_TCK),默认等于10ms
- stm: 该线程在内核态所执行的时间,单位是jiffies,默认等于10ms
可见,该线程Running=1776493054ns,也约等于1776ms。在CPU运行时间包括用户态(utm)和内核态(stm),utm + stm = (152 + 25) ×10 ms = 1770ms,它们大致是相等的。
结论:utm + stm = schedstat第一个参数值。
ANR原因分析
1.1 在开始之前,我们先简略介绍一下ANR Dump Trace 的流程:
由于进程之间是相互隔离的,即使是系统进程也无法直接获取其它进程相关信息。因此需要借助 IPC 通信的方式,将指令发送到目标进程,目标进程接收到信号后,协助完成自身进程 Dump 信息并发送给系统进程。
而这个整体来看链路比较长,而且涉及到与很多进程交互,同时为了进一步降低对应用乃至系统的影响,系统在很多环节都设置大量超时检测。而且从上面流程可以看到发生 ANR 时,系统进程除了发送信号给其它进程之外,自身也 Dump Trace,并获取系统整体及各进程 CPU 使用情况,且将其它进程 Dump 发送的数据写到文件中。因此这些开销将会导致系统进程在 ANR 过程承担很大的负载,这是为什么我们经常在 ANR Trace 中看到 SystemServer 进程 CPU 占比普遍较高的主要原因。
1.2 ANR分析影响因素
举个例子:
在工作中,在分析ANR的时候经常会遇到“我的 Service”逻辑很简单,为何会 ANR 呢?分析Trace.txt文件会发现如下情况:
一脸蒙蔽,这份日志里面并没有任何可供分析信息,难道是系统本身ANR了吗?其实这和ANR的检测原理有很大关系,下面我们就来回答一下为何会出现上面的这类现象。
通过前面的讲解,我们可以发现,系统服务(AMS,InputService)在将具有超时属性的消息,如创建 Service,Receiver,Input 事件等,通过 Binder 或者其它 IPC 的方式发送到目标进程之后,便启动异步超时监测。而这种性质的监测完全是一种黑盒监测,并不是真的监控发送的消息在真实执行过程中是否超时,也就是说系统不管发送的这个消息有没有被执行,或者真实执行过程耗时有多久,只要在监控超时到来之前,服务端没有接收到通知,那么就判定为超时。
同时我们知道,当系统侧将消息发送给目标进程之后,其客户端进程的 Binder 线程接收到该消息后,会按时间顺序插入到消息队列;在后续等待执行过程中,会有下面几种情况发生:
- 进程启动场景,大量业务或基础库需要初始化,在消息入队之前,已经有很多消息待调度;
- 有些场景有可能只是少量消息,但是其中有一个或多个消息耗时很长;
- 有些场景其他进程或者系统负载特别高,整个系统都变得有些卡顿。
上述这些场景都会导致发送的消息还没来得及执行,就可能已经被系统判定成为超时问题,然而此时进程接收信号后,主线程 Dump 的是当前某个消息执行过程的业务堆栈(逻辑)。这样就会导致Trace.txt信息并不准确
所以总的来说,发生 ANR 问题时,Trace 堆栈很多情况下都不是 RootCase。而系统 ANR Info 中提示某个 Service 或 Receiver 导致的 ANR 在很大程度上,并不是这些组件自身问题。
2 ANR分析影响因素分类
结合前面的经验,我们将可能导致 ANR 的影响要素分为下面几个方面,影响环境分为 应用内部环境 和 系统环境;即 系统负载正常,但是应用内部主线程消息过多或耗时严重;另外一类则是 系统或应用内部其它线程或资源负载过高,主线程调度被严重抢占;系统负载正常,主线程调度问题,总体来说包括以下几种:
- 当前 Trace 堆栈所在业务耗时严重;
- 当前 Trace 堆栈所在业务耗时并不严重,但是历史调度有一个严重耗时;
- 当前 Trace 堆栈所在业务耗时并不严重,但是历史调度有多个消息耗时;
- 当前 Trace 堆栈所在业务耗时并不严重,但是历史调度存在巨量重复消息(业务频繁发送消息);
- 当前 Trace 堆栈业务逻辑并不耗时,但是其他线程存在严重资源抢占,如 IO,Mem,CPU;
- 当前 Trace 堆栈业务逻辑并不耗时,但是其他进程存在严重资源抢占,如 IO,Mem,CPU;
2.1 当前主线程正在调度的消息耗时严重
理论上某个消息耗时越严重,那么这个消息造成的卡顿或者 ANR 的概率就越大,这种场景经常发生,相对来说比较容易排查。
发生 ANR 时主线程消息调度示意图如下:
2.2 已调度的消息发生单点耗时严重
如果之前某个历史消息严重耗时,但是直到该消息执行完毕,系统服务仍然没有达到触发超时的临界点,后续主线程继续调度其它消息时,系统判定响应超时,那么正在执行的业务场景很不幸被命中,而当前正在执行的业务逻辑可能很简单。
这种场景比较隐蔽,所以会给我们带来很多困惑。发生 ANR 时主线程消息调度示意图如下:
2.3 连续多个消息耗时严重
除了上述两种场景,还有一种情况就是 存在多个消息耗时严重的情况,直到后面主线程调度其它消息时,系统判定响应超时,那么正在执行的业务场景很不幸被命中;这种场景在实际环境中也是普遍存在的,这类问题更加隐蔽,并且在分析和问题归因上,也很难清晰的划清界限,问题治理上需要推动多个业务场景进行优化。
发生 ANR 时主线程消息调度示意图如下:
2.4 相同消息高频执行(业务逻辑异常)
上面我们讲到的是有一个或多个消息耗时较长,还有另外一种情况就是 业务逻辑发生异常或者业务线程与主线程频繁交互,大量消息堆积在消息队列,这时对于后续追加到消息队列的消息来说,尽管不存在单个耗时严重的消息,但是消息太密集导致一段时间内同样很难被及时调度,因此这种场景也会造成消息调度不及时,进而导致响应超时问题。
发生 ANR 时主线程消息调度示意图如下:
2.5 应用进程或系统(包括其它进程)负载过重
除了上面列举了一些主线程消息耗时严重或者消息过多,导致的消息调度不及时的可能引起的问题之外,还有一种我们经常遇到的场景,那就是进程或系统本身负载很重,如高 CPU,高 IO,低内存(应用内内存抖动频繁 GC,系统内存回收)等等。这种情况出现之后,会导致应用或整体系统性能变差,最终导致一系列超时问题。
针对这种情况,具体到主线程消息调度上表现来看,就是很多消息耗时都比较严重,而且每次消息调度统计的 Wall Duration(绝对时间:包括正常调度和等待,休眠时间)和 CPU Duration(绝对时间:只包括 CPU 执行时间)相差很大,如果出现这种情况我们则认为系统负载可能发生了异常,需要借助系统信息进一步对比分析。这种情况不仅影响当前应用,也会影响其他应用乃至系统自身。
发生 ANR 时主线程消息调度示意图如下:
3. 分析思路
总结思路如下:
分析堆栈,看看是否存在明显业务问题(如死锁,业务严重耗时等等),如果无上述明显问题,则进一步通过 ANR Info 观察系统负载是否过高,进而导致整体性能较差,如 CPU,Mem,IO。然后再进一步分析是本进程还是其它进程导致,最后再分析进程内部分析对比各个线程 CPU 占比,找出可疑线程。具体如下:
3.1 一看 Trace
死锁堆栈
观察 Trace 堆栈,确认是否有明显问题,如主线程是否与其他线程发生死锁,如果是进程内部发生了死锁,那么这类问题就清晰多了,只需找到与当前线程死锁的线程,问题即可解决。
业务堆栈
观察通过 Trace 堆栈,发现当前主线程堆栈正在执行业务逻辑,且该业务逻辑确实存在性能问题,那么很有可能是主线程业务逻辑的问题,为什么只是可能呢?因为如果当前业务很简单,基本不怎么耗时,而这种场景也是日常经常遇到的一类问题,那么就可能需要借助我们之前介绍的思路,追溯历史消息耗时情况了。
IPC Block 堆栈
观察通过 Trace 堆栈,发现主线程堆栈是在跨进程(Binder)通信,那么这个情况并不能当即下定论就是 IPC block 导致,实际情况也有可能是刚发送 Binder 请求不久,以及想要进一步的分析定位,这时也需要追溯历史消息耗时情况。
系统堆栈
通过观察 Trace,发现当前堆栈只是简单的系统堆栈,想要搞清楚是否发生严重耗时,以及进一步的分析定位,如我们常见的 NativePollOnce 场景,这时也需要追溯历史消息耗时情况。
3.2 二看关键字:Load,CPU,Slow Operation,Kswapd,Mmcqd,Lowmemkiller 等等
Slow Operation: Checktime 是 Android 系统针对一些系统服务(AMS,InputService 等)中高频访问的接口,执行时间的监控,当这类接口真实耗时超过预期值将会给出提示信息,此类设计为了在真实环境监测进程被调度和响应能力的一种结果反馈。具体实现是,在每个函数执行前和执行后分析获取当前系统时间,并计算差值,如果该接口耗时超过其设定的阈值,则会触发“slow operation”的信息提醒,部分代码实现如下:
kswapd: 是 linux 中用于页面回收的内核线程,主要用来维护可用内存与文件缓存的平衡,以追求性能最大化,当该线程 CPU 占用过高,说明系统可用内存紧张,或者内存碎片化严重,需要进行 file cache 回写或者内存交换(交换到磁盘),线程 CPU 过高则系统整体性能将会明显下降,进而影响所有应用调度。
mmcqd: 内核线程,主要作用是把上层的 IO 请求进行统一管理和转发到 Driver 层,当该线程 CPU 占用过高,说明系统存在大量文件读写,当然如果内存紧张也会触发文件回写和内存交换到磁盘,所以 kswapd 和 mmcqd 经常是同步出现的。
Lowmemkiller:
从事性能(内存)优化的同学对该模块都比较熟悉,主要是用来监控和管理系统可用内存,当可用内存紧张时,从 kernel 层强制 Kill 一些低优先级的应用,以达到调节系统内存的目的。而选择哪些应用,则主要参考进程优先级(oom_score_adj),这个优先级是 AMS 服务根据应用当前的状态,如前台还是后台,以及进程存活的应用组件类型而计算出来的。例如:对于用户感知比较明显的前台应用,优先级肯定是最高的,此外还有一些系统服务,和后台服务(播放器场景)优先级也会比较高。当然厂商也对此进行了大量的定制(优化),以防止三方应用利用系统设计漏洞,将自身进程设置太高优先级进而达到保活目的。
上面这些关键字是反应系统 CPU,Mem,IO 负载的关键信息,在分析完主线程堆栈信息之后,还需要进一步在 ANRInfo,logcat 或 Kernel 日志中搜索这些关键字,并根据这些关键字当前数值,判断当前系统是否存在资源(CPU,Mem,IO)紧张的情况
3.3 三看系统负载分布:观察系统整体负载:User,Sys,IOWait
通过观察系统负载,则可以进一步明确是 CPU 资源紧张,还是 IO 资源紧张;如果系统负载过高,一定是有某个进程或多个进程引起的。反之系统负载过高又会影响到所有进程调度性能。通过观察 User,Sys 的 CPU 占比,可以进一步发分析当前负载过高是发生在应用空间,还是系统空间,如大量调用逻辑(如文件读写,内存紧张导致系统不断回收内存等等),知道这些之后,排查方向又会进一步缩小范围。
3.4 四看进程 CPU:观察 Top 进程的 CPU 占比
从上面分析,在我们知道当前系统负载过高,是发生在用户空间还是内核空间之后,那么我们就要通过 Anrinfo 的提供的进程 CPU 列表,进一步锁定是哪个(些)进程导致的,这时则要进一步的观察每个进程的 CPU 占比,以及进程内部 user,sys 占比。
在分析进程 CPU 占比过程,有一个关键的信息,要看统计这些进程 CPU 过高的场景是发生在 ANR 之前的一段时间还是之后一段时间,如下图表示 ANR 之前 4339ms 到 22895ms 时间内进程的 CPU 使用率。
3.5 五看 CPU 占比定线程 :对比各线程 CPU 占比,以及线程内部 user 和 kernel 占比
在通过系统负载(user,sys,iowait)锁定方向之后,又通过进程列表锁定目标进程,那么接下来我们就可以从目标进程内部分析各个线程的(utm,stm),进一步分析是哪个线程有问题了。
在 Trace 日志的线程信息里可以清晰的看到每个线程的 utm,stm 耗时。至此我们就完成了从系统到进程,再到进程内部线程方向的负载分析和排查。当然,有时候可能导致系统高负载的不是当前进程,而是其他进程导致,这时同样会影响其他进程,进而导致 ANR