liblog: __android_log_is_loggable support global properties

- Add support for "log.tag" and "persist.log.tag" global
  logging properties, effectively a runtime default minimum
  logging level.
- Add a thread-safe single level cache plus selective logic for the
  four properties being checked to help speed up logging decision
  on subsequent identical calls.
- Using new __system_property_area_serial() to make for
  efficient (<100ns) handling of cache misses. Despite adding
  two new properties, we are 8 times faster on subsequent calls
  even if the properties do not exist.
- A NULL or blank tag is no longer directed to return default,
  it will check the pair of global logging properties first.
- Add liblog.is_loggable gTest
- Fixup liblog.android_logger_get_, allow no content in crash buffer
- Fixup liblog.max_payload, lowered logd priority increases latency

Bug: 19544788
Bug: 21696721
Change-Id: Ideb887755aa3f1fd14a2603bda1fe23cba49642c
This commit is contained in:
Mark Salyzyn 2015-03-12 15:46:29 -07:00
parent 57bd480c3b
commit c158456f50
3 changed files with 335 additions and 24 deletions

View File

@ -15,41 +15,158 @@
*/
#include <ctype.h>
#include <pthread.h>
#include <stdlib.h>
#include <string.h>
#include <sys/system_properties.h>
#define _REALLY_INCLUDE_SYS__SYSTEM_PROPERTIES_H_
#include <sys/_system_properties.h>
#include <android/log.h>
static int __android_log_level(const char *tag, int def)
struct cache {
const prop_info *pinfo;
uint32_t serial;
char c;
};
static void refresh_cache(struct cache *cache, const char *key)
{
uint32_t serial;
char buf[PROP_VALUE_MAX];
if (!tag || !*tag) {
return def;
if (!cache->pinfo) {
cache->pinfo = __system_property_find(key);
if (!cache->pinfo) {
return;
}
}
{
static const char log_namespace[] = "persist.log.tag.";
char key[sizeof(log_namespace) + strlen(tag)];
serial = __system_property_serial(cache->pinfo);
if (serial == cache->serial) {
return;
}
cache->serial = serial;
__system_property_read(cache->pinfo, 0, buf);
cache->c = buf[0];
}
strcpy(key, log_namespace);
static pthread_mutex_t lock = PTHREAD_MUTEX_INITIALIZER;
static int __android_log_level(const char *tag, int def)
{
/* sizeof() is used on this array below */
static const char log_namespace[] = "persist.log.tag.";
static const size_t base_offset = 8; /* skip "persist." */
/* 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 *kp;
size_t i;
char c = 0;
/*
* Single layer cache of four properties. Priorities are:
* log.tag.<tag>
* persist.log.tag.<tag>
* log.tag
* persist.log.tag
* Where the missing tag matches all tags and becomes the
* system global default. We do not support ro.log.tag* .
*/
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 }
};
strcpy(key, log_namespace);
pthread_mutex_lock(&lock);
current_global_serial = __system_property_area_serial();
if (taglen) {
uint32_t current_local_serial = current_global_serial;
if (!last_tag || strcmp(last_tag, tag)) {
/* 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;
}
if (!last_tag) {
last_tag = strdup(tag);
}
strcpy(key + sizeof(log_namespace) - 1, tag);
if (__system_property_get(key + 8, buf) <= 0) {
buf[0] = '\0';
}
if (!buf[0] && __system_property_get(key, buf) <= 0) {
buf[0] = '\0';
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);
}
if (tag_cache[i].c) {
c = tag_cache[i].c;
break;
}
kp = key + base_offset;
}
}
switch (toupper(buf[0])) {
case 'V': return ANDROID_LOG_VERBOSE;
case 'D': return ANDROID_LOG_DEBUG;
case 'I': return ANDROID_LOG_INFO;
case 'W': return ANDROID_LOG_WARN;
case 'E': return ANDROID_LOG_ERROR;
case 'F': /* FALLTHRU */ /* Not officially supported */
case 'A': return ANDROID_LOG_FATAL;
case 'S': return -1; /* ANDROID_LOG_SUPPRESS */
switch (toupper(c)) { /* if invalid, resort to global */
case 'V':
case 'D':
case 'I':
case 'W':
case 'E':
case 'F': /* Not officially supported */
case 'A':
case 'S':
break;
default:
/* clear '.' after log.tag */
key[sizeof(log_namespace) - 2] = '\0';
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);
}
if (global_cache[i].c) {
c = global_cache[i].c;
break;
}
kp = key + base_offset;
}
break;
}
global_serial = current_global_serial;
pthread_mutex_unlock(&lock);
switch (toupper(c)) {
case 'V': return ANDROID_LOG_VERBOSE;
case 'D': return ANDROID_LOG_DEBUG;
case 'I': return ANDROID_LOG_INFO;
case 'W': return ANDROID_LOG_WARN;
case 'E': return ANDROID_LOG_ERROR;
case 'F': /* FALLTHRU */ /* Not officially supported */
case 'A': return ANDROID_LOG_FATAL;
case 'S': return -1; /* ANDROID_LOG_SUPPRESS */
}
return def;
}

View File

@ -77,6 +77,6 @@ include $(CLEAR_VARS)
LOCAL_MODULE := $(test_module_prefix)unit-tests
LOCAL_MODULE_TAGS := $(test_tags)
LOCAL_CFLAGS += $(test_c_flags)
LOCAL_SHARED_LIBRARIES := liblog
LOCAL_SHARED_LIBRARIES := liblog libcutils
LOCAL_SRC_FILES := $(test_src_files)
include $(BUILD_NATIVE_TEST)

View File

