ATrace流程

邢少年
2,189 阅读7分钟

ATrace流程

ps:2022年11月29日对前文进行修改

1: 前言

在性能优化中很重要的一点就是监控,如果不能监控到没有对应的日志和数据,即便是有接收到用户或者测试的反馈,研发也有一些巧妇难为无米之炊.

拿我们常用的SysTrace工具来说,需要python进行抓取,那么这个在线上直接进行使用相对来说就很麻烦了.Systrace是基于Atrace进行开发的,本文就研究下Atrace的流程,也给我们后续直接通过Atrce日志进行监控优化进行一个预研.

2: Trace入口

我们从Trace最常用的代码作为一个切入口进行分析,在Java代码中使用需要在函数入口加Trace.traceBegin和函数终止处加入Trace.traceEnd.顺着这个入口我们接着查看其流程.

/**
 * Writes a trace message to indicate that a given section of code has
 * begun. Must be followed by a call to {@link #traceEnd} using the same
 * tag.
 *
 * @param traceTag The trace tag.
 * @param methodName The method name to appear in the trace.
 *
 * @hide
 */
public static void traceBegin(long traceTag, String methodName) {
    if (isTagEnabled(traceTag)) {
        nativeTraceBegin(traceTag, methodName);
    }
}

/**
 * Writes a trace message to indicate that the current method has ended.
 * Must be called exactly once for each call to {@link #traceBegin} using the same tag.
 *
 * @param traceTag The trace tag.
 *
 * @hide
 */
public static void traceEnd(long traceTag) {
    if (isTagEnabled(traceTag)) {
        nativeTraceEnd(traceTag);
    }
}

不过我们看到对应的函数有@hide标签,如果在正常的应用开发中是没办法直接调用的,应该使用Trace.beginSection和Trace.endSection函数.可以看到只是多了一个sectionName的长度校验,主要的判断还是在isTagEnabled中.我们接下来看isTagEnabled.

public static void beginSection(String sectionName) {
    if (isTagEnabled(TRACE_TAG_APP)) {
        if (sectionName.length() > MAX_SECTION_NAME_LEN) {
            throw new IllegalArgumentException("sectionName is too long");
        }
        nativeTraceBegin(TRACE_TAG_APP, sectionName);
    }
}

public static void endSection() {
    if (isTagEnabled(TRACE_TAG_APP)) {
        nativeTraceEnd(TRACE_TAG_APP);
    }
}

public static boolean isTagEnabled(long traceTag) {
    long tags = sEnabledTags;
    if (tags == TRACE_TAG_NOT_READY) {
        //这里
        tags = cacheEnabledTags();
    }
    return (tags & traceTag) != 0;
}

private static long cacheEnabledTags() {
    //这里可以看到是一个Native函数
    long tags = nativeGetEnabledTags();
    sEnabledTags = tags;
    return tags;
}

上面的代码中,最终我们在函数处加的Trace统计是否生效,最终走到了cacheEnabledTags,而这个Tag不是TRACE_TAG_NOT_READY就会生效.

我们看一下Trace中的所有Native函数定义,看Trace类的的包名为package android.os;,可以去找android_os_Trace.cpp,名称和包名类名是对应的.

private static native long nativeGetEnabledTags();
private static native void nativeSetAppTracingAllowed(boolean allowed);
private static native void nativeSetTracingEnabled(boolean allowed);

@FastNative
private static native void nativeTraceCounter(long tag, String name, int value);
@FastNative
private static native void nativeTraceBegin(long tag, String name);
@FastNative
private static native void nativeTraceEnd(long tag);
@FastNative
private static native void nativeAsyncTraceBegin(long tag, String name, int cookie);
@FastNative
private static native void nativeAsyncTraceEnd(long tag, String name, int cookie)

3: Trace的逻辑

3.1: JNI调用

我列出部分Native的函数的定义,可以看到确实和Trace类中的Native函数一一对应, 我们首先看android_os_Trace_nativeTraceBegin

{ "nativeTraceBegin",
        "(JLjava/lang/String;)V",
        (void*)android_os_Trace_nativeTraceBegin },
{ "nativeTraceEnd",
        "(J)V",
        (void*)android_os_Trace_nativeTraceEnd },
{ "nativeAsyncTraceBegin",
        "(JLjava/lang/String;I)V",
        (void*)android_os_Trace_nativeAsyncTraceBegin },
{ "nativeAsyncTraceEnd",
        "(JLjava/lang/String;I)V",
        (void*)android_os_Trace_nativeAsyncTraceEnd },

#include <cutils/trace.h>

static void android_os_Trace_nativeTraceBegin(JNIEnv* env, jclass clazz,
        jlong tag, jstring nameStr) {
    ScopedStringChars jchars(env, nameStr);
    String8 utf8Chars(reinterpret_cast<const char16_t*>(jchars.get()), jchars.size());
    sanitizeString(utf8Chars);

    ALOGV("%s: %" PRId64 " %s", __FUNCTION__, tag, utf8Chars.string());
    //除了对nameStr,也就是最初定义的sectionName,atrace_begin定义在trace.h中.
    atrace_begin(tag, utf8Chars.string());
}

