diff --git a/libcutils/include/cutils/trace.h b/libcutils/include/cutils/trace.h index 17a007090..98ae0d4ea 100644 --- a/libcutils/include/cutils/trace.h +++ b/libcutils/include/cutils/trace.h @@ -208,6 +208,37 @@ static inline void atrace_async_end(uint64_t tag, const char* name, int32_t cook } } +/** + * Trace the beginning of an asynchronous event. In addition to the name and a + * cookie as in ATRACE_ASYNC_BEGIN/ATRACE_ASYNC_END, a track name argument is + * provided, which is the name of the row where this async event should be + * recorded. The track name, name, and cookie used to begin an event must be + * used to end it. + */ +#define ATRACE_ASYNC_FOR_TRACK_BEGIN(track_name, name, cookie) \ + atrace_async_for_track_begin(ATRACE_TAG, track_name, name, cookie) +static inline void atrace_async_for_track_begin(uint64_t tag, const char* track_name, + const char* name, int32_t cookie) { + if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) { + void atrace_async_for_track_begin_body(const char*, const char*, int32_t); + atrace_async_for_track_begin_body(track_name, name, cookie); + } +} + +/** + * Trace the end of an asynchronous event. + * This should correspond to a previous ATRACE_ASYNC_FOR_TRACK_BEGIN. + */ +#define ATRACE_ASYNC_FOR_TRACK_END(track_name, name, cookie) \ + atrace_async_for_track_end(ATRACE_TAG, track_name, name, cookie) +static inline void atrace_async_for_track_end(uint64_t tag, const char* track_name, + const char* name, int32_t cookie) { + if (CC_UNLIKELY(atrace_is_tag_enabled(tag))) { + void atrace_async_for_track_end_body(const char*, const char*, int32_t); + atrace_async_for_track_end_body(track_name, name, cookie); + } +} + /** * Trace an instantaneous context. name is used to identify the context. * @@ -227,17 +258,18 @@ static inline void atrace_instant(uint64_t tag, const char* 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. + * track_name 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) { +static inline void atrace_instant_for_track(uint64_t tag, const char* track_name, + 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); + atrace_instant_for_track_body(track_name, name); } } diff --git a/libcutils/trace-container.cpp b/libcutils/trace-container.cpp index f3fdda40e..8901e4a40 100644 --- a/libcutils/trace-container.cpp +++ b/libcutils/trace-container.cpp @@ -229,6 +229,28 @@ void atrace_async_end_body(const char* name, int32_t cookie) WRITE_MSG("F|%d|", "|%" PRId32, "", name, cookie); } +void atrace_async_for_track_begin_body(const char* track_name, const char* name, int32_t cookie) { + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("T", "|", "|%d", track_name, name, cookie); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("T|%d|", "|%" PRId32, track_name, name, cookie); +} + +void atrace_async_for_track_end_body(const char* track_name, const char* name, int32_t cookie) { + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("U", "|", "|%d", track_name, name, cookie); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("U|%d|", "|%" PRId32, track_name, name, cookie); +} + void atrace_instant_body(const char* name) { if (CC_LIKELY(atrace_use_container_sock)) { WRITE_MSG_IN_CONTAINER("I", "|", "%s", "", name, ""); diff --git a/libcutils/trace-dev.cpp b/libcutils/trace-dev.cpp index 8bdeac588..eacc8ee56 100644 --- a/libcutils/trace-dev.cpp +++ b/libcutils/trace-dev.cpp @@ -89,6 +89,14 @@ void atrace_async_end_body(const char* name, int32_t cookie) WRITE_MSG("F|%d|", "|%" PRId32, "", name, cookie); } +void atrace_async_for_track_begin_body(const char* track_name, const char* name, int32_t cookie) { + WRITE_MSG("T|%d|", "|%" PRId32, track_name, name, cookie); +} + +void atrace_async_for_track_end_body(const char* track_name, const char* name, int32_t cookie) { + WRITE_MSG("U|%d|", "|%" PRId32, track_name, name, cookie); +} + void atrace_instant_body(const char* name) { WRITE_MSG("I|%d|", "%s", "", name, ""); } diff --git a/libcutils/trace-dev_test.cpp b/libcutils/trace-dev_test.cpp index 29a55900e..841674a99 100644 --- a/libcutils/trace-dev_test.cpp +++ b/libcutils/trace-dev_test.cpp @@ -195,6 +195,226 @@ TEST_F(TraceDevTest, atrace_async_end_body_truncated) { ASSERT_STREQ(expected.c_str(), actual.c_str()); } +TEST_F(TraceDevTest, atrace_async_for_track_begin_body_normal) { + atrace_async_for_track_begin_body("fake_track", "fake_name", 12345); + + 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("T|%d|fake_track|fake_name|12345", getpid()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_begin_body_exact_track_name) { + const int name_size = 5; + std::string expected = android::base::StringPrintf("T|%d|", getpid()); + std::string track_name = + MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - name_size - 6); + atrace_async_for_track_begin_body(track_name.c_str(), "name", 12345); + + 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|12345"; + ASSERT_STREQ(expected.c_str(), actual.c_str()); + + // Add a single character and verify name truncation + ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET)); + track_name += '*'; + expected = android::base::StringPrintf("T|%d|", getpid()); + expected += track_name + "|nam|12345"; + atrace_async_for_track_begin_body(track_name.c_str(), "name", 12345); + 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_async_for_track_begin_body_truncated_track_name) { + std::string expected = android::base::StringPrintf("T|%d|", getpid()); + std::string track_name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + atrace_async_for_track_begin_body(track_name.c_str(), "name", 12345); + + 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() - 9; + expected += android::base::StringPrintf("%.*s|n|12345", expected_len, track_name.c_str()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_begin_body_exact_name) { + const int track_name_size = 11; + std::string expected = android::base::StringPrintf("T|%d|", getpid()); + std::string name = + MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - track_name_size - 6); + atrace_async_for_track_begin_body("track_name", name.c_str(), 12345); + + 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 + "|12345"; + 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_async_for_track_begin_body("track_name", name.c_str(), 12345); + 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_async_for_track_begin_body_truncated_name) { + std::string expected = android::base::StringPrintf("T|%d|track_name|", getpid()); + std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + atrace_async_for_track_begin_body("track_name", name.c_str(), 12345); + + 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 - 6; + expected += android::base::StringPrintf("%.*s|12345", expected_len, name.c_str()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_begin_body_truncated_both) { + std::string expected = android::base::StringPrintf("T|%d|", getpid()); + std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + std::string track_name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + atrace_async_for_track_begin_body(track_name.c_str(), name.c_str(), 12345); + + 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 - 6; + expected += android::base::StringPrintf("%.*s|%.1s|12345", expected_len, track_name.c_str(), + name.c_str()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_end_body_normal) { + atrace_async_for_track_end_body("fake_track", "fake_name", 12345); + + 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("U|%d|fake_track|fake_name|12345", getpid()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_end_body_exact_track_name) { + const int name_size = 5; + std::string expected = android::base::StringPrintf("U|%d|", getpid()); + std::string track_name = + MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - name_size - 6); + atrace_async_for_track_end_body(track_name.c_str(), "name", 12345); + + 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|12345"; + ASSERT_STREQ(expected.c_str(), actual.c_str()); + + // Add a single character and verify name truncation + ASSERT_EQ(0, lseek(atrace_marker_fd, 0, SEEK_SET)); + track_name += '*'; + expected = android::base::StringPrintf("U|%d|", getpid()); + expected += track_name + "|nam|12345"; + atrace_async_for_track_end_body(track_name.c_str(), "name", 12345); + 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_async_for_track_end_body_truncated_track_name) { + std::string expected = android::base::StringPrintf("U|%d|", getpid()); + std::string track_name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + atrace_async_for_track_end_body(track_name.c_str(), "name", 12345); + + 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() - 9; + expected += android::base::StringPrintf("%.*s|n|12345", expected_len, track_name.c_str()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_end_body_exact_name) { + const int track_name_size = 11; + std::string expected = android::base::StringPrintf("U|%d|", getpid()); + std::string name = + MakeName(ATRACE_MESSAGE_LENGTH - expected.length() - 1 - track_name_size - 6); + atrace_async_for_track_end_body("track_name", name.c_str(), 12345); + + 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 + "|12345"; + 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_async_for_track_end_body("track_name", name.c_str(), 12345); + 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_async_for_track_end_body_truncated_name) { + std::string expected = android::base::StringPrintf("U|%d|track_name|", getpid()); + std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + atrace_async_for_track_end_body("track_name", name.c_str(), 12345); + + 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 - 6; + expected += android::base::StringPrintf("%.*s|12345", expected_len, name.c_str()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + +TEST_F(TraceDevTest, atrace_async_for_track_end_body_truncated_both) { + std::string expected = android::base::StringPrintf("U|%d|", getpid()); + std::string name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + std::string track_name = MakeName(2 * ATRACE_MESSAGE_LENGTH); + atrace_async_for_track_end_body(track_name.c_str(), name.c_str(), 12345); + + 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 - 6; + expected += android::base::StringPrintf("%.*s|%.1s|12345", expected_len, track_name.c_str(), + name.c_str()); + ASSERT_STREQ(expected.c_str(), actual.c_str()); +} + TEST_F(TraceDevTest, atrace_instant_body_normal) { atrace_instant_body("fake_name"); diff --git a/libcutils/trace-host.cpp b/libcutils/trace-host.cpp index b01a0ecba..c2a379b2f 100644 --- a/libcutils/trace-host.cpp +++ b/libcutils/trace-host.cpp @@ -28,9 +28,12 @@ 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_async_for_track_begin_body(const char* /*track_name*/, const char* /*name*/, + int32_t /*cookie*/) {} +void atrace_async_for_track_end_body(const char* /*track_name*/, 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_instant_for_track_body(const char* /*track_name*/, 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() {}