Hook Application trace log

Last time about atrace implementation, in fact the main is to write a few system attributes and nodes, and then the APP will trace the log write/sys/kernel/debug/tracing/trace_marker. Therefore, if you do not want to use the atrace function through the command line, you only need to enable the trace function and hook to write to the file node to achieve this function.

Analysis of the`hook` 点

BeginSection method is used to record Trace logs. You can see that only isTagEnabled(TRACE_TAG_APP) is true can you log

  public static void beginSection(String sectionName) {
      if(isTagEnabled(TRACE_TAG_APP)) { nativeTraceBegin(TRACE_TAG_APP, sectionName); }}Copy the code

IsTagEnabled depends on whether the sEnabledTags static variable TRACE_TAG_APP (1L << 12) is set to 1

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(a) {
    long tags = nativeGetEnabledTags();
    sEnabledTags = tags;
    return tags;
}
Copy the code


static jlong android_os_Trace_nativeGetEnabledTags(JNIEnv* env, jclass clazz) {
    return atrace_get_enabled_tags(a); }static inline uint64_t atrace_get_enabled_tags(a)
{
    atrace_init(a);return atrace_enabled_tags;
}
Copy the code

SEnabledTags are controlled by command line arguments when reading logs through the Atrace directory.

Therefore, sEnabledTags need to be set through reflection, and atrace_enabled_tags variable of native layer should be set, because native layer also has a similar judgment.

static inline void atrace_begin(uint64_t tag, const char* name)
{
    if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
        void atrace_begin_body(const char*);
        atrace_begin_body(name); }}static inline uint64_t atrace_is_tag_enabled(uint64_t tag)
{
    return atrace_get_enabled_tags() & tag;
}

Copy the code

Finally, atrace_begin_body is called

void atrace_begin_body(const char* name)
{
    char buf[ATRACE_MESSAGE_LENGTH];

    int len = snprintf(buf, sizeof(buf), "B|%d|%s".getpid(), name);
    if (len >= (int) sizeof(buf)) {
        ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name);
        len = sizeof(buf) - 1;
    }
    write(atrace_marker_fd, buf, len);
}
Copy the code

As you can see, it is simply write atrace_marker_fd, so just hook the process and write the log to another file to get the APP trace log.

To obtain`trace_marker`File descriptor and`atrace_enabled_tags`

Use kwai::linker to find the atrace_enabled_tags and atrace_marker_fd symbols from libcutils.so.

The following code is from profilo reference, you can see that is simple dlopen and DLSYm two tracks, interesting is the source code of atrace_enabled_tags is defined as uint64_t, This is where STD ::atomic

is strongly changed.

uint64_t                atrace_enabled_tags  = ATRACE_TAG_NOT_READY;
Copy the code

int* atrace_marker_fd = nullptr;
std::atomic<uint64_t>* atrace_enabled_tags = nullptr;

auto sdk = android_get_device_api_level(a); {ALOGE("SDK %d ", sdk);
    using kwai::linker::DlFcn;
    std::string lib_name("libcutils.so");
    std::string enabled_tags_sym("atrace_enabled_tags");
    std::string fd_sym("atrace_marker_fd");

    if (sdk < 18) {
        lib_name = "libutils.so";
        // android::Tracer::sEnabledTags
        enabled_tags_sym = "_ZN7android6Tracer12sEnabledTagsE";
        // android::Tracer::sTraceFD
        fd_sym = "_ZN7android6Tracer8sTraceFDE";
    }

    void* handle;
    if (sdk < 21) {
        handle = DlFcn::dlopen(lib_name.c_str(), RTLD_LOCAL);
    } else {
        handle = DlFcn::dlopen(lib_name.c_str(), RTLD_GLOBAL);
    }

    atrace_enabled_tags = reinterpret_cast<std::atomic<uint64_t>*>(
            DlFcn::dlsym(handle, enabled_tags_sym.c_str()));

    if (atrace_enabled_tags == nullptr) {
        throw std::runtime_error("Enabled Tags not defined");
    }

    atrace_marker_fd = reinterpret_cast<int*>(DlFcn::dlsym(handle, fd_sym.c_str()));

    if (*atrace_marker_fd == - 1) {
        // This is a case that can happen for older Android version i.e. 4.4
        // in which scenario the marker fd is not initialized/opened by Zygote.
        // Nevertheless for Profilo trace it is not necessary to have an open fd,
        // since all we really need is to ensure that we 'know' it is marker
        // fd to continue writing Profilo logs, thus the usage of marker fd
        // acting really as a placeholder for magic id.
        *atrace_marker_fd = - 100.;
    }

    DlFcn::dlclose(handle);
}
Copy the code

