原文链接:Android 耗时代码(ANR)的查找检测和分析解决 TraceView的使用手册 - CSDN博客
关于ANR:Application Not Response,意思是应用未能及时响应。
ANR有三种发生情况:
前两者定义在ActivityManagerService.java里面,
屏幕或按键点击后5秒内无响应,
// How long we wait until we timeout on key dispatching.
static final int KEY_DISPATCHING_TIMEOUT = 5*1000;
前台广播10秒内没处理完,后台广播可以60秒没处理完,
// How long we allow a receiver to run before giving up on it.
static final int BROADCAST_FG_TIMEOUT = 10*1000;
static final int BROADCAST_BG_TIMEOUT = 60*1000;
Service的超时定义在ActiveServices.java里,意思是处于前台进程里的服务20秒没处理完超时,处于后台进程里的服务200秒没响应。
// How long we wait for a service to finish executing.
static final int SERVICE_TIMEOUT = 20*1000;
// How long we wait for a service to finish executing.
static final int SERVICE_BACKGROUND_TIMEOUT = SERVICE_TIMEOUT * 10;
对于这个有些解释把前者译为前台服务。我觉得是有歧义的,因为前台服务一般说的是有在通知栏有一个常驻通知的服务。
实测过,写一个普通Service,SystemClock.sleep(20000)会报ANR,SystemClock.sleep(19500)不会报ANR。
出现ANR后,执行adb命令下载日志到某个目录,adb pull /data/anr/traces.txt D:\ss,然后就可以查看ANR出现的地方。
打开这个traces.txt文件,开头会有大概20行的当前应用运行信息。然后是就是ANR出现的代码定位了,
DALVIK THREADS (21):
"main" prio=5 tid=1 Sleeping
| group="main" sCount=1 dsCount=0 obj=0x76af9fb0 self=0x7f9b49a000
| sysTid=4423 nice=0 cgrp=default sched=0/0 handle=0x7f9f6e7e30
| state=S schedstat=( 1089793398 859095826 3028 ) utm=90 stm=18 core=7 HZ=100
| stack=0x7fbff76000-0x7fbff78000 stackSize=8MB
| held mutexes=
at java.lang.Thread.sleep!(Native method)
- sleeping on <0x12b5bd91> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:1031)
- locked <0x12b5bd91> (a java.lang.Object)
at java.lang.Thread.sleep(Thread.java:985)
at android.os.SystemClock.sleep(SystemClock.java:120)
at com.yao.mytestproject.service.NormalService.onStartCommand(NormalService.java:27)
at android.app.ActivityThread.handleServiceArgs(ActivityThread.java:3293)
at android.app.ActivityThread.access$2200(ActivityThread.java:187)
at android.app.ActivityThread$H.handleMessage(ActivityThread.java:1688)
at android.os.Handler.dispatchMessage(Handler.java:111)
at android.os.Looper.loop(Looper.java:194)
at android.app.ActivityThread.main(ActivityThread.java:5871)
at java.lang.reflect.Method.invoke!(Native method)
at java.lang.reflect.Method.invoke(Method.java:372)
at com.android.internal.os.ZygoteInit$MethodAndArgsCaller.run(ZygoteInit.java:1119)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:885)
比如这个例子,是因为在NormalService里面SystemClock.slee方法导致的ANR。
Android不止有ANR,还有阻塞操作和耗时代码。
说是屏幕或按键点击后5秒内无响应,但是1,2秒没反应已经让用户挺崩溃了。所以找出应用的耗时代码是一件十分重要的事。
生成TraceView日志的两种方式
第一种是通过代码生成,
开始的地方写代码 Debug.startMethodTracing();
结束的地方写代码 Debug.stopMethodTracing();
注意需要写入sdcard权限。
日志会保存到/sdcard/dmtrace.trace,然后adb pull /sdcard/dmtrace.trace D:\dir拉下来。用Android Device Monitor打开就行。
第二种是通过操作Android Device Monitor的按钮生成,
打开Android Device Monitor,选中想观察的进程。点击Start Method Profiling,一通操作后,再点击Stop method Profiling。就是弹出这段时间操作的trace文件。
强烈建议用这种方式,因为第一种方式有bug。文章后面会介绍。
.trace文件显示是这样的。分为两部分。
.trace文件使用Monitor打开上半部分是一个图,一行表示一个线程,列表示时间。
鼠标放在图中间的区域,左上角会出现几个信息,分别是毫秒数(millisecond的缩写),当前时刻正在执行的方法以及它的方法编号,以及一些执行时间信息。此时点击可以在使下面表格跳到对应的方法里。
时间轴拖拽可以放大选中的区域,双击上面的信息栏可以返回原始大小。
拖动操作图下半部分是一个详细的表格,一行代表一种方法,各个列代表某个执行时间或对应的百分比。具体来说每一项对应的意思,
Incl Cpu Time:某方法占用CPU的时间
Excl Cpu Time:某方法本身(不包含子方法)占用CPU的时间
Incl Real Time:某方法执行所占用执行的时间
Excl Real Time:某方法本身(不包括子方法)执行所占用的时间
Calls+RecurCalls/Total:调用+递归调用某方法的次数(Total只在点击一个方法后展示的详细项才有,代表总方法调用次数)
Cpu Time/Call:表示Incl Cpu Time / Call的时间,即某方法平均占用CPU时间
Real Time/Call:表示Incl Real / Call的时间,即某方法平均执行时间
方法调用堆栈比如这个表格,我选择了按Incl Real Time倒序排列。
发生这几个方法都只执行了一次,占用了20秒出头。因为我代码中是这么写的
因为Sleep方法执行耗时,但是Cpu并不需要运行,所以Incl Cpu Time很小。
@Override
protected void onCreate(Bundle savedInstanceState) {
super.onCreate(savedInstanceState);
setContentView(R.layout.activity_empty);
findViewById(R.id.btn).setOnClickListener(new View.OnClickListener() {
@Override
public void onClick(View v) {
doSomeNetwork();
}
});
}
private void doSomeNetwork() {
SystemClock.sleep(20000);
}
只观察当前包名的方法,可以看到从匿名内部类的onClick方法开始,TraceActivity到access$000(表示为了内部类可以访问外部类的私有方法或变量,Java编译器生成的一种特殊的静态方法),到doSomeNetWork方法,到SystemClock.sleep方法,到Thread.sleep方法执行时间都是20秒出头。并且由于这是包含关系,所以时间是递减的。
而从onClick方法往上看,也能看到我们的点击事件是从dispatchMessage方法开始,到handleCallback.....等等一系列的调用过程。
doSomeNetwork方法点开某个方法,比如doSomeNetwork来看,会列举出当前方法的父方法和子方法,点击这些父、子方法还能自动跳转,很方便。
一般如何使用这个工具?大概是分两类,一类是找执行时间久的方法,一类是找到调用次数多到不符合常理的方法。
一.执行时间久
主要是观察Incl Real Time,来个实际例子,代码如下,这是一个OkHttp请求后的回调。
@Override
public void onResponse(Call call, Response response) throws IOException {
if (response.isSuccessful()) {
DailiesJson dailiesJson = new Gson().fromJson(response.body().string(), DailiesJson.class);
if (TextUtils.isEmpty(endDate)) { //如果是首次加载这个界面
startDate = dailiesJson.getDate();
endDate = dailiesJson.getDate();
dailyAdapter.addList(dailiesJson.getStories());
getDataComplete(tartgetDate);
} else if (tartgetDate == null) { //表示下拉刷新
if (endDate.equals(dailiesJson.getDate())) { //App的最晚时间 等于 下拉新获取的时间
stopRefreshing();
} else { //App的最晚时间 不等于 下拉新获取的时间
endDate = dailiesJson.getDate();
dailyAdapter.addListToHeader(dailiesJson.getStories());
}
} else { //表示上拉加载
startDate = dailiesJson.getDate();
dailyAdapter.addList(dailiesJson.getStories());
getDataComplete(tartgetDate);
}
}
}
trace文件是这样的,
trace文件这方法是OkHttp访问url成功后的回调,可以看到里面的Gson.formJson方法在只执行了一次,却耗费了674毫秒。
之后就可以考虑看看是不是应该换个更快更给力的json解析工具比如fastjson,还是跟服务端讨论一下优化返回的json结构减少冗余。或者是把这段解析json的代码放入子线程里面完成以免影响主线程里的UI更新(OkHttp的onResponse默认是放在子线程里面的)。
二.调用次数多到不符合常理
除了执行方法耗时Incl Real Time,另一个需要关注的列是Calls+RecurCalls/Total。查看是不是某些方法多次冗余调用了。
很奇怪的如果是第一种通过代码生成的trace文件,我写了两个demo,RecyclerView.Adapter和ListView的BaseAdapter,里面的属于构建Item视图的onBindViewHolder方法和getView方法都无法正常显示调用次数。onBindViewHolder是完全找不到有这个方法,而getView方法是只显示调用了一次,而我日志打印出来其实getView已经执行了19次。
用了第二种方法就能正常显示了。这里我写了个ListView配BaseAdapter的demo。普通ListView,刚打开没有滑动时候,界面能显示比如6个Item,就是执行6次getView方法。大家都懂。然后对于ScrollView嵌套ListView,有一种解决方式是自定义ListViewForScrollView继承ListView,onMeasure方法里让它的高度一次性测量出来,具体了解看链接 Android开发之ScrollView中嵌套ListView的解决方案。
对于这种ListViewForScrollView,我们也来trace一下看看。
trace文件发现应用只是刚打开页面,还没滚动这个ScrollView,就已经执行了38次getView。
找到getView方法,发现它只有一个父类方法AbsListView.obtainView。很方便的我们点击它看看。
obtainView() Trace文件可以看到obtainView方法分别被ListView.makeAndAddView和ListView.measureHeightOfChildren各调用了19次。
具体原因是因为ListViewForScrollView是一下子测量出所有的item的高度并且一次性显示出来的。所以当然性能方面会比较差,这个ListView只有19个item还能忍一忍,item比较多的情况就不应该用这种方案了。
附一个普通且健康的ListView的BaseAdapter.getView的trace表格。可以看到真正执行时间只有72毫秒,是不是比上面的234毫秒快很多。
健康ListView有一点需要吐槽的,就是TraceView最底下的搜索栏根本不能搜索!!去StackOverFlow一搜,说从2012年发现的bug到现在还没修复。
http://stackoverflow.com/questions/38632495/android-traceview-find-on-traceview-does-not-work
更新:cmd中使用命令行打开的TraceView工具可以用搜索。
只能用命令行,直接点击会显示这个独立的traceview工具已废弃,请使用Android Device Monitor代替。有点醉。
C:\Users\Administrator\AppData\Local\Android\sdk\tools>traceview.bat C:\Users\Administrator\Desktop\dmtrace.trace
还有一种也是可以全局检测是否有耗时操作,比如主线程里有网络访问、磁盘读写的检测方式叫StrictMode。
总结一句就是使用方便,但是功能没有trace多。可以参考文章Android性能调优利器StrictMode。
网友评论