From 9a54240abab7f9ed3f71d167836c46fe9566ef16 Mon Sep 17 00:00:00 2001 From: Ray Ye Date: Tue, 15 Mar 2022 23:28:01 +0000 Subject: [PATCH] Added trackName as additional argument to WRITE_MSG to handle trace messages with a track name Bug: 220499650 Test: atest TraceDevTest Change-Id: I3f6be6b693fb6f906b90655d5d553e853c4d4411 --- libcutils/trace-container.cpp | 70 +++++++++++++++++------------ libcutils/trace-dev.cpp | 18 ++++---- libcutils/trace-dev.inc | 33 ++++++++++---- libcutils/trace-dev_test.cpp | 85 +++++++++++++++++++++++++++++------ 4 files changed, 145 insertions(+), 61 deletions(-) diff --git a/libcutils/trace-container.cpp b/libcutils/trace-container.cpp index ef7c72d1d..f3fdda40e 100644 --- a/libcutils/trace-container.cpp +++ b/libcutils/trace-container.cpp @@ -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); \ + buf, sizeof(buf), \ + 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 { \ - /* Data is still too long. Drop it. */ \ - ALOGW("Data is too long in %s: %s\n", __FUNCTION__, name); \ - len = 0; \ + 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), \ + 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); } diff --git a/libcutils/trace-dev.cpp b/libcutils/trace-dev.cpp index 25c86f436..8bdeac588 100644 --- a/libcutils/trace-dev.cpp +++ b/libcutils/trace-dev.cpp @@ -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); } diff --git a/libcutils/trace-dev.inc b/libcutils/trace-dev.inc index 3b459e094..94945ec7d 100644 --- a/libcutils/trace-dev.inc +++ b/libcutils/trace-dev.inc @@ -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); \ } \ - write(atrace_marker_fd, buf, len); \ } #endif // __TRACE_DEV_INC diff --git a/libcutils/trace-dev_test.cpp b/libcutils/trace-dev_test.cpp index ff6d20231..29a55900e 100644 --- a/libcutils/trace-dev_test.cpp +++ b/libcutils/trace-dev_test.cpp @@ -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 trackName = MakeName(2 * ATRACE_MESSAGE_LENGTH); - atrace_instant_for_track_body(trackName.c_str(), "name"); + 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() - 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|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 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() - 3; + expected += + android::base::StringPrintf("%.*s|%.1s", expected_len, track_name.c_str(), name.c_str()); ASSERT_STREQ(expected.c_str(), actual.c_str()); }