Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 8461ca59 authored by Treehugger Robot's avatar Treehugger Robot Committed by Gerrit Code Review
Browse files

Merge "Added trackName as additional argument to WRITE_MSG to handle trace...

Merge "Added trackName as additional argument to WRITE_MSG to handle trace messages with a track name"
parents 4767dcca 9a54240a
Loading
Loading
Loading
Loading
+41 −29
Original line number Diff line number Diff line
@@ -131,29 +131,41 @@ static inline uint64_t gettime(clockid_t clk_id)

// Write trace events to container trace file. Note that we need to amend tid and time information
// here comparing to normal ftrace, where those informations are added by kernel.
#define WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value) { \
#define WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, \
        track_name, name, value) { \
    char buf[CONTAINER_ATRACE_MESSAGE_LENGTH]; \
    const char* track_name_sep = track_name[0] != '\0' ? "|" : ""; \
    int pid = getpid(); \
    int tid = gettid(); \
    uint64_t ts = gettime(CLOCK_MONOTONIC); \
    uint64_t tts = gettime(CLOCK_THREAD_CPUTIME_ID); \
    int len = snprintf( \
            buf, sizeof(buf), \
            ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s" value_format, \
            pid, tid, ts, tts, name, value); \
            ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s%s%s" value_format, \
            pid, tid, ts, tts, track_name, track_name_sep, name, value); \
    if (len >= (int) sizeof(buf)) { \
        int name_len = strlen(name) - (len - sizeof(buf)) - 1; \
        /* Truncate the name to make the message fit. */ \
        if (name_len > 0) { \
            ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \
            len = snprintf( \
                buf, sizeof(buf), \
                    ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%.*s" value_format, \
                    pid, tid, ts, tts, name_len, name, value); \
                ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s%s%.*s" value_format, \
                pid, tid, ts, tts, track_name, track_name_sep, name_len, name, value); \
        } else { \
            int track_name_len = 0; \
            if (track_name[0] != '\0') { \
                track_name_len = strlen(track_name) - (len - strlen(name) - sizeof(buf)) - 2; \
            } \
            if (track_name_len <= 0){ \
                /* Data is still too long. Drop it. */ \
            ALOGW("Data is too long in %s: %s\n", __FUNCTION__, name); \
                len = 0; \
            } else { \
                /* Truncate the trackName and name to make the message fit. */ \
                len = snprintf( \
                    buf, sizeof(buf), \
                    ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%.*s|%.1s" value_format, \
                    pid, tid, ts, tts, track_name_len, track_name, name, value); \
            } \
        } \
    } \
    if (len > 0) { \
@@ -161,10 +173,10 @@ static inline uint64_t gettime(clockid_t clk_id)
    } \
}

#define WRITE_MSG_IN_CONTAINER(ph, sep_before_name, value_format, name, value) { \
#define WRITE_MSG_IN_CONTAINER(ph, sep_before_name, value_format, track_name, name, value) { \
    pthread_rwlock_rdlock(&atrace_container_sock_rwlock); \
    if (atrace_container_sock_fd != -1) { \
       WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value); \
       WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, track_name, name, value); \
    } \
    pthread_rwlock_unlock(&atrace_container_sock_rwlock); \
}
@@ -172,93 +184,93 @@ static inline uint64_t gettime(clockid_t clk_id)
void atrace_begin_body(const char* name)
{
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("B", "|", "%s", name, "");
        WRITE_MSG_IN_CONTAINER("B", "|", "%s", "", name, "");
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("B|%d|", "%s", name, "");
    WRITE_MSG("B|%d|", "%s", "", name, "");
}

void atrace_end_body()
{
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("E", "", "%s", "", "");
        WRITE_MSG_IN_CONTAINER("E", "", "%s", "", "", "");
        return;
    }

    if (atrace_marker_fd < 0) return;

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

void atrace_async_begin_body(const char* name, int32_t cookie)
{
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("S", "|", "|%d", name, cookie);
        WRITE_MSG_IN_CONTAINER("S", "|", "|%d", "", name, cookie);
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("S|%d|", "|%" PRId32, name, cookie);
    WRITE_MSG("S|%d|", "|%" PRId32, "", name, cookie);
}

void atrace_async_end_body(const char* name, int32_t cookie)
{
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("F", "|", "|%d", name, cookie);
        WRITE_MSG_IN_CONTAINER("F", "|", "|%d", "", name, cookie);
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("F|%d|", "|%" PRId32, name, cookie);
    WRITE_MSG("F|%d|", "|%" PRId32, "", name, cookie);
}

