您的浏览器不支持CSS3,建议使用Firfox、Chrome等浏览器,以取得最佳显示效果

基于AOP思想的Android方法耗时开源分析工具TimeTracer

开发技术 655℃ 0 4个月前 (02-26)

摘要

TimeTracer是一款基于AOP思想的Android方法耗时分析工具,功能类似Android Studio提供的CPU Profiler,但对App性能的影响更小。

背景

需要对APP的运行速度进行性能优化,在可能有性能问题的地方手工埋点的做法非常繁琐、效率低下,希望能有一个可以直观易用、自动化、精细化的分析代码耗时的工具。

Android Studio 提供了Profiler工具,其中 CPU Profiler(Instrument模式)可以实现方法耗时的精确追踪并生成火焰图,但是开启后对App的运行性能影响很大,会导致严重的卡顿,影响性能分析。特别是分析滚动卡顿的时候,页面滚动受到了很大影响,几乎没法正常操作App和分析问题。

备注:CPU Profiler有两种模式:

  • Sample模式,每隔一段指定的时长采样堆栈,然后利用堆栈推断方法调用(不保证完全准确)。采样间隔如果设置太大,则不能分析到耗时短但连续多次调用的方法;如果间隔设置太小,会影响性能。
  • Instrument模式,在方法起始和终止时记录时间,精确度高但是对性能影响较大。

另一个可用的方案就是Uber提供的 nanoscope 工具,对性能影响比较小,但是只能在模拟器或者Nexus 6P手机(需要刷机)中使用。

本文介绍一种基于AOP思想实现的分析工具TimeTracer,通过Javassist修改class字节码,对代码进行插桩,再配合一些Java代码,实现精确的方法级耗时分析,并且实测对性能影响很小。

AOP = Aspect Oriented Programming,意为面向切面编程,相关介绍可以网上找到,这里不细说。

整体思路

TimeTracer的源码和Demo工程可在GitHub获取:

https://github.com/jzj1993/TimeTracer

TimeTracer由Gradle插件和Java代码两部分组成。

Gradle插件在每个方法(包括构造函数)的起始和结束处插入一段特定的耗时统计代码。

Java耗时统计代码在方法的起始和结束时获取时间戳,并按照代码调用层级保存到栈中,然后按层级直接输出方法运行耗时。当然也可以进一步开发完善,输出更详细的结果。

TimeTracer可以:

  • 分析指定包 / 类 / 方法中的耗时
  • 分析主线程或指定线程

实现细节

Gradle插件实现

Gradle插件使用Google提供的Transform API,将源码和AAR包中的class取出来,用javassist库修改字节码。为了加速编译过程,用ForkJoinPool并行处理任务。

Gradle插件在每个方法的起始和结束处插入对TimeTracer的调用。

例如原始代码如下:

public class MainActivity {
    public void method1() {
        method2();
    }

    private void method2() {
        // ...
    }
}

经过插件处理后,如下:

public class MainActivity {
    public void method1() {
        TimeTracer.methodStart("MainActivity.method1");
        method2();
        TimeTracer.methodEnd("MainActivity.method1");
    }

    private void method2() {
        TimeTracer.methodStart("MainActivity.method2");
        // ...
        TimeTracer.methodEnd("MainActivity.method2");
    }
}

Java耗时统计实现

被统计方法的开头和结尾,都会调用TimeTracer的methodStart和methodEnd,TimeTracer中再调用ITracer实例的相应方法。

public interface ITracer {
    void traceStart();
    void traceEnd();
    void methodStart(String method);
    void methodEnd(String method);
}

public class TimeTracer {
    private static ITracer TRACER = ITracer.EMPTY_TRACER;
    // ...
    public static void methodStart(String method) {
        TRACER.methodStart(method);
    }

    public static void methodEnd(String method) {
        TRACER.methodEnd(method);
    }
}

BaseTimeTracer是ITracer的抽象实现,用于实现通用的分析逻辑。

BaseTimeTracer中用数组实现了一个栈结构,栈指针为level变量,该变量同时也代表方法调用层级。当一个方法调用开始时,将level加一,时间戳入栈。当一个方法调用结束时,将level减一,再次读取时间戳,并从栈中取出一个时间戳。对于同一个线程,方法调用的start和end是对称的,因此这个时间戳就是该方法调用开始时的时间戳,将这两个时间戳相减,即可算出方法耗时。

由于每个方法执行前后都会调用methodStart和methodEnd方法,因此为了减少统计方法自身对性能的影响,这两个方法中应避免耗时操作。

下面给出BaseTimeTracer中的关键代码:

public abstract class BaseTimeTracer implements ITracer {
    /**
     * 调用时间。直接用数组实现栈,减小对方法调用耗时的影响。
     */
    protected final long[] mTimes;
    /**
     * 方法名。直接用数组实现栈,减小对方法调用耗时的影响。
     */
    protected final String[] mNames;
    /**
     * 最大调用嵌套层级,也就是栈的容量。调用嵌套深度不能超过此数值,否则可能导致统计出错
     */
    private final int mMaxLevel;
    /**
     * 当前Level,相当于栈的指针
     */
    protected int mLevel = 0;

    // ....
    public BaseTimeTracer(int maxLevel) {
        mMaxLevel = maxLevel;
        mTimes = new long[mMaxLevel];
        mNames = new String[mMaxLevel];
    }

    // 检查是否满足要求,包括线程的检查。只有在同一个线程,start和end的调用才是对称的。
    protected abstract boolean checkMatchStart(String method);
    protected abstract boolean checkMatchEnd(String method);
    protected abstract long timestamp();

