美文网首页
(转载)Android 耗时代码(ANR)的查找检测和分析解决

(转载)Android 耗时代码(ANR)的查找检测和分析解决

作者: Walter_Hu | 来源:发表于2018-09-09 15:08 被阅读41次

    原文链接: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

    相关文章

      网友评论

          本文标题:(转载)Android 耗时代码(ANR)的查找检测和分析解决

          本文链接:https://www.haomeiwen.com/subject/pztdgftx.html