logd: Add logd_test (d3ba6650) · Commits · e / os / android_system_core

logd/Android.mk

+2 −0

Original line number	Diff line number	Diff line
		@@ -28,3 +28,5 @@ LOCAL_SHARED_LIBRARIES := \
		LOCAL_MODULE_TAGS := optional

		include $(BUILD_EXECUTABLE)

		include $(call first-makefiles-under,$(LOCAL_PATH))

logd/tests/Android.mk

0 → 100644

+53 −0

Original line number	Diff line number	Diff line
		#
		# Copyright (C) 2014 The Android Open Source Project
		#
		# Licensed under the Apache License, Version 2.0 (the "License");
		# you may not use this file except in compliance with the License.
		# You may obtain a copy of the License at
		#
		# http://www.apache.org/licenses/LICENSE-2.0
		#
		# Unless required by applicable law or agreed to in writing, software
		# distributed under the License is distributed on an "AS IS" BASIS,
		# WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
		# See the License for the specific language governing permissions and
		# limitations under the License.
		#

		LOCAL_PATH := $(call my-dir)

		# -----------------------------------------------------------------------------
		# Benchmarks. (see ../../liblog/tests)
		# -----------------------------------------------------------------------------

		test_module_prefix := logd-
		test_tags := tests

		# -----------------------------------------------------------------------------
		# Unit tests.
		# -----------------------------------------------------------------------------

		test_c_flags := \
		-fstack-protector-all \
		-g \
		-Wall -Wextra \
		-Werror \
		-fno-builtin \

		ifeq ($(TARGET_USES_LOGD),true)
		test_c_flags += -DTARGET_USES_LOGD=1
		endif

		test_src_files := \
		logd_test.cpp

		# Build tests for the logger. Run with:
		# adb shell /data/nativetest/logd-unit-tests/logd-unit-tests
		include $(CLEAR_VARS)
		LOCAL_MODULE := $(test_module_prefix)unit-tests
		LOCAL_MODULE_TAGS := $(test_tags)
		LOCAL_ADDITIONAL_DEPENDENCIES := $(LOCAL_PATH)/Android.mk
		LOCAL_CFLAGS += $(test_c_flags)
		LOCAL_SHARED_LIBRARIES := libcutils
		LOCAL_SRC_FILES := $(test_src_files)
		include $(BUILD_NATIVE_TEST)

logd/tests/logd_test.cpp

0 → 100644

+611 −0