在Android的JNI层一般情况下是不存在具体的逻辑,基本上就是对对象做个转换,做个基本判断这样,在nativeTraceBegin也不例外.我们需要接着寻找atrace_begin在哪里进行具体的实现.

3.2: Atrace具体逻辑

文件路径system/core/include/cutils/trace.h

我们最终在system目录找到了具体的函数定义.

#define ATRACE_BEGIN(name) atrace_begin(ATRACE_TAG, name)
static inline void atrace_begin(uint64_t tag, const char* name)
{
     // 3.2.1: Trace判断逻辑
    if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
        void atrace_begin_body(const char*);
        //3.2.2: Trace输出逻辑
        atrace_begin_body(name);
    }
}

3.2.1 Atrace的开启判断

Atrace_is_Enable-0.png

上面是我梳理的ATrace的开启判断流程,Java和JNI的调用我们就直接跳过,我们从trace.h开始说起

  • 文件路径system/core/include/cutils/trace.h

首先先叉开一下,在atrace_begin函数中有一个判断函数atrace_is_tag_enabled,我们看下这个函数,满足了什么条件Atrace才可以输出日志.我们发现它最终也是调用的atrace_get_enabled_tags,也就是在Atrace的每次日志输出时都对tag进行了同样的判断,我们将整个开启的逻辑判断一起分析一下

/**
 * Test if a given tag is currently enabled.
 * Returns nonzero if the tag is enabled, otherwise zero.
 * It can be used as a guard condition around more expensive trace calculations.
 */
#define ATRACE_ENABLED() atrace_is_tag_enabled(ATRACE_TAG)
static inline uint64_t atrace_is_tag_enabled(uint64_t tag)
{
    return atrace_get_enabled_tags() & tag;
}

上面的代码中接着调用atrace_get_enabled_tags,atrace_get_enabled_tags也就回到图中的第6步.


#define ATRACE_GET_ENABLED_TAGS() atrace_get_enabled_tags()
static inline uint64_t atrace_get_enabled_tags()
{
    // 这里
    atrace_init();
    
    return atrace_enabled_tags;
}

我们接着看atrace_init函数.

#define ATRACE_INIT() atrace_init()
static inline void atrace_init()
{

    if (CC_UNLIKELY(!atomic_load_explicit(&atrace_is_ready, memory_order_acquire))) {
        atrace_setup();
    }
}

在atrace_init函数中我们看到对应的判断中的调用中有一些判断,因为这个地方可能多个线程同时去调用atrace_begin函数,很谨慎为了防止乱序等问题,用原子操作去判断是否已经初始化

  • 文件路径-system/core/libcutils/trace-dev.cpp
void atrace_setup()
{
    //可以看到这里使用pthread_once函数去执行 atrace_init_once函数
    pthread_once(&atrace_once_control, atrace_init_once);
}

总结atrace_init和atrace_setup函数就是Atrace的怕初始化不太及时,因为有可能在任何进程任何位置去使用它进行标记,所以它在第一个引用自己的函数中做了初始化的操作,为了防止多个进程同时使用导致多次初始化的问题有使用atomic_load_explicit和pthread_once防止多次调用的问题.

static void atrace_init_once()
{
    // 打开trace_marker
    atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC);
    if (atrace_marker_fd == -1) {
        ALOGE("Error opening trace file: %s (%d)", strerror(errno), errno);
        atrace_enabled_tags = 0;
        goto done;
    }

    atrace_enabled_tags = atrace_get_property();

done:
    atomic_store_explicit(&atrace_is_ready, true, memory_order_release);
}

我们接着分析一下atrace_init_once函数,就是首先要拿到/sys/kernel/debug/tracing/trace_marker这个节点文件的句柄,如果获取失败,就直接返回0,trace_marker的文件创建依赖于内核的CONFI_FTRACE的配置.

如果文件存在,atrace_enabled_tags就会依赖于atrace_get_property的结果,我们对其后续的逻辑进行分析.

// Read the sysprop and return the value tags should be set to
static uint64_t atrace_get_property()
{
    char value[PROPERTY_VALUE_MAX];
    char *endptr;
    uint64_t tags;
    //获取属性值,默认为0
    property_get("debug.atrace.tags.enableflags", value, "0");
    errno = 0;
    //看不明白的话,请自己查看C的函数原型
    tags = strtoull(value, &endptr, 0);
    // 判断格式是否正确
    if (value[0] == '\0' || *endptr != '\0') {
        ALOGE("Error parsing trace property: Not a number: %s", value);
        return 0;
    } else if (errno == ERANGE || tags == ULLONG_MAX) {
        ALOGE("Error parsing trace property: Number too large: %s", value);
        return 0;
    }

    // Only set the "app" tag if this process was selected for app-level debug
    // tracing.
    //我们看这个app进程是如何判断的
    if (atrace_is_app_tracing_enabled()) {
        tags |= ATRACE_TAG_APP;
    } else {
        tags &= ~ATRACE_TAG_APP;
    }

    return (tags | ATRACE_TAG_ALWAYS) & ATRACE_TAG_VALID_MASK;
}

