Is logging Android systrace events directly from n

Question

The Android systrace logging system is fantastic, but it only works in the Java portion of the code, through Trace.beginSection() and Trace.endSection(). In a C/C++ NDK (native) portion of the code it can only be used through JNI, which is slow or unavailable in threads without a Java environment...

Is there any way of either adding events to the main systrace trace buffer, or even generating a separate log, from native C code?

This older question mentions atrace/ftrace as being the internal system Android's systrace uses. Can this be tapped into (easily)?

BONUS TWIST: Since tracing calls would often be in performance-critical sections, it should ideally be possible to run the calls after the actual event time. i.e. I for one would prefer to be able to specify the times to log, instead of the calls polling for it themselves. But that would just be icing on the cake.

Answer 1

Posting a follow-up answer with some code, based on fadden's pointers. Please read his/her answer first for the overview.

All it takes is writing properly formatted strings to /sys/kernel/debug/tracing/trace_marker, which can be opened without problems. Below is some very minimal code based on the cutils header and C file. I preferred to re-implement it instead of pulling in any dependencies, so if you care a lot about correctness check the rigorous implementation there, and/or add your own extra checks and error-handling.

This was tested to work on Android 4.4.2.

The trace file must first be opened, saving the file descriptor in an atrace_marker_fd global:

#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>

#define ATRACE_MESSAGE_LEN 256
int     atrace_marker_fd = -1;

void trace_init()
{
  atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY);
  if (atrace_marker_fd == -1)   { /* do error handling */ }
}

Normal 'nested' traces like the Java Trace.beginSection and Trace.endSection are obtained with:

inline void trace_begin(const char *name)
{
    char buf[ATRACE_MESSAGE_LEN];
    int len = snprintf(buf, ATRACE_MESSAGE_LEN, "B|%d|%s", getpid(), name);
    write(atrace_marker_fd, buf, len);
}

inline void trace_end()
{
    char c = 'E';
    write(atrace_marker_fd, &c, 1);
}

Two more trace types are available, which are not accessible to Java as far as I know: trace counters and asynchronous traces.

Counters track the value of an integer and draw a little graph in the systrace HTML output. Very useful stuff:

inline void trace_counter(const char *name, const int value)
{
    char buf[ATRACE_MESSAGE_LEN];
    int len = snprintf(buf, ATRACE_MESSAGE_LEN, "C|%d|%s|%i", getpid(), name, value);
    write(atrace_marker_fd, buf, len);
}

Asynchronous traces produce non-nested (i.e. simply overlapping) intervals. They show up as grey segments above the thin thread-state bar in the systrace HTML output. They take an extra 32-bit integer argument that "distinguishes simultaneous events". The same name and integer must be used when ending traces:

inline void trace_async_begin(const char *name, const int32_t cookie)
{
    char buf[ATRACE_MESSAGE_LEN];
    int len = snprintf(buf, ATRACE_MESSAGE_LEN, "S|%d|%s|%i", getpid(), name, cookie);
    write(atrace_marker_fd, buf, len);
}

inline void trace_async_end(const char *name, const int32_t cookie)
{
    char buf[ATRACE_MESSAGE_LEN];
    int len = snprintf(buf, ATRACE_MESSAGE_LEN, "F|%d|%s|%i", getpid(), name, cookie);
    write(atrace_marker_fd, buf, len);
}

Finally, there indeed seems to be no way of specifying times to log, short of recompiling Android, so this doesn't do anything for the "bonus twist".

Answer 2

I don't think it's exposed from the NDK.

If you look at the sources, you can see that the android.os.Trace class calls into native code to do the actual work. That code calls atrace_begin() and atrace_end(), which are declared in a header in the cutils library.

You may be able to use the atrace functions directly if you extract the headers from the full source tree and link against the internal libraries. However, you can see from the header that atrace_begin() is simply:

static inline void atrace_begin(uint64_t tag, const char* name)
{
    if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
        char buf[ATRACE_MESSAGE_LENGTH];
        size_t len;
        len = snprintf(buf, ATRACE_MESSAGE_LENGTH, "B|%d|%s", getpid(), name);
        write(atrace_marker_fd, buf, len);
    }
}

Events are written directly to the trace file descriptor. (Note that the timestamp is not part of the event; that's added automatically.) You could do something similar in your code; see atrace_init_once() in the .c file to see how the file is opened.

Bear in mind that, unless atrace is published as part of the NDK, any code using it would be non-portable and likely to fail in past or future versions of Android. However, as systrace is a debugging tool and not something you'd actually want to ship enabled in an app, compatibility is probably not a concern.