open`trace`

According to source code analysis, atrace_enabled_tags is an INT64_t, each of which represents atrace tag, so setting all 1 means opening all functions, which is set in native, but also needs to be set in the upper layer. Reflection calls nativeGetEnabledTags and then sets the value to trace.SenabledTags.

atrace_enabled_tags->exchange(UINT64_MAX);
Copy the code

private object SystraceReflector {
    fun updateSystraceTags(a) {
        if(sTrace_sEnabledTags ! =null&& sTrace_nativeGetEnabledTags ! =null) {
            try{ sTrace_sEnabledTags? .set(
                    null, sTrace_nativeGetEnabledTags? .invoke(null))}catch (e: IllegalAccessException) {
            } catch (e: InvocationTargetException) {
            }
        }
    }

    private var sTrace_nativeGetEnabledTags: Method? = null
    private var sTrace_sEnabledTags: Field? = null

    init {
        var m: Method?
        try {
            m = Trace::class.java.getDeclaredMethod("nativeGetEnabledTags")
            m.setAccessible(true)}catch (e: NoSuchMethodException) {
            m = null
        }
        sTrace_nativeGetEnabledTags = m
        var f: Field?
        try {
            f = Trace::class.java.getDeclaredField("sEnabledTags")
            f.setAccessible(true)}catch (e: NoSuchFieldException) {
            f = null
        }
        sTrace_sEnabledTags = f
    }
}
Copy the code

`hook write`call

Atrace_marker_fd (xhook); Very simple, hook all loaded so write and __write_chk functions directly. If profilo only hooks the following 7 SOS, trace log will be missed, resulting in functions in trace.html generated Did not finished. I don’t know which SOS were missed, so I simply hook all of them. However, this will result in extra flag bits, but it does not affect the visualization, so let’s settle for now :P.

"libandroid_runtime.so",
"libui.so",
"libgui.so",
"libart.so",
"libhwui.so",
"libEGL.so",
"libcutils.so"
Copy the code

bool should_log_systrace(int fd, size_t count) {
    return systrace_installed && fd == *atrace_marker_fd;
}

ssize_t write_hook(int fd, const void* buf, size_t count) {
    if (should_log_systrace(fd, count)) {
        log_systrace(buf, count);
        return count;
    }
    return write(fd, buf, count);
}

size_t (*orig__write_chk)(int fd, const void* buf, size_t count, size_t buf_size);

size_t hook__write_chk(int fd, const void* buf, size_t count, size_t buf_size) {
    if (should_log_systrace(fd, count)) {
        log_systrace(buf, count);
        return count;
    }
    return orig__write_chk(fd, buf, count, buf_size);
}

void hookLoadedLibs(a) {
    xhook_register(".*\\.so$"."write", (void *) write_hook, nullptr);
    xhook_register(".*\\.so$"."__write_chk", (void *) hook__write_chk,
                   (void **) &orig__write_chk);
    // ignore the current so hook
    xhook_ignore(".*toy_lib\\.so$"."write");
    xhook_ignore(".*toy_lib\\.so$"."__write_chk");

    xhook_refresh(0);
    xhook_clear(a); }Copy the code

Save the log

From the previous article, a trace log that can generate visual HTML using systrace.py must start with the following three lines of the log, maybe two, without testing.

TRACE:
# tracer: nop
#
Copy the code

The log format must be in the following format

< thread name >-< thread ID > [000]... 1 < time > - seconds: tracing_mark_write: < B > | E | < process id > | < TAG >Copy the code

But we get to the log Only the last section < B > | E | < process id > | < TAG >, so you need to together again and then write here need to get the thread name, thread id and MONOTONIC time.

The thread ID can be obtained from gettid().

The thread name can be read from /proc/ /task/

/comm. The pid can be obtained from getpid().

The time is obtained by clock_getTime (CLOCK_MONOTONIC, &t), which needs to be converted from nanosecond to second, and converted from int64_t to double, otherwise the time accuracy is not correct.

A file was created in the /data/local/ TMP directory, but it was not successfully created. There may be a permission problem, so it can only be temporarily received and created in the command line. For code brevity, write to the log synchronously. CPP basically did not write, are temporary grope copy Baidu Google, write a little hot eyes, please forgive me, probably meaning is that :P.

