Add instant trace methods

Bug: 207049735
Test: atest TraceDevTest
Change-Id: If2826a9bb1fb99d75ff3c9c03c16c2f5f1ec5d1b
This commit is contained in:
Lucas Dupin 2021-12-08 16:37:22 -08:00
parent 8189339de3
commit 2c2c5d998e
5 changed files with 166 additions and 0 deletions

View file

@ -207,6 +207,39 @@ static inline void atrace_async_end(uint64_t tag, const char* name, int32_t cook
}
}
/**
* Trace an instantaneous context. name is used to identify the context.
*
* An "instant" is an event with no defined duration. Visually is displayed like a single marker
* in the timeline (rather than a span, in the case of begin/end events).
*
* By default, instant events are added into a dedicated track that has the same name of the event.
* Use atrace_instant_for_track to put different instant events into the same timeline track/row.
*/
#define ATRACE_INSTANT(name) atrace_instant(ATRACE_TAG, name)
static inline void atrace_instant(uint64_t tag, const char* name) {
if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
void atrace_instant_body(const char*);
atrace_instant_body(name);
}
}
/**
* Trace an instantaneous context. name is used to identify the context.
* trackName is the name of the row where the event should be recorded.
*
* An "instant" is an event with no defined duration. Visually is displayed like a single marker
* in the timeline (rather than a span, in the case of begin/end events).
*/
#define ATRACE_INSTANT_FOR_TRACK(trackName, name) \
atrace_instant_for_track(ATRACE_TAG, trackName, name)
static inline void atrace_instant_for_track(uint64_t tag, const char* trackName, const char* name) {
if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) {
void atrace_instant_for_track_body(const char*, const char*);
atrace_instant_for_track_body(trackName, name);
}
}
/**
* Traces an integer counter value. name is used to identify the counter.
* This can be used to track how a value changes over time.

View file

@ -217,6 +217,28 @@ void atrace_async_end_body(const char* name, int32_t 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, "");
return;
}
if (atrace_marker_fd < 0) return;
WRITE_MSG("I|%d|", "%s", name, "");
}
void atrace_instant_for_track_body(const char* trackName, const char* name) {
if (CC_LIKELY(atrace_use_container_sock)) {
WRITE_MSG_IN_CONTAINER("N", "|", "|%s", trackName, name);
return;
}
if (atrace_marker_fd < 0) return;
WRITE_MSG("N|%d|", "|%s", name, trackName);
}
void atrace_int_body(const char* name, int32_t value)
{
if (CC_LIKELY(atrace_use_container_sock)) {

View file

@ -89,6 +89,14 @@ void atrace_async_end_body(const char* name, int32_t cookie)
WRITE_MSG("F|%d|", "|%" PRId32, name, cookie);
}
void atrace_instant_body(const char* 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_int_body(const char* name, int32_t value)
{
WRITE_MSG("C|%d|", "|%" PRId32, name, value);

View file

@ -195,6 +195,106 @@ TEST_F(TraceDevTest, atrace_async_end_body_truncated) {
ASSERT_STREQ(expected.c_str(), actual.c_str());
}
TEST_F(TraceDevTest, atrace_instant_body_normal) {
atrace_instant_body("fake_name");
ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
std::string actual;
ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
std::string expected = android::base::StringPrintf("I|%d|fake_name", getpid());
ASSERT_STREQ(expected.c_str(), actual.c_str());
}
TEST_F(TraceDevTest, atrace_instant_body_exact) {
std::string expected = android::base::StringPrintf("I|%d|", getpid());
std::string name = MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1);
atrace_instant_body(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 += name;
ASSERT_STREQ(expected.c_str(), actual.c_str());
// Add a single character and verify we get the exact same value as before.
ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
name += '*';
atrace_instant_body(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_body_truncated) {
std::string expected = android::base::StringPrintf("I|%d|", getpid());
std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH);
atrace_instant_body(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_normal) {
atrace_instant_for_track_body("fake_track", "fake_name");
ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
std::string actual;
ASSERT_TRUE(android::base::ReadFdToString(atrace_marker_fd, &actual));
std::string expected = android::base::StringPrintf("N|%d|fake_track|fake_name", getpid());
ASSERT_STREQ(expected.c_str(), actual.c_str());
}
TEST_F(TraceDevTest, atrace_instant_for_track_body_exact) {
const int nameSize = 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");
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";
ASSERT_STREQ(expected.c_str(), actual.c_str());
// Add a single character and verify we get the exact same value as before.
ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET));
trackName += '*';
atrace_instant_for_track_body(trackName.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;
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");
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());
ASSERT_STREQ(expected.c_str(), actual.c_str());
}
TEST_F(TraceDevTest, atrace_int_body_normal) {
atrace_int_body("fake_name", 12345);

View file

@ -28,6 +28,9 @@ void atrace_begin_body(const char* /*name*/) {}
void atrace_end_body() { }
void atrace_async_begin_body(const char* /*name*/, int32_t /*cookie*/) {}
void atrace_async_end_body(const char* /*name*/, int32_t /*cookie*/) {}
void atrace_instant_body(const char* /*name*/) {}
void atrace_instant_for_track_body(const char* /*trackName*/,
const char* /*name*/) {}
void atrace_int_body(const char* /*name*/, int32_t /*value*/) {}
void atrace_int64_body(const char* /*name*/, int64_t /*value*/) {}
void atrace_init() {}