liblog: test: pmsg overhead measurement
This test tells us that scatter-gather (writev instead of write)
carries a small ~2% penalty. Unaligned buffer carry a similar
additional penalty. On N9 it takes 3us to 22us _just_ to write
the pmsg logs, depending on size. Some assumptions about the
socket read and write performance for the main logging can be made
from tracking these results and should improve design decisions.
Bug: 18771697
Bug: 23685592
Change-Id: Id4d64c449140e4f39078c62b0097e403df91fe0c
diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp
index b594634..9f29a09 100644
--- a/liblog/tests/liblog_benchmark.cpp
+++ b/liblog/tests/liblog_benchmark.cpp
@@ -14,11 +14,17 @@
* limitations under the License.
*/
+#include <fcntl.h>
+#include <sys/endian.h>
#include <sys/socket.h>
+#include <sys/types.h>
+#include <unistd.h>
+
#include <cutils/sockets.h>
#include <log/log.h>
#include <log/logger.h>
#include <log/log_read.h>
+#include <private/android_logger.h>
#include "benchmark.h"
@@ -85,6 +91,380 @@
BENCHMARK(BM_clock_overhead);
/*
+ * Measure the time it takes to submit the android logging data to pstore
+ */
+static void BM_pmsg_short(int iters) {
+
+ int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY));
+ if (pstore_fd < 0) {
+ return;
+ }
+
+ /*
+ * struct {
+ * // what we provide to pstore
+ * android_pmsg_log_header_t pmsg_header;
+ * // what we provide to socket
+ * android_log_header_t header;
+ * // caller provides
+ * union {
+ * struct {
+ * char prio;
+ * char payload[];
+ * } string;
+ * struct {
+ * uint32_t tag
+ * char payload[];
+ * } binary;
+ * };
+ * };
+ */
+
+ struct timespec ts;
+ clock_gettime(android_log_clockid(), &ts);
+
+ android_pmsg_log_header_t pmsg_header;
+ pmsg_header.magic = LOGGER_MAGIC;
+ pmsg_header.len = sizeof(android_pmsg_log_header_t)
+ + sizeof(android_log_header_t);
+ pmsg_header.uid = getuid();
+ pmsg_header.pid = getpid();
+
+ android_log_header_t header;
+ header.tid = gettid();
+ header.realtime.tv_sec = ts.tv_sec;
+ header.realtime.tv_nsec = ts.tv_nsec;
+
+ static const unsigned nr = 1;
+ static const unsigned header_length = 2;
+ struct iovec newVec[nr + header_length];
+
+ newVec[0].iov_base = (unsigned char *) &pmsg_header;
+ newVec[0].iov_len = sizeof(pmsg_header);
+ newVec[1].iov_base = (unsigned char *) &header;
+ newVec[1].iov_len = sizeof(header);
+
+ android_log_event_int_t buffer;
+
+ header.id = LOG_ID_EVENTS;
+ buffer.header.tag = 0;
+ buffer.payload.type = EVENT_TYPE_INT;
+ uint32_t snapshot = 0;
+ buffer.payload.data = htole32(snapshot);
+
+ newVec[2].iov_base = &buffer;
+ newVec[2].iov_len = sizeof(buffer);
+
+ StartBenchmarkTiming();
+ for (int i = 0; i < iters; ++i) {
+ ++snapshot;
+ buffer.payload.data = htole32(snapshot);
+ writev(pstore_fd, newVec, nr);
+ }
+ StopBenchmarkTiming();
+ close(pstore_fd);
+}
+BENCHMARK(BM_pmsg_short);
+
+/*
+ * Measure the time it takes to submit the android logging data to pstore
+ * best case aligned single block.
+ */
+static void BM_pmsg_short_aligned(int iters) {
+
+ int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY));
+ if (pstore_fd < 0) {
+ return;
+ }
+
+ /*
+ * struct {
+ * // what we provide to pstore
+ * android_pmsg_log_header_t pmsg_header;
+ * // what we provide to socket
+ * android_log_header_t header;
+ * // caller provides
+ * union {
+ * struct {
+ * char prio;
+ * char payload[];
+ * } string;
+ * struct {
+ * uint32_t tag
+ * char payload[];
+ * } binary;
+ * };
+ * };
+ */
+
+ struct timespec ts;
+ clock_gettime(android_log_clockid(), &ts);
+
+ struct packet {
+ android_pmsg_log_header_t pmsg_header;
+ android_log_header_t header;
+ android_log_event_int_t payload;
+ };
+ char buf[sizeof(struct packet) + 8] __aligned(8);
+ memset(buf, 0, sizeof(buf));
+ struct packet *buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7);
+ if (((uintptr_t)&buffer->pmsg_header) & 7) {
+ fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters);
+ }
+
+ buffer->pmsg_header.magic = LOGGER_MAGIC;
+ buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t)
+ + sizeof(android_log_header_t);
+ buffer->pmsg_header.uid = getuid();
+ buffer->pmsg_header.pid = getpid();
+
+ buffer->header.tid = gettid();
+ buffer->header.realtime.tv_sec = ts.tv_sec;
+ buffer->header.realtime.tv_nsec = ts.tv_nsec;
+
+ buffer->header.id = LOG_ID_EVENTS;
+ buffer->payload.header.tag = 0;
+ buffer->payload.payload.type = EVENT_TYPE_INT;
+ uint32_t snapshot = 0;
+ buffer->payload.payload.data = htole32(snapshot);
+
+ StartBenchmarkTiming();
+ for (int i = 0; i < iters; ++i) {
+ ++snapshot;
+ buffer->payload.payload.data = htole32(snapshot);
+ write(pstore_fd, &buffer->pmsg_header,
+ sizeof(android_pmsg_log_header_t) +
+ sizeof(android_log_header_t) +
+ sizeof(android_log_event_int_t));
+ }
+ StopBenchmarkTiming();
+ close(pstore_fd);
+}
+BENCHMARK(BM_pmsg_short_aligned);
+
+/*
+ * Measure the time it takes to submit the android logging data to pstore
+ * best case aligned single block.
+ */
+static void BM_pmsg_short_unaligned1(int iters) {
+
+ int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY));
+ if (pstore_fd < 0) {
+ return;
+ }
+
+ /*
+ * struct {
+ * // what we provide to pstore
+ * android_pmsg_log_header_t pmsg_header;
+ * // what we provide to socket
+ * android_log_header_t header;
+ * // caller provides
+ * union {
+ * struct {
+ * char prio;
+ * char payload[];
+ * } string;
+ * struct {
+ * uint32_t tag
+ * char payload[];
+ * } binary;
+ * };
+ * };
+ */
+
+ struct timespec ts;
+ clock_gettime(android_log_clockid(), &ts);
+
+ struct packet {
+ android_pmsg_log_header_t pmsg_header;
+ android_log_header_t header;
+ android_log_event_int_t payload;
+ };
+ char buf[sizeof(struct packet) + 8] __aligned(8);
+ memset(buf, 0, sizeof(buf));
+ struct packet *buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1);
+ if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) {
+ fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters);
+ }
+
+ buffer->pmsg_header.magic = LOGGER_MAGIC;
+ buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t)
+ + sizeof(android_log_header_t);
+ buffer->pmsg_header.uid = getuid();
+ buffer->pmsg_header.pid = getpid();
+
+ buffer->header.tid = gettid();
+ buffer->header.realtime.tv_sec = ts.tv_sec;
+ buffer->header.realtime.tv_nsec = ts.tv_nsec;
+
+ buffer->header.id = LOG_ID_EVENTS;
+ buffer->payload.header.tag = 0;
+ buffer->payload.payload.type = EVENT_TYPE_INT;
+ uint32_t snapshot = 0;
+ buffer->payload.payload.data = htole32(snapshot);
+
+ StartBenchmarkTiming();
+ for (int i = 0; i < iters; ++i) {
+ ++snapshot;
+ buffer->payload.payload.data = htole32(snapshot);
+ write(pstore_fd, &buffer->pmsg_header,
+ sizeof(android_pmsg_log_header_t) +
+ sizeof(android_log_header_t) +
+ sizeof(android_log_event_int_t));
+ }
+ StopBenchmarkTiming();
+ close(pstore_fd);
+}
+BENCHMARK(BM_pmsg_short_unaligned1);
+
+/*
+ * Measure the time it takes to submit the android logging data to pstore
+ * best case aligned single block.
+ */
+static void BM_pmsg_long_aligned(int iters) {
+
+ int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY));
+ if (pstore_fd < 0) {
+ return;
+ }
+
+ /*
+ * struct {
+ * // what we provide to pstore
+ * android_pmsg_log_header_t pmsg_header;
+ * // what we provide to socket
+ * android_log_header_t header;
+ * // caller provides
+ * union {
+ * struct {
+ * char prio;
+ * char payload[];
+ * } string;
+ * struct {
+ * uint32_t tag
+ * char payload[];
+ * } binary;
+ * };
+ * };
+ */
+
+ struct timespec ts;
+ clock_gettime(android_log_clockid(), &ts);
+
+ struct packet {
+ android_pmsg_log_header_t pmsg_header;
+ android_log_header_t header;
+ android_log_event_int_t payload;
+ };
+ char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD] __aligned(8);
+ memset(buf, 0, sizeof(buf));
+ struct packet *buffer = (struct packet*)(((uintptr_t)buf + 7) & ~7);
+ if (((uintptr_t)&buffer->pmsg_header) & 7) {
+ fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters);
+ }
+
+ buffer->pmsg_header.magic = LOGGER_MAGIC;
+ buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t)
+ + sizeof(android_log_header_t);
+ buffer->pmsg_header.uid = getuid();
+ buffer->pmsg_header.pid = getpid();
+
+ buffer->header.tid = gettid();
+ buffer->header.realtime.tv_sec = ts.tv_sec;
+ buffer->header.realtime.tv_nsec = ts.tv_nsec;
+
+ buffer->header.id = LOG_ID_EVENTS;
+ buffer->payload.header.tag = 0;
+ buffer->payload.payload.type = EVENT_TYPE_INT;
+ uint32_t snapshot = 0;
+ buffer->payload.payload.data = htole32(snapshot);
+
+ StartBenchmarkTiming();
+ for (int i = 0; i < iters; ++i) {
+ ++snapshot;
+ buffer->payload.payload.data = htole32(snapshot);
+ write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD);
+ }
+ StopBenchmarkTiming();
+ close(pstore_fd);
+}
+BENCHMARK(BM_pmsg_long_aligned);
+
+/*
+ * Measure the time it takes to submit the android logging data to pstore
+ * best case aligned single block.
+ */
+static void BM_pmsg_long_unaligned1(int iters) {
+
+ int pstore_fd = TEMP_FAILURE_RETRY(open("/dev/pmsg0", O_WRONLY));
+ if (pstore_fd < 0) {
+ return;
+ }
+
+ /*
+ * struct {
+ * // what we provide to pstore
+ * android_pmsg_log_header_t pmsg_header;
+ * // what we provide to socket
+ * android_log_header_t header;
+ * // caller provides
+ * union {
+ * struct {
+ * char prio;
+ * char payload[];
+ * } string;
+ * struct {
+ * uint32_t tag
+ * char payload[];
+ * } binary;
+ * };
+ * };
+ */
+
+ struct timespec ts;
+ clock_gettime(android_log_clockid(), &ts);
+
+ struct packet {
+ android_pmsg_log_header_t pmsg_header;
+ android_log_header_t header;
+ android_log_event_int_t payload;
+ };
+ char buf[sizeof(struct packet) + 8 + LOGGER_ENTRY_MAX_PAYLOAD] __aligned(8);
+ memset(buf, 0, sizeof(buf));
+ struct packet *buffer = (struct packet*)((((uintptr_t)buf + 7) & ~7) + 1);
+ if ((((uintptr_t)&buffer->pmsg_header) & 7) != 1) {
+ fprintf (stderr, "&buffer=0x%p iters=%d\n", &buffer->pmsg_header, iters);
+ }
+
+ buffer->pmsg_header.magic = LOGGER_MAGIC;
+ buffer->pmsg_header.len = sizeof(android_pmsg_log_header_t)
+ + sizeof(android_log_header_t);
+ buffer->pmsg_header.uid = getuid();
+ buffer->pmsg_header.pid = getpid();
+
+ buffer->header.tid = gettid();
+ buffer->header.realtime.tv_sec = ts.tv_sec;
+ buffer->header.realtime.tv_nsec = ts.tv_nsec;
+
+ buffer->header.id = LOG_ID_EVENTS;
+ buffer->payload.header.tag = 0;
+ buffer->payload.payload.type = EVENT_TYPE_INT;
+ uint32_t snapshot = 0;
+ buffer->payload.payload.data = htole32(snapshot);
+
+ StartBenchmarkTiming();
+ for (int i = 0; i < iters; ++i) {
+ ++snapshot;
+ buffer->payload.payload.data = htole32(snapshot);
+ write(pstore_fd, &buffer->pmsg_header, LOGGER_ENTRY_MAX_PAYLOAD);
+ }
+ StopBenchmarkTiming();
+ close(pstore_fd);
+}
+BENCHMARK(BM_pmsg_long_unaligned1);
+
+/*
* Measure the time it takes to submit the android logging call using
* discrete acquisition under light load. Expect this to be a dozen or so
* syscall periods (40us).