diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp index b5946344e..9f29a09c9 100644 --- a/liblog/tests/liblog_benchmark.cpp +++ b/liblog/tests/liblog_benchmark.cpp @@ -14,11 +14,17 @@ * limitations under the License. */ +#include +#include #include +#include +#include + #include #include #include #include +#include #include "benchmark.h" @@ -84,6 +90,380 @@ static void BM_clock_overhead(int iters) { } 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