Original line number	Diff line number	Diff line
		/*
		* Copyright (C) 2014 The Android Open Source Project
		*
		* Licensed under the Apache License, Version 2.0 (the "License");
		* you may not use this file except in compliance with the License.
		* You may obtain a copy of the License at
		*
		* http://www.apache.org/licenses/LICENSE-2.0
		*
		* Unless required by applicable law or agreed to in writing, software
		* distributed under the License is distributed on an "AS IS" BASIS,
		* WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
		* See the License for the specific language governing permissions and
		* limitations under the License.
		*/

		#include <fcntl.h>
		#include <signal.h>
		#include <stdio.h>
		#include <string.h>

		#include <gtest/gtest.h>

		#include "cutils/sockets.h"
		#include "log/logger.h"

		#define __unused __attribute__((__unused__))

		/*
		* returns statistics
		*/
		static void my_android_logger_get_statistics(char *buf, size_t len)
		{
		snprintf(buf, len, "getStatistics 0 1 2 3");
		int sock = socket_local_client("logd",
		ANDROID_SOCKET_NAMESPACE_RESERVED,
		SOCK_STREAM);
		if (sock >= 0) {
		if (write(sock, buf, strlen(buf) + 1) > 0) {
		read(sock, buf, len);
		}
		close(sock);
		}
		}

		static void alloc_statistics(char *buffer, size_t length)
		{
		size_t len = 8192;
		char *buf;

		for(int retry = 32; (retry >= 0); delete [] buf, --retry) {
		buf = new char [len];
		my_android_logger_get_statistics(buf, len);

		buf[len-1] = '\0';
		size_t ret = atol(buf) + 1;
		if (ret < 4) {
		delete [] buf;
		buf = NULL;
		break;
		}
		bool check = ret <= len;
		len = ret;
		if (check) {
		break;
		}
		len += len / 8; // allow for some slop
		}
		*buffer = buf;
		*length = len;
		}

		static char find_benchmark_spam(char cp)
		{
		// liblog_benchmarks has been run designed to SPAM. The signature of
		// a noisiest UID statistics is one of the following:
		//
		// main: UID/PID Total size/num Now UID/PID[?] Total
		// 0 7500306/304207 71608/3183 0/4225? 7454388/303656
		// -or-
		// 0/gone 7454388/303656
		//
		// basically if we see a large number of 0/????? entries
		unsigned long value;
		do {
		char *benchmark = strstr(cp, " 0/");
		char *benchmark_newline = strstr(cp, "\n0/");
		if (!benchmark) {
		benchmark = benchmark_newline;
		}
		if (benchmark_newline && (benchmark > benchmark_newline)) {
		benchmark = benchmark_newline;
		}
		cp = benchmark;
		if (!cp) {
		break;
		}
		cp += 3;
		while (isdigit(cp) \|\| (cp == 'g') \|\| (cp == 'o') \|\| (cp == 'n')) {
		++cp;
		}
		value = 0;
		// ###? or gone
		if ((cp == '?') \|\| (cp == 'e')) {
		while (*++cp == ' ');
		while (isdigit(*cp)) {
		value = value * 10ULL + *cp - '0';
		++cp;
		}
		}
		} while ((value < 900000ULL) && *cp);
		return cp;
		}

		TEST(logd, statistics) {
		size_t len;
		char *buf;

		alloc_statistics(&buf, &len);

		#ifdef TARGET_USES_LOGD
		ASSERT_TRUE(NULL != buf);
		#else
		if (!buf) {
		return;
		}
		#endif

		// remove trailing FF
		char *cp = buf + len - 1;
		*cp = '\0';
		bool truncated = *--cp != '\f';
		if (!truncated) {
		*cp = '\0';
		}

		// squash out the byte count
		cp = buf;
		if (!truncated) {
		while (isdigit(cp) \|\| (cp == '\n')) {
		++cp;
		}
		}

		fprintf(stderr, "%s", cp);

		EXPECT_LT((size_t)64, strlen(cp));

		EXPECT_EQ(0, truncated);

		#ifdef TARGET_USES_LOGD
		char *main_logs = strstr(cp, "\nmain:");
		EXPECT_TRUE(NULL != main_logs);

		char *radio_logs = strstr(cp, "\nradio:");
		EXPECT_TRUE(NULL != radio_logs);

		char *system_logs = strstr(cp, "\nsystem:");
		EXPECT_TRUE(NULL != system_logs);

		char *events_logs = strstr(cp, "\nevents:");
		EXPECT_TRUE(NULL != events_logs);
		#endif

		// Parse timing stats

		cp = strstr(cp, "Minimum time between log events per dgram_qlen:");

		char *log_events_per_span = cp;

		if (cp) {
		while (cp && (cp != '\n')) {
		++cp;
		}
		if (*cp == '\n') {
		++cp;
		}

		char *list_of_spans = cp;
		EXPECT_NE('\0', *list_of_spans);

		unsigned short number_of_buckets = 0;
		unsigned short *dgram_qlen = NULL;
		unsigned short bucket = 0;
		while (cp && (cp != '\n')) {
		bucket = 0;
		while (isdigit(*cp)) {
		bucket = bucket * 10 + *cp - '0';
		++cp;
		}
		while (*cp == ' ') {
		++cp;
		}
		if (!bucket) {
		break;
		}
		unsigned short *new_dgram_qlen = new unsigned short[number_of_buckets + 1];
		EXPECT_TRUE(new_dgram_qlen != NULL);
		if (dgram_qlen) {
		memcpy(new_dgram_qlen, dgram_qlen, sizeof(dgram_qlen) number_of_buckets);
		delete [] dgram_qlen;
		}

		dgram_qlen = new_dgram_qlen;
		dgram_qlen[number_of_buckets++] = bucket;
		}

		char *end_of_spans = cp;
		EXPECT_NE('\0', *end_of_spans);

		EXPECT_LT(5, number_of_buckets);

		unsigned long long *times = new unsigned long long [number_of_buckets];
		ASSERT_TRUE(times != NULL);

		memset(times, 0, sizeof(times) number_of_buckets);

		while (*cp == '\n') {
		++cp;
		}

		unsigned short number_of_values = 0;
		unsigned long long value;
		while (cp && (cp != '\n')) {
		EXPECT_GE(number_of_buckets, number_of_values);

		value = 0;
		while (isdigit(*cp)) {
		value = value * 10ULL + *cp - '0';
		++cp;
		}

		switch(*cp) {
		case ' ':
		case '\n':
		value *= 1000ULL;
		/* FALLTHRU */
		case 'm':
		value *= 1000ULL;
		/* FALLTHRU */
		case 'u':
		value *= 1000ULL;
		/* FALLTHRU */
		case 'n':
		default:
		break;
		}
		while (*++cp == ' ');

		if (!value) {
		break;
		}

		times[number_of_values] = value;
		++number_of_values;
		}

		#ifdef TARGET_USES_LOGD
		EXPECT_EQ(number_of_values, number_of_buckets);
		#endif

		FILE *fp;
		ASSERT_TRUE(NULL != (fp = fopen("/proc/sys/net/unix/max_dgram_qlen", "r")));

		unsigned max_dgram_qlen = 0;
		fscanf(fp, "%u", &max_dgram_qlen);

		fclose(fp);

		// Find launch point
		unsigned short launch = 0;
		unsigned long long total = 0;
		do {
		total += times[launch];
		} while (((++launch < number_of_buckets)
		&& ((total / launch) >= (times[launch] / 8ULL)))
		\|\| (launch == 1)); // too soon

		bool failure = number_of_buckets <= launch;
		if (!failure) {
		unsigned short l = launch;
		if (l >= number_of_buckets) {
		l = number_of_buckets - 1;
		}
		failure = max_dgram_qlen < dgram_qlen[l];
		}

		// We can get failure if at any time liblog_benchmarks has been run
		// because designed to overload /proc/sys/net/unix/max_dgram_qlen even
		// at excessive values like 20000. It does so to measure the raw processing
		// performance of logd.
		if (failure) {
		cp = find_benchmark_spam(cp);
		}

		if (cp) {
		// Fake a failure, but without the failure code
		if (number_of_buckets <= launch) {
		printf ("Expected: number_of_buckets > launch, actual: %u vs %u\n",
		number_of_buckets, launch);
		}
		if (launch >= number_of_buckets) {
		launch = number_of_buckets - 1;
		}
		if (max_dgram_qlen < dgram_qlen[launch]) {
		printf ("Expected: max_dgram_qlen >= dgram_qlen[%d],"
		" actual: %u vs %u\n",
		launch, max_dgram_qlen, dgram_qlen[launch]);
		}
		} else
		#ifndef TARGET_USES_LOGD
		if (total)
		#endif
		{
		EXPECT_GT(number_of_buckets, launch);
		if (launch >= number_of_buckets) {
		launch = number_of_buckets - 1;
		}
		EXPECT_GE(max_dgram_qlen, dgram_qlen[launch]);
		}

		delete [] dgram_qlen;
		delete [] times;
		}
		delete [] buf;
		}

		static void caught_signal(int signum __unused) { }

		static void dump_log_msg(const char *prefix,
		log_msg *msg, unsigned int version, int lid) {
		switch(msg->entry.hdr_size) {
		case 0:
		version = 1;
		break;

		case sizeof(msg->entry_v2):
		if (version == 0) {
		version = 2;
		}
		break;
		}

		fprintf(stderr, "%s: v%u[%u] ", prefix, version, msg->len());
		if (version != 1) {
		fprintf(stderr, "hdr_size=%u ", msg->entry.hdr_size);
		}
		fprintf(stderr, "pid=%u tid=%u %u.%09u ",
		msg->entry.pid, msg->entry.tid, msg->entry.sec, msg->entry.nsec);
		switch(version) {
		case 1:
		break;
		case 2:
		fprintf(stderr, "euid=%u ", msg->entry_v2.euid);
		break;
		case 3:
		default:
		lid = msg->entry.lid;
		break;
		}

		switch(lid) {
		case 0:
		fprintf(stderr, "lid=main ");
		break;
		case 1:
		fprintf(stderr, "lid=radio ");
		break;
		case 2:
		fprintf(stderr, "lid=events ");
		break;
		case 3:
		fprintf(stderr, "lid=system ");
		break;
		default:
		if (lid >= 0) {
		fprintf(stderr, "lid=%d ", lid);
		}
		}

		unsigned int len = msg->entry.len;
		fprintf(stderr, "msg[%u]={", len);
		unsigned char cp = reinterpret_cast<unsigned char >(msg->msg());
		while(len) {
		unsigned char *p = cp;
		while (p && (((' ' <= p) && (p < 0x7F)) \|\| (p == '\n'))) {
		++p;
		}
		if (((p - cp) > 3) && !*p && ((unsigned int)(p - cp) < len)) {
		fprintf(stderr, "\"");
		while (*cp) {
		fprintf(stderr, (cp != '\n') ? "%c" : "\\n", cp);
		++cp;
		--len;
		}
		fprintf(stderr, "\"");
		} else {
		fprintf(stderr, "%02x", *cp);
		}
		++cp;
		if (--len) {
		fprintf(stderr, ", ");
		}
		}
		fprintf(stderr, "}\n");
		}

		TEST(logd, both) {
		log_msg msg;

		// check if we can read any logs from logd
		bool user_logger_available = false;
		bool user_logger_content = false;

		int fd = socket_local_client("logdr",
		ANDROID_SOCKET_NAMESPACE_RESERVED,
		SOCK_SEQPACKET);
		if (fd >= 0) {
		struct sigaction ignore, old_sigaction;
		memset(&ignore, 0, sizeof(ignore));
		ignore.sa_handler = caught_signal;
		sigemptyset(&ignore.sa_mask);
		sigaction(SIGALRM, &ignore, &old_sigaction);
		unsigned int old_alarm = alarm(10);

		static const char ask[] = "dumpAndClose lids=0,1,2,3";
		user_logger_available = write(fd, ask, sizeof(ask)) == sizeof(ask);

		user_logger_content = recv(fd, msg.buf, sizeof(msg), 0) > 0;

		if (user_logger_content) {
		dump_log_msg("user", &msg, 3, -1);
		}

		alarm(0);
		sigaction(SIGALRM, &old_sigaction, NULL);

		close(fd);
		}

		// check if we can read any logs from kernel logger
		bool kernel_logger_available = false;
		bool kernel_logger_content = false;

		static const char *loggers[] = {
		"/dev/log/main", "/dev/log_main",
		"/dev/log/radio", "/dev/log_radio",
		"/dev/log/events", "/dev/log_events",
		"/dev/log/system", "/dev/log_system",
		};

		for (unsigned int i = 0; i < (sizeof(loggers) / sizeof(loggers[0])); ++i) {
		fd = open(loggers[i], O_RDONLY);
		if (fd < 0) {
		continue;
		}
		kernel_logger_available = true;
		fcntl(fd, F_SETFL, O_RDONLY \| O_NONBLOCK);
		int result = TEMP_FAILURE_RETRY(read(fd, msg.buf, sizeof(msg)));
		if (result > 0) {
		kernel_logger_content = true;
		dump_log_msg("kernel", &msg, 0, i / 2);
		}
		close(fd);
		}

		static const char yes[] = "\xE2\x9C\x93";
		static const char no[] = "\xE2\x9c\x98";
		fprintf(stderr,
		"LOGGER Available Content\n"
		"user %-13s%s\n"
		"kernel %-13s%s\n"
		" status %-11s%s\n",
		(user_logger_available) ? yes : no,
		(user_logger_content) ? yes : no,
		(kernel_logger_available) ? yes : no,
		(kernel_logger_content) ? yes : no,
		(user_logger_available && kernel_logger_available) ? "WARNING" : "ok",
		(user_logger_content && kernel_logger_content) ? "ERROR" : "ok");

		if (user_logger_available && kernel_logger_available) {
		printf("WARNING: kernel & user logger; both consuming resources!!!\n");
		}

		EXPECT_EQ(0, user_logger_content && kernel_logger_content);
		EXPECT_EQ(0, !user_logger_content && !kernel_logger_content);
		}

		// BAD ROBOT
		// Benchmark threshold are generally considered bad form unless there is
		// is some human love applied to the continued maintenance and whether the
		// thresholds are tuned on a per-target basis. Here we check if the values
		// are more than double what is expected. Doubling will not prevent failure
		// on busy or low-end systems that could have a tendency to stretch values.
		//
		// The primary goal of this test is to simulate a spammy app (benchmark
		// being the worst) and check to make sure the logger can deal with it
		// appropriately by checking all the statistics are in an expected range.
		//
		TEST(logd, benchmark) {
		size_t len;
		char *buf;

		alloc_statistics(&buf, &len);
		bool benchmark_already_run = buf && find_benchmark_spam(buf);
		delete [] buf;

		if (benchmark_already_run) {
		fprintf(stderr, "WARNING: spam already present and too much history\n"
		" false OK for prune by worst UID check\n");
		}

		FILE *fp;

		// Introduce some extreme spam for the worst UID filter
		ASSERT_TRUE(NULL != (fp = popen(
		"/data/nativetest/liblog-benchmarks/liblog-benchmarks",
		"r")));

		char buffer[5120];

		static const char *benchmarks[] = {
		"BM_log_maximum_retry ",
		"BM_log_maximum ",
		"BM_clock_overhead ",
		"BM_log_overhead ",
		"BM_log_latency ",
		"BM_log_delay "
		};
		static const unsigned int log_maximum_retry = 0;
		static const unsigned int log_maximum = 1;
		static const unsigned int clock_overhead = 2;
		static const unsigned int log_overhead = 3;
		static const unsigned int log_latency = 4;
		static const unsigned int log_delay = 5;

		unsigned long ns[sizeof(benchmarks) / sizeof(benchmarks[0])];

		memset(ns, 0, sizeof(ns));

		while (fgets(buffer, sizeof(buffer), fp)) {
		for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
		if (strncmp(benchmarks[i], buffer, strlen(benchmarks[i]))) {
		continue;
		}
		sscanf(buffer, "%*s %lu %lu", &ns[i], &ns[i]);
		fprintf(stderr, "%-22s%8lu\n", benchmarks[i], ns[i]);
		}
		}
		int ret = pclose(fp);

		if (!WIFEXITED(ret) \|\| (WEXITSTATUS(ret) == 127)) {
		fprintf(stderr,
		"WARNING: "
		"/data/nativetest/liblog-benchmarks/liblog-benchmarks missing\n"
		" can not perform test\n");
		return;
		}

		#ifdef TARGET_USES_LOGD
		EXPECT_GE(100000UL, ns[log_maximum_retry]); // 42777 user
		#else
		EXPECT_GE(10000UL, ns[log_maximum_retry]); // 5636 kernel
		#endif

		#ifdef TARGET_USES_LOGD
		EXPECT_GE(25000UL, ns[log_maximum]); // 14055 user
		#else
		EXPECT_GE(10000UL, ns[log_maximum]); // 5637 kernel
		#endif

		EXPECT_GE(4000UL, ns[clock_overhead]); // 2008

		#ifdef TARGET_USES_LOGD
		EXPECT_GE(250000UL, ns[log_overhead]); // 113219 user
		#else
		EXPECT_GE(100000UL, ns[log_overhead]); // 50945 kernel
		#endif

		#ifdef TARGET_USES_LOGD
		EXPECT_GE(7500UL, ns[log_latency]); // 3718 user space
		#else
		EXPECT_GE(500000UL, ns[log_latency]); // 254200 kernel
		#endif

		#ifdef TARGET_USES_LOGD
		EXPECT_GE(20000000UL, ns[log_delay]); // 9542541 user
		#else
		EXPECT_GE(55000UL, ns[log_delay]); // 27341 kernel
		#endif

		for (unsigned i = 0; i < sizeof(ns) / sizeof(ns[0]); ++i) {
		EXPECT_NE(0UL, ns[i]);
		}

		alloc_statistics(&buf, &len);

		#ifdef TARGET_USES_LOGD
		bool collected_statistics = !!buf;
		EXPECT_EQ(true, collected_statistics);
		#else
		if (!buf) {
		return;
		}
		#endif

		ASSERT_TRUE(NULL != buf);
		EXPECT_TRUE(find_benchmark_spam(buf) != NULL);

		delete [] buf;
		}