void atrace_instant_body(const char* name) {
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("I", "|", "%s", name, "");
        WRITE_MSG_IN_CONTAINER("I", "|", "%s", "", name, "");
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("I|%d|", "%s", name, "");
    WRITE_MSG("I|%d|", "%s", "", name, "");
}

void atrace_instant_for_track_body(const char* trackName, const char* name) {
void atrace_instant_for_track_body(const char* track_name, const char* name) {
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("N", "|", "|%s", trackName, name);
        WRITE_MSG_IN_CONTAINER("N", "|", "%s", track_name, name, "");
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("N|%d|", "|%s", name, trackName);
    WRITE_MSG("N|%d|", "%s", track_name, name, "");
}

void atrace_int_body(const char* name, int32_t value)
{
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId32, name, value);
        WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId32, "", name, value);
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("C|%d|", "|%" PRId32, name, value);
    WRITE_MSG("C|%d|", "|%" PRId32, "", name, value);
}

void atrace_int64_body(const char* name, int64_t value)
{
    if (CC_LIKELY(atrace_use_container_sock)) {
        WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId64, name, value);
        WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId64, "", name, value);
        return;
    }

    if (atrace_marker_fd < 0) return;

    WRITE_MSG("C|%d|", "|%" PRId64, name, value);
    WRITE_MSG("C|%d|", "|%" PRId64, "", name, value);
}
+9 −9
Original line number Diff line number Diff line
@@ -71,38 +71,38 @@ void atrace_setup()

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

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

void atrace_async_begin_body(const char* name, int32_t cookie)
{
    WRITE_MSG("S|%d|", "|%" PRId32, name, cookie);
    WRITE_MSG("S|%d|", "|%" PRId32, "", name, cookie);
}

void atrace_async_end_body(const char* name, int32_t cookie)
{
    WRITE_MSG("F|%d|", "|%" PRId32, name, cookie);
    WRITE_MSG("F|%d|", "|%" PRId32, "", name, cookie);
}

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

void atrace_instant_for_track_body(const char* trackName, const char* name) {
    WRITE_MSG("N|%d|", "|%s", trackName, name);
void atrace_instant_for_track_body(const char* track_name, const char* name) {
    WRITE_MSG("N|%d|", "%s", track_name, name, "");
}

void atrace_int_body(const char* name, int32_t value)
{
    WRITE_MSG("C|%d|", "|%" PRId32, name, value);
    WRITE_MSG("C|%d|", "|%" PRId32, "", name, value);
}

void atrace_int64_body(const char* name, int64_t value)
{
    WRITE_MSG("C|%d|", "|%" PRId64, name, value);
    WRITE_MSG("C|%d|", "|%" PRId64, "", name, value);
}
+24 −9
Original line number Diff line number Diff line
@@ -185,21 +185,36 @@ void atrace_update_tags()
    }
}

#define WRITE_MSG(format_begin, format_end, name, value) { \
#define WRITE_MSG(format_begin, format_end, track_name, name, value) { \
    char buf[ATRACE_MESSAGE_LENGTH] __attribute__((uninitialized));     \
    const char* track_name_sep = track_name[0] != '\0' ? "|" : ""; \
    int pid = getpid(); \
    int len = snprintf(buf, sizeof(buf), format_begin "%s" format_end, pid, \
        name, value); \
    int len = snprintf(buf, sizeof(buf), format_begin "%s%s%s" format_end, pid, \
        track_name, track_name_sep, 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); \
        if (name_len > 0) { \
            len = snprintf(buf, sizeof(buf), format_begin "%s%s%.*s" format_end, pid, \
                track_name, track_name_sep, name_len, name, value); \
        } else { \
            int track_name_len = 0; \
            if (track_name[0] != '\0') { \
                track_name_len = strlen(track_name) - (len - strlen(name) - sizeof(buf)) - 2; \
            } \
            if (track_name_len <= 0) { \
                /* Data is still too long. Drop it. */ \
                len = 0; \
            } else { \
                /* Truncate the trackName and name to make the message fit */ \
                len = snprintf(buf, sizeof(buf), format_begin "%.*s|%.1s" format_end, pid, \
                    track_name_len, track_name, name, value); \
            } \
        } \
    } \
    if (len > 0) { \
        write(atrace_marker_fd, buf, len); \
    } \
}

