liblog: Add cpu utilization test
- followup to measure CPU utilization in liblog to
ensure this issue gets caught before a regression
passes into the labs. Threshold for failure is 1%.
(cherry picked from commit edadb2e7196040dd476e86581dc1c8e26449c00d)
BUG: 12457855
Change-Id: I40568a72aeef2f554b19ad55f3dd3c02bc023f24
diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp
index 532dc45..9ae8f22 100644
--- a/liblog/tests/liblog_test.cpp
+++ b/liblog/tests/liblog_test.cpp
@@ -15,11 +15,27 @@
*/
#include <fcntl.h>
+#include <signal.h>
#include <gtest/gtest.h>
#include <log/log.h>
#include <log/logger.h>
#include <log/log_read.h>
+// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and
+// non-syscall libs. Since we are only using this in the emergency of
+// a signal to stuff a terminating code into the logs, we will spin rather
+// than try a usleep.
+#define LOG_FAILURE_RETRY(exp) ({ \
+ typeof (exp) _rc; \
+ do { \
+ _rc = (exp); \
+ } while (((_rc == -1) \
+ && ((errno == EINTR) \
+ || (errno == EAGAIN))) \
+ || (_rc == -EINTR) \
+ || (_rc == -EAGAIN)); \
+ _rc; })
+
TEST(liblog, __android_log_buf_print) {
ASSERT_LT(0, __android_log_buf_print(LOG_ID_RADIO, ANDROID_LOG_INFO,
"TEST__android_log_buf_print",
@@ -142,6 +158,146 @@
android_logger_list_close(logger_list);
}
+static unsigned signaled;
+log_time signal_time;
+
+static void caught_blocking(int signum)
+{
+ unsigned long long v = 0xDEADBEEFA55A0000ULL;
+
+ v += getpid() & 0xFFFF;
+
+ ++signaled;
+ if ((signal_time.tv_sec == 0) && (signal_time.tv_nsec == 0)) {
+ clock_gettime(CLOCK_MONOTONIC, &signal_time);
+ signal_time.tv_sec += 2;
+ }
+
+ LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v)));
+}
+
+// Fill in current process user and system time in 10ms increments
+static void get_ticks(unsigned long long *uticks, unsigned long long *sticks)
+{
+ *uticks = *sticks = 0;
+
+ pid_t pid = getpid();
+
+ char buffer[512];
+ snprintf(buffer, sizeof(buffer), "/proc/%u/stat", pid);
+
+ FILE *fp = fopen(buffer, "r");
+ if (!fp) {
+ return;
+ }
+
+ char *cp = fgets(buffer, sizeof(buffer), fp);
+ fclose(fp);
+ if (!cp) {
+ return;
+ }
+
+ pid_t d;
+ char s[sizeof(buffer)];
+ char c;
+ long long ll;
+ unsigned long long ull;
+
+ if (15 != sscanf(buffer,
+ "%d %s %c %lld %lld %lld %lld %lld %llu %llu %llu %llu %llu %llu %llu ",
+ &d, s, &c, &ll, &ll, &ll, &ll, &ll, &ull, &ull, &ull, &ull, &ull,
+ uticks, sticks)) {
+ *uticks = *sticks = 0;
+ }
+}
+
+TEST(liblog, android_logger_list_read__cpu) {
+ struct logger_list *logger_list;
+ unsigned long long v = 0xDEADBEEFA55A0000ULL;
+
+ pid_t pid = getpid();
+
+ v += pid & 0xFFFF;
+
+ ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open(
+ LOG_ID_EVENTS, O_RDONLY, 1000, pid)));
+
+ int count = 0;
+
+ int signals = 0;
+
+ unsigned long long uticks_start;
+ unsigned long long sticks_start;
+ get_ticks(&uticks_start, &sticks_start);
+
+ const unsigned alarm_time = 10;
+
+ memset(&signal_time, 0, sizeof(signal_time));
+
+ signal(SIGALRM, caught_blocking);
+ alarm(alarm_time);
+
+ signaled = 0;
+
+ do {
+ log_msg log_msg;
+ if (android_logger_list_read(logger_list, &log_msg) <= 0) {
+ break;
+ }
+
+ alarm(alarm_time);
+
+ ++count;
+
+ ASSERT_EQ(log_msg.entry.pid, pid);
+
+ if ((log_msg.entry.len != (4 + 1 + 8))
+ || (log_msg.id() != LOG_ID_EVENTS)) {
+ continue;
+ }
+
+ char *eventData = log_msg.msg();
+
+ if (eventData[4] != EVENT_TYPE_LONG) {
+ continue;
+ }
+
+ unsigned long long l = eventData[4 + 1 + 0] & 0xFF;
+ l |= (unsigned long long) (eventData[4 + 1 + 1] & 0xFF) << 8;
+ l |= (unsigned long long) (eventData[4 + 1 + 2] & 0xFF) << 16;
+ l |= (unsigned long long) (eventData[4 + 1 + 3] & 0xFF) << 24;
+ l |= (unsigned long long) (eventData[4 + 1 + 4] & 0xFF) << 32;
+ l |= (unsigned long long) (eventData[4 + 1 + 5] & 0xFF) << 40;
+ l |= (unsigned long long) (eventData[4 + 1 + 6] & 0xFF) << 48;
+ l |= (unsigned long long) (eventData[4 + 1 + 7] & 0xFF) << 56;
+
+ if (l == v) {
+ ++signals;
+ break;
+ }
+ } while (!signaled || ({log_time t(CLOCK_MONOTONIC); t < signal_time;}));
+ alarm(0);
+ signal(SIGALRM, SIG_DFL);
+
+ ASSERT_LT(1, count);
+
+ ASSERT_EQ(1, signals);
+
+ android_logger_list_close(logger_list);
+
+ unsigned long long uticks_end;
+ unsigned long long sticks_end;
+ get_ticks(&uticks_end, &sticks_end);
+
+ // Less than 1% in either user or system time, or both
+ const unsigned long long one_percent_ticks = alarm_time;
+ unsigned long long user_ticks = uticks_end - uticks_start;
+ unsigned long long system_ticks = sticks_end - sticks_start;
+ ASSERT_GT(one_percent_ticks, user_ticks);
+ ASSERT_GT(one_percent_ticks, system_ticks);
+ ASSERT_GT(one_percent_ticks, user_ticks + system_ticks);
+}
+
TEST(liblog, android_logger_get_) {
struct logger_list * logger_list = android_logger_list_alloc(O_WRONLY, 0, 0);