Merge "liblog: is loggable is flaky" am: 2427d34152 (02cb6d7c) · Commits · e / os / android_system_core

liblog/log_is_loggable.c

+173 −89

Original line number	Diff line number	Diff line
		@@ -25,13 +25,18 @@

		static pthread_mutex_t lock_loggable = PTHREAD_MUTEX_INITIALIZER;

		static void lock()
		static int lock()
		{
		/*
		* If we trigger a signal handler in the middle of locked activity and the
		* signal handler logs a message, we could get into a deadlock state.
		*/
		pthread_mutex_lock(&lock_loggable);
		/*
		* Any contention, and we can turn around and use the non-cached method
		* in less time than the system call associated with a mutex to deal with
		* the contention.
		*/
		return pthread_mutex_trylock(&lock_loggable);
		}

		static void unlock()
		@@ -45,6 +50,12 @@ struct cache {
		unsigned char c;
		};

		static int check_cache(struct cache *cache)
		{
		return cache->pinfo
		&& __system_property_serial(cache->pinfo) != cache->serial;
		}

		#define BOOLEAN_TRUE 0xFF
		#define BOOLEAN_FALSE 0xFE

		@@ -58,6 +69,7 @@ static void refresh_cache(struct cache cache, const char key)
		if (!cache->pinfo) {
		return;
		}
		cache->serial = -1;
		}
		serial = __system_property_serial(cache->pinfo);
		if (serial == cache->serial) {
		@@ -85,7 +97,7 @@ static int __android_log_level(const char *tag, int default_prio)
		/* calculate the size of our key temporary buffer */
		const size_t taglen = (tag && *tag) ? strlen(tag) : 0;
		/* sizeof(log_namespace) = strlen(log_namespace) + 1 */
		char key[sizeof(log_namespace) + taglen];
		char key[sizeof(log_namespace) + taglen]; /* may be > PROPERTY_KEY_MAX */
		char *kp;
		size_t i;
		char c = 0;
		@@ -101,48 +113,75 @@ static int __android_log_level(const char *tag, int default_prio)
		static char *last_tag;
		static uint32_t global_serial;
		uint32_t current_global_serial;
		static struct cache tag_cache[2] = {
		{ NULL, -1, 0 },
		{ NULL, -1, 0 }
		};
		static struct cache global_cache[2] = {
		{ NULL, -1, 0 },
		{ NULL, -1, 0 }
		};
		static struct cache tag_cache[2];
		static struct cache global_cache[2];
		int change_detected;
		int global_change_detected;
		int not_locked;

		strcpy(key, log_namespace);

		lock();
		global_change_detected = change_detected = not_locked = lock();

		if (!not_locked) {
		/*
		* check all known serial numbers to changes.
		*/
		for (i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) {
		if (check_cache(&tag_cache[i])) {
		change_detected = 1;
		}
		}
		for (i = 0; i < (sizeof(global_cache) / sizeof(global_cache[0])); ++i) {
		if (check_cache(&global_cache[i])) {
		global_change_detected = 1;
		}
		}

		current_global_serial = __system_property_area_serial();
		if (current_global_serial != global_serial) {
		change_detected = 1;
		global_change_detected = 1;
		}
		}

		if (taglen) {
		uint32_t current_local_serial = current_global_serial;

		if (!last_tag \|\| (last_tag[0] != tag[0]) \|\| strcmp(last_tag + 1, tag + 1)) {
		int local_change_detected = change_detected;
		if (!not_locked) {
		if (!last_tag
		\|\| (last_tag[0] != tag[0])
		\|\| strcmp(last_tag + 1, tag + 1)) {
		/* invalidate log.tag.<tag> cache */
		for (i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) {
		tag_cache[i].pinfo = NULL;
		tag_cache[i].serial = -1;
		tag_cache[i].c = '\0';
		}
		free(last_tag);
		last_tag = NULL;
		current_global_serial = -1;
		local_change_detected = 1;
		}
		if (!last_tag) {
		last_tag = strdup(tag);
		}
		}
		strcpy(key + sizeof(log_namespace) - 1, tag);

		kp = key;
		for (i = 0; i < (sizeof(tag_cache) / sizeof(tag_cache[0])); ++i) {
		if (current_local_serial != global_serial) {
		refresh_cache(&tag_cache[i], kp);
		struct cache *cache = &tag_cache[i];
		struct cache temp_cache;

		if (not_locked) {
		temp_cache.pinfo = NULL;
		temp_cache.c = '\0';
		cache = &temp_cache;
		}
		if (local_change_detected) {
		refresh_cache(cache, kp);
		}

		if (tag_cache[i].c) {
		c = tag_cache[i].c;
		if (cache->c) {
		c = cache->c;
		break;
		}

		@@ -167,12 +206,23 @@ static int __android_log_level(const char *tag, int default_prio)

		kp = key;
		for (i = 0; i < (sizeof(global_cache) / sizeof(global_cache[0])); ++i) {
		if (current_global_serial != global_serial) {
		refresh_cache(&global_cache[i], kp);
		struct cache *cache = &global_cache[i];
		struct cache temp_cache;

		if (not_locked) {
		temp_cache = *cache;
		if (temp_cache.pinfo != cache->pinfo) { /* check atomic */
		temp_cache.pinfo = NULL;
		temp_cache.c = '\0';
		}
		cache = &temp_cache;
		}
		if (global_change_detected) {
		refresh_cache(cache, kp);
		}

		if (global_cache[i].c) {
		c = global_cache[i].c;
		if (cache->c) {
		c = cache->c;
		break;
		}

		@@ -181,9 +231,10 @@ static int __android_log_level(const char *tag, int default_prio)
		break;
		}

		if (!not_locked) {
		global_serial = current_global_serial;

		unlock();
		}

		switch (toupper(c)) {
		case 'V': return ANDROID_LOG_VERBOSE;
		@@ -206,70 +257,103 @@ int __android_log_is_loggable(int prio, const char *tag, int default_prio)
		}

		/*
		* Timestamp state generally remains constant, since a change is
		* rare, we can accept a trylock failure gracefully. Use a separate
		* lock from is_loggable to keep contention down b/25563384.
		* For properties that are read often, but generally remain constant.
		* Since a change is rare, we will accept a trylock failure gracefully.
		* Use a separate lock from is_loggable to keep contention down b/25563384.
		*/
		static pthread_mutex_t lock_clockid = PTHREAD_MUTEX_INITIALIZER;
		struct cache2 {
		pthread_mutex_t lock;
		uint32_t serial;
		const char *key_persist;
		struct cache cache_persist;
		const char *key_ro;
		struct cache cache_ro;
		unsigned char (const evaluate)(const struct cache2 self);
		};

		clockid_t android_log_clockid()
		static inline unsigned char do_cache2(struct cache2 *self)
		{
		static struct cache r_time_cache = { NULL, -1, 0 };
		static struct cache p_time_cache = { NULL, -1, 0 };
		char c;
		uint32_t current_serial;
		int change_detected;
		unsigned char c;

		if (pthread_mutex_trylock(&lock_clockid)) {
		if (pthread_mutex_trylock(&self->lock)) {
		/* We are willing to accept some race in this context */
		if (!(c = p_time_cache.c)) {
		c = r_time_cache.c;
		return self->evaluate(self);
		}
		} else {
		static uint32_t serial;
		uint32_t current_serial = __system_property_area_serial();
		if (current_serial != serial) {
		refresh_cache(&r_time_cache, "ro.logd.timestamp");
		refresh_cache(&p_time_cache, "persist.logd.timestamp");
		serial = current_serial;

		change_detected = check_cache(&self->cache_persist)
		\|\| check_cache(&self->cache_ro);
		current_serial = __system_property_area_serial();
		if (current_serial != self->serial) {
		change_detected = 1;
		}
		if (!(c = p_time_cache.c)) {
		c = r_time_cache.c;
		if (change_detected) {
		refresh_cache(&self->cache_persist, self->key_persist);
		refresh_cache(&self->cache_ro, self->key_ro);
		self->serial = current_serial;
		}
		c = self->evaluate(self);

		pthread_mutex_unlock(&lock_clockid);
		pthread_mutex_unlock(&self->lock);

		return c;
		}

		static unsigned char evaluate_persist_ro(const struct cache2 *self)
		{
		unsigned char c = self->cache_persist.c;

		if (c) {
		return c;
		}

		return (tolower(c) == 'm') ? CLOCK_MONOTONIC : CLOCK_REALTIME;
		return self->cache_ro.c;
		}

		/*
		* security state generally remains constant, since a change is
		* rare, we can accept a trylock failure gracefully.
		* Timestamp state generally remains constant, but can change at any time
		* to handle developer requirements.
		*/
		static pthread_mutex_t lock_security = PTHREAD_MUTEX_INITIALIZER;

		int __android_log_security()
		clockid_t android_log_clockid()
		{
		static struct cache r_do_cache = { NULL, -1, BOOLEAN_FALSE };
		static struct cache p_security_cache = { NULL, -1, BOOLEAN_FALSE };
		int retval;
		static struct cache2 clockid = {
		PTHREAD_MUTEX_INITIALIZER,
		0,
		"persist.logd.timestamp",
		{ NULL, -1, '\0' },
		"ro.logd.timestamp",
		{ NULL, -1, '\0' },
		evaluate_persist_ro
		};

		if (pthread_mutex_trylock(&lock_security)) {
		/* We are willing to accept some race in this context */
		retval = (r_do_cache.c != BOOLEAN_FALSE) && r_do_cache.c &&
		(p_security_cache.c == BOOLEAN_TRUE);
		} else {
		static uint32_t serial;
		uint32_t current_serial = __system_property_area_serial();
		if (current_serial != serial) {
		refresh_cache(&r_do_cache, "ro.device_owner");
		refresh_cache(&p_security_cache, "persist.logd.security");
		serial = current_serial;
		return (tolower(do_cache2(&clockid)) == 'm')
		? CLOCK_MONOTONIC
		: CLOCK_REALTIME;
		}
		retval = (r_do_cache.c != BOOLEAN_FALSE) && r_do_cache.c &&
		(p_security_cache.c == BOOLEAN_TRUE);

		pthread_mutex_unlock(&lock_security);
		/*
		* Security state generally remains constant, but the DO must be able
		* to turn off logging should it become spammy after an attack is detected.
		*/
		static unsigned char evaluate_security(const struct cache2 *self)
		{
		unsigned char c = self->cache_ro.c;

		return (c != BOOLEAN_FALSE) && c && (self->cache_persist.c == BOOLEAN_TRUE);
		}

		return retval;
		int __android_log_security()
		{
		static struct cache2 security = {
		PTHREAD_MUTEX_INITIALIZER,
		0,
		"persist.logd.security",
		{ NULL, -1, BOOLEAN_FALSE },
		"ro.device_owner",
		{ NULL, -1, BOOLEAN_FALSE },
		evaluate_security
		};

		return do_cache2(&security);
		}

liblog/tests/liblog_benchmark.cpp

+28 −0

Original line number	Diff line number	Diff line
		@@ -660,3 +660,31 @@ static void BM_is_loggable(int iters) {
		StopBenchmarkTiming();
		}
		BENCHMARK(BM_is_loggable);

		/*
		* Measure the time it takes for android_log_clockid.
		*/
		static void BM_clockid(int iters) {
		StartBenchmarkTiming();

		for (int i = 0; i < iters; ++i) {
		android_log_clockid();
		}

		StopBenchmarkTiming();
		}
		BENCHMARK(BM_clockid);

		/*
		* Measure the time it takes for __android_log_security.
		*/
		static void BM_security(int iters) {
		StartBenchmarkTiming();

		for (int i = 0; i < iters; ++i) {
		__android_log_security();
		}

		StopBenchmarkTiming();
		}
		BENCHMARK(BM_security);