    @Override
    public void methodStart(String method) {
        if (!mEnable || !checkMatchStart(method)) {
            return;
        }
        if (mLevel >= mMaxLevel) {
            err("max level exceeded, maxLevel = " + mMaxLevel);
            return;
        }
        mTimes[mLevel] = timestamp(); // push
        mNames[mLevel] = method;
        ++mLevel;
    }

    @Override
    public void methodEnd(String method) {
        if (!mEnable || mLevel <= 0 || !checkMatchEnd(method)) {
            return;
        }
        String name = mNames[mLevel - 1];
        if (!methodEquals(name, method)) {
            return;
        }
        --mLevel;
        long time = timestamp() - mTimes[mLevel]; // pop
        output(method, mLevel, time);
    }

    /**
     * 方法耗时输出,可根据需要过滤。
     */
    protected void output(String method, int level, long time) {
        // ...
        log("%s%s: %d ms", space(level), method, time);
    }

    protected void log(String msg, Object... args) {
        Log.w(TAG, String.format(msg, args));
    }

    protected void err(String msg, Object... args) {
        Log.e(TAG, String.format(msg, args));
    }

    private String space(int level) {
        if (level <= 0) {
            return "";
        }
        char[] chars = new char[level];
        Arrays.fill(chars, '\t');
        return new String(chars);
    }
}

ThreadTimeTracer继承自BaseTimeTracer,用于统计指定线程中的耗时操作,其时间戳为当前线程执行时间。

public class ThreadTimeTracer extends BaseTimeTracer {

    private final Looper mLooper;

    public ThreadTimeTracer(Looper looper) {
        mLooper = looper;
    }

    @Override
    protected boolean checkMatchStart(String method) {
        return Looper.myLooper() == mLooper;
    }

    @Override
    protected boolean checkMatchEnd(String method) {
        return Looper.myLooper() == mLooper;
    }

    protected long timestamp() {
        return SystemClock.currentThreadTimeMillis();
    }
}

Gradle插件配置

在工程中的配置:

buildscript {
    dependencies {
        // 简单起见,这里直接引用plugin模块编译生成的jar文件,不发布maven
        classpath files('plugin/output/plugin.jar')
        classpath 'org.javassist:javassist:3.20.0-GA'
    }
}
apply plugin: 'TimeTracer'
TimeTracer {
    // 指定要处理的完整类名,正则表达式匹配,可以过滤特定的包,
    // 不指定则默认处理所有类(TimeTracer自身的实现除外)
    // processClassesRegex 'com\\.paincker\\.timetracer\\.demo.*'

    // 指定插入到方法开头和结束处的代码,
    // 支持简单变量,包括<class-name>,<simple-class-name>,<method-name>
    codeBeforeMethod "com.paincker.timetracer.tracer.TimeTracer.methodStart(\"<simple-class-name>.<method-name>\");";
    codeAfterMethod "com.paincker.timetracer.tracer.TimeTracer.methodEnd(\"<simple-class-name>.<method-name>\");";
}

使用示例

Demo工程中写了一个简单的RecyclerView,其中onBindView中进行了一些耗时代码调用,导致RecyclerView的滑动卡顿。

为了定位滑动卡顿的具体代码,在Demo工程中配置使用TimeTracer,追踪方法调用。在Demo工程中执行10s,期间滑动RecyclerView,得出Log信息如图,可以看出方法调用层级和耗时。

很容易看出来耗时的方法,stringOperation占用了较多时间,是造成滑动卡顿的主要原因。

备注:

  • 这里只是一个简单示例,onBindView中代码不多,因此直接人工也能定位到问题,代码调用层级复杂的时候,工具才能更充分的发挥优势。
  • 统计插件自身也有性能消耗,调用层级越深,消耗越多。不过由于其中的代码较简单,每次执行时间都是微秒级别的,而且所有方法都有相似的逻辑,因此采集到数据的参考价值仍然较高。

下图为使用Android Studio自带CPU Profiler生成的结果(Trace模式)。

CPU Profiler和TimeTracer对比

CPU ProfilerTimeTracer
使用方法AndroidStudio在Debug环境下直接按钮启动、停止分析,并查看数据先写代码,编译打包后测试,通过代码控制启动时机
测试范围APP范围内所有线程所有方法,包括系统API的调用工程中的所有方法,可根据需要写代码进行过滤,重点分析某个包、某个线程、特定条件下的代码
数据查看支持火焰图等形式使用Log输出,能满足最简单基本的需要,也可以自行开发扩展
优点图形化界面比较直观运行速度快,不影响App操作;可定制性强(例如分析指定条件下的数据,结合自动化工具实现数据收集等)
缺点容易导致电脑和手机卡死,特别是影响手机App正常操作;功能灵活度有限不能查看APP以外的代码耗时,不过问题不大,因为一般都是优化项目本身的代码;Log输出的方式比较简陋

总结

由于TimeTracer需要对大量方法插入代码,进行精确耗时分析,数据量较大,本身对性能有一定的影响。因此主要用于开发和测试阶段分析性能,不宜用于线上环境。

从进一步优化的角度来看,可以将统计信息输出成可视化的HTML,使用不同的颜色和尺寸,直观的展示每个耗时方法;还可以对结果进行排序,显示最耗时的方法等。

最后,欢迎扫码关注微信公众号。微软 / Shopee / Coupang / BAT等国内外企业内推、行业和技术交流,也可以加我微信 jzj2015(注明来自博客),拉你进技术群。

本文由原创,转载请注明来源:https://www.paincker.com/time-tracer
(标注了原文链接的文章除外)

0

暂无评论

评论前:需填写以下信息,或 登录

用户登录

忘记密码?