JuneLeo's Blog
0%

最简单的Trace工具

发表于 更新于

Trace工具主要是为了快速的分析java层方法耗时，在收集收集数据时，我们只收集了自己关注的数据，没有其他数据的干扰，可以很快的找到方法索引，分析方法耗时。
搜索方式：类名|方法名，或者方法名

方法1：com.autonavi.bundle.vui.impl.VUIOuterServiceImpl|loadVCS
image.png
方法2:com.autonavi.bundle.vui.impl.VUIOuterServiceImpl|preLoad
image.png

1 使用

1.1修改

android/amap_bundle_portal/build.gradle

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
buildscript {
    repositories {
        maven { url 'https://maven.amap.com/nexus/content/repositories/libs/' }
    }
    dependencies { 
        classpath 'com.amap.trace:trace-build:1.1.4' //放在classpath 'com.autonavi.scm:perf-hook:1.0.1-hookui'后面
    }
}
    

apply plugin: 'com.amap.trace' // 放在 apply from: '../gradle/ajx-module.gradle' 后面

trace {
    packages = ['com.autonavi.vcs','com.autonavi.bundle.vui'] // 过滤的包名，越少越快，这里过滤了vui的包名
    isUI = true   // 是否只收集UI线程耗时
}

1.2编译

1
tk build apk

如果编译有问题，删除如下目录

1
android/amap_bundle_portal/build/intermediates/transforms/AmapTraceTransform

1.3 运行app

方法栈为超过500次调用，输出一次方法栈记录
输出目录为：/sdcard/Android/data/com.autonavi.minimap/files/trace/trace-1672751118743

1
adb pull /sdcard/Android/data/com.autonavi.minimap/files/trace/

1.4 Perfetto查看

https://ui.perfetto.dev/
将导出的文件拖入perfetto网页
image.png
输入关注的方法：例如我想看VUICenter中的onPageLifeCreate方法
image.png
搜索：onPageLifeCreate 或者VUICenter|onPageLifeCreate
image.png
使用快捷键 w放大，s缩小，a左移，d右移

2 原理

我们这里使用了atrace的日志输出格式，我们给所有的关注的方法进行插桩，在方法开始和结束的位置进行打点，然后将打的点进行输出，输出格式是atrace的日志格式。
atrace的日志格式，我么可以使用systrace和perfetto进行解析。

2.1 atrace日志格式

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
capturing trace... done
TRACE:
# tracer: nop
#
# entries-in-buffer/entries-written: 251577/251577   #P:8
#
#                                      _-----=> irqs-off
#                                     / _----=> need-resched
#                                    | / _---=> hardirq/softirq
#                                    || / _--=> preempt-depth
#                                    ||| /     delay
#           TASK-PID    TGID   CPU#  ||||    TIMESTAMP  FUNCTION
#              | |        |      |   ||||       |         |
           <...>-14676 (14676) [004] .... 362012.007768: tracing_mark_write: B|14676|MainActivity:onCreate
           <...>-14676 (14676) [004] .... 362011.991722: tracing_mark_write: E|14676

格式如下：

1
<线程名>-<线程id> (进程id) [cpu] .... <us时间戳>: tracing_mark_write: <B|E>|<进程id>|<tag>|<args>

那么我们只需要在方法开始和结束的地方进行插桩，将上方的信息写入到trace日志中，即可统计到方法耗时。
我们导出的日志如下

1
2
3
4
5
6
7
8
9
TRACE:
# tracer: nop
#

main-30573 (30573) [001] ... 513231.528305: tracing_mark_write: B|30573|com.autonavi.bundle.vui.impl.VUIOuterServiceImpl|loadVCS
main-30573 (30573) [001] ... 513231.583242: tracing_mark_write: E|30573|com.autonavi.bundle.vui.impl.VUIOuterServiceImpl|loadVCS
TaskScheduler#3-30674 (30573) [001] ... 513231.729805: tracing_mark_write: B|30573|com.autonavi.bundle.vui.impl.VUIOuterServiceImpl|preLoad
TaskScheduler#3-30674 (30573) [001] ... 513231.732829: tracing_mark_write: E|30573|com.autonavi.bundle.vui.impl.VUIOuterServiceImpl|preLoad

2.2 插桩

这里插桩使用了tranform + asm；
image.png
AmapTrace 主要是将信息写入文件

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
public class AmapTrace {

    static ExecutorService executorService = Executors.newFixedThreadPool(1);

    public static List<String> traces = new ArrayList<>();

    public static int pid = 0;
    public static boolean isFirst = true;

    public static final String FILE_NAME = "trace-" + System.currentTimeMillis();
    public static String FILE_PATH;

    public static final Map<Long, Integer> threadMap = new HashMap<>();


    public static String getFilePath() {
        return FILE_PATH + File.separator + "files" + File.separator + "trace" + File.separator + FILE_NAME;
    }


    public static void startTrace(String methodId) {
        if (pid == 0) {
            pid = android.os.Process.myPid();
        }

        final long time = SystemClock.elapsedRealtimeNanos();

        Integer tid = getTid();


        String pkg = Thread.currentThread().getName();

        executorService.execute(new Runnable() {
            @Override
            public void run() {
                realStartTrace(methodId, tid, pkg, time);
            }
        });
    }

    private static int getTid() {
        Integer aLong = threadMap.get(Thread.currentThread().getId());
        if (aLong == null) {
            aLong = Process.myTid();
            threadMap.put(Thread.currentThread().getId(), aLong);
        }
        return aLong;
    }

    public static void endTrace(String methodId) {
    	if (pid == 0) {
            pid = android.os.Process.myPid();
        }

        final long time = SystemClock.elapsedRealtimeNanos();

        int tid = getTid();

        String pkg = Thread.currentThread().getName();

        executorService.execute(new Runnable() {
            @Override
            public void run() {
                realEndTrace(methodId, tid, pkg, time);
            }
        });

    }

    private static void realStartTrace(String methodId, int tid, String pkg, long time) {
        // <...>-14676 (14676) [004] .... 362012.007768: tracing_mark_write: B|14676|MainActivity:onCreate
        String us = String.valueOf(time / 1000);
        us = us.substring(0, 6) + "." + us.substring(6);
        traces.add(String.format("%s-%d (%d) [001] ... %s: tracing_mark_write: B|%d|%s", pkg, tid, pid, us, pid, methodId));
    }

    private static void realEndTrace(String methodId, int tid, String pkg, long time) {

        // <...>-14676 (14676) [004] .... 362012.007768: tracing_mark_write: B|14676|MainActivity:onCreate
        String us = String.valueOf(time / 1000);
        us = us.substring(0, 6) + "." + us.substring(6);
        traces.add(String.format("%s-%d (%d) [001] ... %s: tracing_mark_write: E|%d|%s", pkg, tid, pid, us, pid, methodId));
        if (traces.size() > 1000) {
            export();
        }
    }


    public static void export() {
        // 导出
    }
}

文件中FILE_PATH 没有进行赋值，是在编译阶段进行的字节码修改
image.png

3 问题

如果一个包中同时存在大小写class，解压时被覆盖的问题，如下，r.class 的内容会被R.class的内容覆盖。
image.png
image.png
这个问题暂时还没有解决，目前处理是当遇到这个jar包时，直接过滤了。

4 未来

未来计划使用Trace.beginSection和Trace.endSection，主要需要解决2个问题。

  1. hook FD : /sys/kernel/debug/tracing/trace_marker
  2. atrace_enabled_tags 的值返回1

hook 使用kwai::linker