@ -17,6 +17,8 @@
#include <fcntl.h>
#include <inttypes.h>
#include <signal.h>
#include <cutils/properties.h>
#include <gtest/gtest.h>
#include <log/log.h>
#include <log/logger.h>
@ -439,6 +441,7 @@ TEST(liblog, max_payload) {
LOG_FAILURE_RETRY(__android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO,
tag, max_payload_buf));
sleep(2);
struct logger_list *logger_list;
@ -603,10 +606,14 @@ TEST(liblog, android_logger_get_) {
if (id != android_name_to_log_id(name)) {
continue;
}
fprintf(stderr, "log buffer %s\r", name);
struct logger * logger;
EXPECT_TRUE(NULL != (logger = android_logger_open(logger_list, id)));
EXPECT_EQ(id, android_logger_get_id(logger));
EXPECT_LT(0, android_logger_get_log_size(logger));
/* crash buffer is allowed to be empty, that is actually healthy! */
if (android_logger_get_log_size(logger) || strcmp("crash", name)) {
EXPECT_LT(0, android_logger_get_log_size(logger));
}
EXPECT_LT(0, android_logger_get_log_readable_size(logger));
EXPECT_LT(0, android_logger_get_log_version(logger));
}
@ -682,3 +689,190 @@ TEST(liblog, filterRule) {
android_log_format_free(p_format);
}
TEST(liblog, is_loggable) {
static const char tag[] = "is_loggable";
static const char log_namespace[] = "persist.log.tag.";
static const size_t base_offset = 8; /* skip "persist." */
// sizeof("string") = strlen("string") + 1
char key[sizeof(log_namespace) + sizeof(tag) - 1];
char hold[4][PROP_VALUE_MAX];
static const struct {
int level;
char type;
} levels[] = {
{ ANDROID_LOG_VERBOSE, 'v' },
{ ANDROID_LOG_DEBUG , 'd' },
{ ANDROID_LOG_INFO , 'i' },
{ ANDROID_LOG_WARN , 'w' },
{ ANDROID_LOG_ERROR , 'e' },
{ ANDROID_LOG_FATAL , 'a' },
{ -1 , 's' },
{ -2 , 'g' }, // Illegal value, resort to default
};
// Set up initial test condition
memset(hold, 0, sizeof(hold));
snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
property_get(key, hold[0], "");
property_set(key, "");
property_get(key + base_offset, hold[1], "");
property_set(key + base_offset, "");
strcpy(key, log_namespace);
key[sizeof(log_namespace) - 2] = '\0';
property_get(key, hold[2], "");
property_set(key, "");
property_get(key, hold[3], "");
property_set(key + base_offset, "");
// All combinations of level and defaults
for(size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
if (levels[i].level == -2) {
continue;
}
for(size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
if (levels[j].level == -2) {
continue;
}
fprintf(stderr, "i=%zu j=%zu\r", i, j);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
levels[j].level));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
levels[j].level));
}
}
}
// All combinations of level and tag and global properties
for(size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
if (levels[i].level == -2) {
continue;
}
for(size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
char buf[2];
buf[0] = levels[j].type;
buf[1] = '\0';
snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
i, j, key, buf);
property_set(key, buf);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)
|| ((levels[i].level < ANDROID_LOG_DEBUG)
&& (levels[j].level == -2))) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
}
property_set(key, "");
fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
i, j, key + base_offset, buf);
property_set(key + base_offset, buf);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)
|| ((levels[i].level < ANDROID_LOG_DEBUG)
&& (levels[j].level == -2))) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
}
property_set(key + base_offset, "");
strcpy(key, log_namespace);
key[sizeof(log_namespace) - 2] = '\0';
fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
i, j, key, buf);
property_set(key, buf);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)
|| ((levels[i].level < ANDROID_LOG_DEBUG)
&& (levels[j].level == -2))) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
}
property_set(key, "");
fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
i, j, key + base_offset, buf);
property_set(key + base_offset, buf);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)
|| ((levels[i].level < ANDROID_LOG_DEBUG)
&& (levels[j].level == -2))) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
}
property_set(key + base_offset, "");
}
}
// All combinations of level and tag properties, but with global set to INFO
strcpy(key, log_namespace);
key[sizeof(log_namespace) - 2] = '\0';
property_set(key, "I");
snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
for(size_t i = 0; i < (sizeof(levels) / sizeof(levels[0])); ++i) {
if (levels[i].level == -2) {
continue;
}
for(size_t j = 0; j < (sizeof(levels) / sizeof(levels[0])); ++j) {
char buf[2];
buf[0] = levels[j].type;
buf[1] = '\0';
fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
i, j, key, buf);
property_set(key, buf);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)
|| ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
&& (levels[j].level == -2))) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
}
property_set(key, "");
fprintf(stderr, "i=%zu j=%zu property_set(\"%s\",\"%s\")\r",
i, j, key + base_offset, buf);
property_set(key + base_offset, buf);
if ((levels[i].level < levels[j].level)
|| (levels[j].level == -1)
|| ((levels[i].level < ANDROID_LOG_INFO) // Yes INFO
&& (levels[j].level == -2))) {
EXPECT_FALSE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
} else {
EXPECT_TRUE(__android_log_is_loggable(levels[i].level, tag,
ANDROID_LOG_DEBUG));
}
property_set(key + base_offset, "");
}
}
// reset parms
snprintf(key, sizeof(key), "%s%s", log_namespace, tag);
property_set(key, hold[0]);
property_set(key + base_offset, hold[1]);
strcpy(key, log_namespace);
key[sizeof(log_namespace) - 2] = '\0';
property_set(key, hold[2]);
property_set(key + base_offset, hold[3]);
}