int fd = 0;
std::map<int, std::string> mapThreadName;

std::string getThreadName(int tid) {
    std::map<int, std::string>::iterator iter;
    iter = mapThreadName.find(tid);

    if(iter ! = mapThreadName.end()) {
        return iter->second;
    } else {
        char fname[128];
        int len = sprintf(fname, "/proc/%d/task/%d/comm".getpid(), tid);
        int cfd = open(fname, O_RDONLY);
        if (cfd) {
            char name[32];
            int c = read(cfd, name,  32);
            if (c > 0) {
                mapThreadName[tid] = std::string(name, c - 1);
                returnmapThreadName[tid]; }}}return std::to_string(tid);
}

typedef int64_t nsecs_t; // nano-seconds
nsecs_t systemTime(a)
{
    struct timespec t;
    t.tv_sec = t.tv_nsec = 0;
    clock_gettime(CLOCK_MONOTONIC, &t);
    return nsecs_t(t.tv_sec)*1000000000LL + t.tv_nsec;
}


void log_systrace(const void* buf, size_t count) {
    const char* msg = reinterpret_cast<const char*>(buf);
    double f = double(systemTime/ ())1000000000;
    switch (msg[0]) {
        case 'B':
            ALOGE("%s", buf); //"B|<pid>|<name>"
            if (fd) {
                char buf1[1024];
                int len = snprintf(buf1, sizeof(buf1), "%s-%d [000] ... 1 %.6f: tracing_mark_write: %s\n".getThreadName(gettid()).c_str(), gettid(), f, msg);
                write(fd, buf1, len);
            }
            break;
        case 'E':
            ALOGE("E");  // "E"
            if (fd) {
                char buf1[1024];
                int len = snprintf(buf1, sizeof(buf1), "%s-%d [000] ... 1 %.6f: tracing_mark_write: E\n".getThreadName(gettid()).c_str(), gettid(), f);
                write(fd, buf1, len);
            }
            break;
        default:
            return; }}void installAtrace(a) {
    fd = open("/data/local/tmp/mytrace.txt", O_WRONLY | O_CREAT, 0666);
    std::string head("TRACE:\n# tracer: nop\n#\n");
    write(fd, head.c_str(), head.size());
    
    // Open the trace function
}

Copy the code

Looking at the log file, you can see that the required format was generated correctly

TRACE:
# tracer: nop
#
RenderThread- 20036. [000]..1. 241751.465787: tracing_mark_write: B|19945|AttachCurrentThread
RenderThread- 20036. [000]..1. 241751.468185: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.468293: tracing_mark_write: B|19945|postAndWait
com.example.toy- 19945. [000]..1. 241751.477535: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.493119: tracing_mark_write: B|19945|postAndWait
com.example.toy- 19945. [000]..1. 241751.493345: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.493457: tracing_mark_write: B|19945|postAndWait
com.example.toy- 19945. [000]..1. 241751.493575: tracing_mark_write: E
RenderThread- 20036. [000]..1. 241751.494002: tracing_mark_write: B|19945|notifyFramePending
RenderThread- 20036. [000]..1. 241751.494100: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.499166: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.499489: tracing_mark_write: B|19945|postAndWait
com.example.toy- 19945. [000]..1. 241751.499661: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.501794: tracing_mark_write: B|19945|Choreographer#doFrame
com.example.toy- 19945. [000]..1. 241751.501954: tracing_mark_write: B|19945|input
com.example.toy- 19945. [000]..1. 241751.502065: tracing_mark_write: E
com.example.toy- 19945. [000]..1. 241751.502129: tracing_mark_write: B|19945|traversal

Copy the code

The last step is to convert the saved logs using the Systrace tool, which will not be demonstrated.

At the same time, this is only the APP log, if you need other logs, such as CPU scheduling, you need to turn on the real FTrace function like atrace tool, and then merge it with the whole APP log.

Reference documentation

Douyin Android Performance Optimization Series: a new generation of all-purpose performance analysis tool Rhea

Systrace principle, process and customization

profilo

xhook

AndroidAdvanceWithGeektime_Chapter06

Analysis of thehook 点

To obtaintrace_markerFile descriptor andatrace_enabled_tags

opentrace

hook writecall

Save the log

Reference documentation

Related Posts

WebView ADAPTS to post night mode

A HashMap and Hashtable

Retrofit source code analysis

Analysis of the`hook` 点

To obtain`trace_marker`File descriptor and`atrace_enabled_tags`

open`trace`

`hook write`call