使用TraceView+实际案列实战性能分析找出android app UI卡顿原因

川长思鸟来 2021-11-17 11:46 378阅读 0赞

### TraceView ###

*  前言
 *  UI卡顿
 *  TraceView
 *   *  Debug
     *  DDMS 工具
 *  实例分析
 *   *  Profile Panel

# 前言 #

最近公司SE拿了一个南京厂家做的一款工程机跟我反映一个问题，说在这个手机上使用公司APP的一个上下翻页功能的时候，翻页动作执行的就像慢动作一样（看下图）；瞬间我特么菊花一紧，居然有这种事，这不能忍啊，同时心中也是一万只草泥马奔腾而过，心想：大哥 你又从哪个不知名厂家拿了个手机过来啊，鬼知道他们的手机有没有问题呢，测试都用了十来台工程机和市场上的民用手机都没出现这问题；但是现实是残酷的，谁让我是程序猿呢，只能乖乖的去查原因了

![在这里插入图片描述][20181203194918539.gif]  
这是将翻页功能单独做个demo，可以看到翻页的过程很慢

# UI卡顿 #

ui卡顿应该是程序猿最不想见到的问题了，或者说现象吧，因为这让用户很直接的感受到极差的使用体验，此时用户的内心OS：这什么垃圾APP啊，做的这么卡；心情好点的可能连带着手机一起怼，这什么垃圾手机啊，性能这么差；所以在平常开发的时候一定要注意这方面的问题，多做测试，同时多拿一些机型测试，毕竟Android碎片化太严重了，随便一个小厂家都能做个手机出来卖。

一般来说UI卡顿，比如列表卡顿，动画卡顿，界面切换卡顿，基本上都是因为主线程有耗时操作，影响视图的连贯展示；而耗时有两种情况：

*  方法调用次数不多，但是单次执行该方法耗时
 *  方法单次执行不耗时，但是调用次数过多导致耗时

开头也说了，只在这款工程机上出现了翻页慢的情况，所以第一种情况是不可能了；所以只能考虑第二种情况了，因为第二种情况还是要取决于设备的硬件的，但是想一眼找到哪块方法耗时真不容易，这时候就要借助工具来帮我们找出到底谁在偷偷的做耗时操作

# TraceView #

本文要用到的性能分析工具就是TraceView，它是Android平台的特有的一个用于性能分析的工具，通过图形化界面的方式展示程序的性能表现，可以具体追踪到方法级别；TraceView本身是一个数据分析工具，而数据采集需要依靠Debug 类或者 DDMS 工具，两者用法如下

## Debug ##

假如你明确知道是哪个方法耗时，或者哪个操作耗时，这时候你就可以通过Debug类的API来分析；比如你想测下方法A要消耗多长时间和这段时间内所有线程的执行情况（只有Java线程），那就在方法A的开头添加Debug.startMethodTracing方法，然后结束时添加Debug.stopMethodTracing方法（想分析Native层的用startNativeTracing方法）；这时候会在SD卡根目录下生成一个dmtrace.trace文件，切记要添加并申请WRITE\_EXTERNAL\_STORAGE权限，如下

public void onClick(View v) {
    
            Debug.startMethodTracing();
    
            //接下來做一些耗時操作
    
            Debug.stopMethodTracing();
    
        }

接下来将文件导入到电脑，你们可以看下自己的SDK安装目录下的tools目录下有一个traceview.bat文件，进入到这个目录然后在dos中运行traceview C:\\tracefile\\dmtrace.trace，然后就能看到一个分析图形了，最后按照官方文档分析就行了

## DDMS 工具 ##

我今天就是用这个工具来进行数据采集，DDMS 的全称是Dalvik Debug Monitor Service，是 Android 开发环境中的Dalvik虚拟机调试监控服务，可采集系统中某个正在运行的进程的函数调用信息；这个工具比较适合盲测，比如你也不知道具体哪个方法会出现耗时，那就通过它把APP的某一段使用过程进行方法追踪分析

使用方法是在Android Studio里进行如下操作

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70]  
或者直接在dos窗口中输入monitor，接着就会弹出Android Device Monitor窗口：

![在这里插入图片描述][20181203195419179.png]

![在这里插入图片描述][2018120319560681.png]

点击上图中的按钮你可能会弹出一个选择框，如下

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 1]

*  第一个：基于样本的分析，通过在给定频率上中断VM并在那时收集调用堆栈来工作。 开销与采样频率成正比
 *  第二个：基于跟踪的分析，通过跟踪每个方法的进入和退出来工作。这捕获了所有方法的执行，无论多小，因此具有高开销

我这里选择第二种

# 实例分析 #

接下来就使用这个工具再结合上面说的翻页卡顿例子实际操作，看看如何分析卡顿原因

我们打开DDMS，点击上方图中的按钮，然后做一次翻页动作，接着再次点击那个按钮停止方法追踪分析，这时DDMS会自动触发Traceview工具来分析采集数据，并弹出可视化的面板，如下

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 2]

我这里就是追踪了一个翻页动作的方法执行情况，这个面板分为三部分：

*  A区域：罗列出追踪过程中所采集到的线程信息，可以看到这里采集到了三个线程
 *  B区域：即Timeline Panel(时间线面板)，标尺是时间线，下方是每个线程一个时间段内所涉及的方法调用信息，这些信息包括函数名、函数执行时间等，突出的颜色区域其实是由每个小立柱组成的，每个小立柱即代表一次方法调用，将鼠标放上去就会显示相应的信息；你如果觉得太密集，可以滚动鼠标上的滚轴进行放大显示
 *  C区域：即Profile Panel(分析面板)，这个区域是Traceview的核心，非常详细的展示了一段时间内该进程内的各个方法调用的情况，以及占用CPU时间，调用次数等信息，不过这里要注意这个时间是Java层方法执行时间，不包括Native层函数执行时间