// Determine whether application-level tracing is enabled for this process.
static bool atrace_is_app_tracing_enabled()
{
    //最终判断ro.debuggable
    bool sys_debuggable = __android_log_is_debuggable();
    bool result = false;
    //atrace_is_debuggable 默认为false,也就是说如果是release固件,普通的app进程很难通过这个判断,
    //所以很多框架都也是通过dlopen hook的方式,直接修改返回值.
    if (sys_debuggable || atrace_is_debuggable) {
        // Check whether tracing is enabled for this process.
        FILE * file = fopen("/proc/self/cmdline", "re");
        if (file) {
            char cmdline[4096];
            if (fgets(cmdline, sizeof(cmdline), file)) {
                //这里
                result = atrace_is_cmdline_match(cmdline);
            } else {
                ALOGE("Error reading cmdline: %s (%d)", strerror(errno), errno);
            }
            fclose(file);
        } else {
            ALOGE("Error opening /proc/self/cmdline: %s (%d)", strerror(errno),
                    errno);
        }
    }

    return result;
}

// Check whether the given command line matches one of the comma-separated
// values listed in the app_cmdlines property.
static bool atrace_is_cmdline_match(const char* cmdline)
{
    //获取这个属性值
    int count = property_get_int32("debug.atrace.app_number", 0);

    char buf[PROPERTY_KEY_MAX];
    char value[PROPERTY_VALUE_MAX];

    for (int i = 0; i < count; i++) {
        snprintf(buf, sizeof(buf), "debug.atrace.app_%d", i);
        property_get(buf, value, "");
        //最终看对应的进程是否存在debug.atrece中.
        if (strcmp(value, "*") == 0 || strcmp(value, cmdline) == 0) {
            return true;
        }
    }

    return false;
}

3.2.2 写入逻辑

它的实现类在system/core/libcutils/trace-dev.cpp中.可以看到函数内部非常简单就是一个宏函数,我们接下来去找宏函数的定义.

void atrace_begin_body(const char* name)
{
    WRITE_MSG("B|%d|", "%s", name, "");
}

void atrace_end_body()
{
    WRITE_MSG("E|%d", "%s", "", "");
}

WRITE_MSG宏函数定义在system/core/libcutils/trace-dev.inc中,可以看到对应的字符被加工之后,被写入了atrace_marker_fd中,看一下atrace_marker_fd在哪里赋值的.


#define ATRACE_MESSAGE_LENGTH 1024

int atrace_marker_fd     = -1;


#define WRITE_MSG(format_begin, format_end, name, value) { \
    char buf[ATRACE_MESSAGE_LENGTH]; \
    int pid = getpid(); \
    int len = snprintf(buf, sizeof(buf), format_begin "%s" format_end, pid, \
        name, value); \
    if (len >= (int) sizeof(buf)) { \
        /* Given the sizeof(buf), and all of the current format buffers, \
         * it is impossible for name_len to be < 0 if len >= sizeof(buf). */ \
        int name_len = strlen(name) - (len - sizeof(buf)) - 1; \
        /* Truncate the name to make the message fit. */ \
        ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \
        len = snprintf(buf, sizeof(buf), format_begin "%.*s" format_end, pid, \
            name_len, name, value); \
    } \
    write(atrace_marker_fd, buf, len); \
}

#endif  // __TRACE_DEV_INC

logTag - cutils-trace

总结

atrace还是比较简单的,基本的流程和原理基本上分析完了,相对比较简单.

  • 1: 写入的时候B,E这些不同的字符和特定的规则加上进程ID等组合到一起,然后经过转换为我们分析的systrace日志.
  • 2: 写入的文件路径就是/sys/kernel/debug/tracing/trace_marker,前提是设备内核打开了Ftrace的开关,才会创建该文件.
  • 3: 总结一下就是上层框架通过代码注入的方式在应用层的函数中加上trace的标签,然后通过dlopen打开atrace的开关,然后在拿到trace_marker中的数据,加上格式转换进行分析.
  • 4:下一章节在对Ftrace的流程进行分析一下.

反思

回忆一下学习Android性能优化的过程中,systrace是一个必经过程,在这段过程中也自己尝试去解决一些问题,很多都是通过systrace发现的.

也因为有一些设备在kernel中没有开启CONFIG_FTRACE,进而没有其他好的手段去做一些优化,自己也尝试去看了systrace的一些基本依赖于atrce,ftace等基础框架.不过大多没有仔细的阅读完成,对其内在的联系也并没有完全的看下去,有一天看到了抖音 Android 性能优化系列：新一代全能型性能分析工具 Rhea这篇文章,很多关节瞬间清晰了起来,忽然有一些惭愧了起来,一个应用层能将优化工具玩到怎么牛的地步,而作为一个系统开发工程师,却对很多根本性的问题望而却步.

avatar
文章
阅读
粉丝