#endif  // __TRACE_DEV_INC
+71 −14
Original line number Diff line number Diff line
@@ -255,43 +255,100 @@ TEST_F(TraceDevTest, atrace_instant_for_track_body_normal) {
    ASSERT_STREQ(expected.c_str(), actual.c_str());
}

TEST_F(TraceDevTest, atrace_instant_for_track_body_exact) {
    const int nameSize = 5;
TEST_F(TraceDevTest, atrace_instant_for_track_body_exact_track_name) {
    const int name_size = 5;
    std::string expected = android::base::StringPrintf("N|%d|", getpid());
    std::string trackName = MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - nameSize);
    atrace_instant_for_track_body(trackName.c_str(), "name");
    std::string track_name = MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - name_size);
    atrace_instant_for_track_body(track_name.c_str(), "name");

    ASSERT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));

    std::string actual;
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    expected += trackName + "|name";
    expected += track_name + "|name";
    ASSERT_STREQ(expected.c_str(), actual.c_str());

    // Add a single character and verify we get the exact same value as before.
    // Add a single character and verify name truncation
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
    trackName += '*';
    atrace_instant_for_track_body(trackName.c_str(), "name");
    track_name += '*';
    expected = android::base::StringPrintf("N|%d|", getpid());
    expected += track_name + "|nam";
    atrace_instant_for_track_body(track_name.c_str(), "name");
    EXPECT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    ASSERT_STREQ(expected.c_str(), actual.c_str());
}

TEST_F(TraceDevTest, atrace_instant_for_track_body_truncated) {
    const int nameSize = 5;
TEST_F(TraceDevTest, atrace_instant_for_track_body_truncated_track_name) {
    std::string expected = android::base::StringPrintf("N|%d|", getpid());
    std::string track_name = MakeName(2 * ATRACE_MESSAGE_LENGTH);
    atrace_instant_for_track_body(track_name.c_str(), "name");

    ASSERT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));

    std::string actual;
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    int expected_len = ATRACE_MESSAGE_LENGTH - expected.length() - 3;
    expected += android::base::StringPrintf("%.*s|n", expected_len, track_name.c_str());
    ASSERT_STREQ(expected.c_str(), actual.c_str());
}

TEST_F(TraceDevTest, atrace_instant_for_track_body_exact_name) {
    const int track_name_size = 11;
    std::string expected = android::base::StringPrintf("N|%d|", getpid());
    std::string trackName = MakeName(2 * ATRACE_MESSAGE_LENGTH);
    atrace_instant_for_track_body(trackName.c_str(), "name");
    std::string name = MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - track_name_size);
    atrace_instant_for_track_body("track_name", name.c_str());

    ASSERT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));

    std::string actual;
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    expected += "track_name|" + name;
    ASSERT_STREQ(expected.c_str(), actual.c_str());

    // Add a single character and verify we get the same value as before.
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
    name += '*';
    atrace_instant_for_track_body("track_name", name.c_str());
    EXPECT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    ASSERT_STREQ(expected.c_str(), actual.c_str());
}

TEST_F(TraceDevTest, atrace_instant_for_track_body_truncated_name) {
    std::string expected = android::base::StringPrintf("N|%d|track_name|", getpid());
    std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH);
    atrace_instant_for_track_body("track_name", name.c_str());

    ASSERT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));

    std::string actual;
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    int expected_len = ATRACE_MESSAGE_LENGTH - expected.length() - 1;
    expected += android::base::StringPrintf("%.*s", expected_len, name.c_str());
    ASSERT_STREQ(expected.c_str(), actual.c_str());
}

TEST_F(TraceDevTest, atrace_instant_for_track_body_truncated_both) {
    std::string expected = android::base::StringPrintf("N|%d|", getpid());
    std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH);
    std::string track_name = MakeName(2 * ATRACE_MESSAGE_LENGTH);
    atrace_instant_for_track_body(track_name.c_str(), name.c_str());

    ASSERT_EQ(ATRACE_MESSAGE_LENGTH - 1, lseek(atrace_marker_fd, 0, SEEK_CUR));
    ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));

    std::string actual;
    ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
    int expected_len = ATRACE_MESSAGE_LENGTH - expected.length() - 1 - nameSize;
    expected += android::base::StringPrintf("%.*s|name", expected_len, trackName.c_str());
    int expected_len = ATRACE_MESSAGE_LENGTH - expected.length() - 3;
    expected +=
        android::base::StringPrintf("%.*s|%.1s", expected_len, track_name.c_str(), name.c_str());
    ASSERT_STREQ(expected.c_str(), actual.c_str());
}