## Profile Panel ##

接下来重点就是分析这个Profile Panel了，那需要先了解这个面板上的名称的意义，如下这幅图：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 3]

该图片顶部有多个英文名称，含义如下

<table> 
 <thead> 
  <tr> 
   <th>名称</th> 
   <th>含义</th> 
  </tr> 
 </thead> 
 <tbody> 
  <tr> 
   <td>Name</td> 
   <td>追踪期间所调用的方法</td> 
  </tr> 
  <tr> 
   <td>Incl Cpu Time %</td> 
   <td>Cpu执行该方法及其子方法所花费时间占Cpu总执行时间的百分比</td> 
  </tr> 
  <tr> 
   <td>Incl Cpu Time</td> 
   <td>Cpu执行该方法该方法及其子方法所花费的时间，以毫秒为单位</td> 
  </tr> 
  <tr> 
   <td>Excl Cpu Time %</td> 
   <td>Cpu执行该方法所花费的时间占Cpu总时间的百分比，不包含内部调用其它方法时间</td> 
  </tr> 
  <tr> 
   <td>Excl Cpu Time</td> 
   <td>Cpu执行该方法所花费的时间，不包含内部调用其它方法时间，以毫秒为单位</td> 
  </tr> 
  <tr> 
   <td>Incl Real Time %</td> 
   <td>该方法及其子方法从开始执行到结束所花费的实际时间占总时间的百分比</td> 
  </tr> 
  <tr> 
   <td>Incl Real Time</td> 
   <td>该方法及其子方法从开始执行到结束所花费的实际时间，以毫秒为单位</td> 
  </tr> 
  <tr> 
   <td>Excl Real Time %</td> 
   <td>该方法从开始执行到结束所花费的实际时间占总时间的百分比，不包含子方法</td> 
  </tr> 
  <tr> 
   <td>Excl Real Time</td> 
   <td>该方法从开始执行到结束所花费的实际时间，以毫秒为单位，不包含子方法</td> 
  </tr> 
  <tr> 
   <td>Calls+Recur Calls/Total</td> 
   <td>方法调用次数+递归次数 调用次数/总次数 【前半截是方法的数据，后半截是点击方法后下方弹出的子方法的数据】</td> 
  </tr> 
  <tr> 
   <td>Cpu Time/Call</td> 
   <td>Cpu执行时间和调用次数的百分比，表示每次调用所消耗的Cpu时间</td> 
  </tr> 
  <tr> 
   <td>Real Time/Call</td> 
   <td>方法执行实践花费的时间和调用次数的百分比，表示该方法平均执行时间</td> 
  </tr> 
 </tbody> 
</table>

我们可以点击每个名称进行排序，这里以Incl Cpu Time进行降序排列，点击上图中的第一行，如下图：  
![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 4]

可以看到占比最高的79.8%的方法是FlipRenderer类的onDrawFrame方法，并且CPU总的执行时间是817ms，这个方法就占用了652ms，从后面的Incl Real Time也表面该方法实际执行了1196ms，调用了24次；那我就继续点击这个方法看看，会跳到如下图所示的结果

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 5]

这个图可以看到有Parents和Children两栏，其中Parents下方表示调用该方法的父方法，Children下方表示该方法内部调用的子方法，接下来我们继续点击比例最高的方法进入看看，直到下方这个图

![在这里插入图片描述][watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 6]

最终可以看到是self这行的Incl Cpu Time比例最高，self代表自身方法中的语句执行情况，也就是说Cpu执行这个方法自身语句所花费的时间最多；同时可以看下Incl Real Time的值，除去执行自己语句的484.144ms的耗时，内部还调用了一个GLUtils.texSubImage2D方法耗时507.571ms；这样翻页慢的原因就是这个createTexture方法了

其实从后面的Calls+Recur Calls/Total 可以看出来createTexture方法被调用了48次，Incl Real Time值表明48次调用花费时间是1032.437ms，平均一次调用要1032.437/4821.509 = 21.509ms，跟Real Time/Call值是一样的，这也说明这种UI卡顿是属于单次执行不耗时，但是调用次数多了就耗时的情况

通过对比发现，这一个createTexture方法在其它设备上执行一次只需要5ms左右，但是在这个设备上执行一次时间就翻了5倍；一看手机使用的是一款联发科的低配版cpu，不过最后还是自己优化了下这个方法，降低执行所花费的时间，基本算解决了这个问题；大家也可以使用这个方法去分析下自己app里的UI卡顿原因

[20181203194918539.gif]: /images/20211116/68e6234168dd42158423b20df4ab83e0.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70]: /images/20211116/c6b6119513ca42dfa01e89806c4dc974.png
[20181203195419179.png]: /images/20211116/869609b452a64167b36783815fd4779e.png
[2018120319560681.png]: /images/20211116/a7b418e9995c4d5ba0ba80e8e9ce05e9.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 1]: /images/20211116/df2f4aec88be41e5a58b01b60d3bd261.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 2]: /images/20211116/471fa8ebecb84dcfb3e373c5992b389b.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 3]: /images/20211116/69ae901d07994375b9c9a93d2d6cc00e.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 4]: /images/20211116/bf6d00ddac404f2fa08a008f6096fc7a.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 5]: /images/20211116/6b521491451447398ad751a30f6d682e.png
[watermark_type_ZmFuZ3poZW5naGVpdGk_shadow_10_text_aHR0cHM6Ly9ibG9nLmNzZG4ubmV0L3FxXzMwOTkzNTk1_size_16_color_FFFFFF_t_70 6]: /images/20211116/f824e724509e454f9eec3bbb2dbbe661.png