tequilaOS/platform_system_core
2
0
Fork 0
Code Issues Pull requests Projects Releases Packages Wiki Activity

Added trackName as additional argument to WRITE_MSG to handle trace

Browse source 
messages with a track name

Bug: 220499650
Test: atest TraceDevTest
Change-Id: I3f6be6b693fb6f906b90655d5d553e853c4d4411
This commit is contained in:
Ray Ye 2022-03-15 23:28:01 +00:00
parent 95c777072f
commit 9a54240aba
4 changed files with 145 additions and 61 deletions
Show stats Download patch file Download diff file Expand all files Collapse all files

70
libcutils/trace-container.cpp
View file

@ -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);
}

18
libcutils/trace-dev.cpp
View file

@ -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);
}

33
libcutils/trace-dev.inc
View file

@ -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

85
libcutils/trace-dev_test.cpp
View file

@ -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());
}