diff options
author | Mark Salyzyn <salyzyn@google.com> | 2014-01-28 21:09:37 +0000 |
---|---|---|
committer | Gerrit Code Review <noreply-gerritcodereview@google.com> | 2014-01-28 21:09:37 +0000 |
commit | d2acdd82e613b3e1d79a00943ac3bf5fbc14a766 (patch) | |
tree | d7f0ff36ad86281f3fa4eb36978658711e7c2296 /liblog | |
parent | 12db3eb6db3b80011043e404530012612a1d0fbf (diff) | |
parent | 44b99c22af84331068935a9bc3e807165a88237c (diff) | |
download | system_core-d2acdd82e613b3e1d79a00943ac3bf5fbc14a766.zip system_core-d2acdd82e613b3e1d79a00943ac3bf5fbc14a766.tar.gz system_core-d2acdd82e613b3e1d79a00943ac3bf5fbc14a766.tar.bz2 |
Merge changes I70ab37d5,I716f89c0,I34c96adf,I77650923,I35b0d1ee, ...
* changes:
libsysutils: SocketListener export release
libsysutils: Add iovec/runOnEachSocket
liblog: support struct logger_event_v2 format
liblog: update timestamp on NOTICE file
libcutils: resolve warning in iosched_policy.c
liblog: Add const pedantics
logcat: Add -T flag (-t w/o assumption of -d)
logcat: Add logcat test suite
liblog: Add cpu utilization test
liblog: Add liblog test suite
debuggerd: Support newline split in log messages
liblog: deprecate export LOGGER ioctl definitions
liblog: deprecate export of LOGGER_LOG_* defines
liblog: Add README
liblog: resolve build warning messages
liblog: high CPU usage from logcat
liblog: fix build again
liblog: drop use of sys/cdefs.h
liblog: git_master@964770 build problem
logcat: Incorporate liblog reading API
debuggerd: Incorporate liblog reading API
liblog: Interface to support abstracting log read
adb: deprecate legacy log service interface
adb: regression from Move list.c to inlines
liblog: whitespace cleanup
libcutils: bug str_parms.c:str_parms_get_float().
libcutils: UNUSED argument warnings
libsysutils: Get rid of warnings
libcutils: Move list.c to inlines on list.h
Diffstat (limited to 'liblog')
-rw-r--r-- | liblog/Android.mk | 9 | ||||
-rw-r--r-- | liblog/NOTICE | 2 | ||||
-rw-r--r-- | liblog/README | 134 | ||||
-rw-r--r-- | liblog/fake_log_device.c | 10 | ||||
-rw-r--r-- | liblog/log_read.c | 665 | ||||
-rw-r--r-- | liblog/logd_write.c | 11 | ||||
-rw-r--r-- | liblog/logprint.c | 23 | ||||
-rw-r--r-- | liblog/tests/Android.mk | 77 | ||||
-rw-r--r-- | liblog/tests/benchmark.h | 147 | ||||
-rw-r--r-- | liblog/tests/benchmark_main.cpp | 245 | ||||
-rw-r--r-- | liblog/tests/liblog_benchmark.cpp | 268 | ||||
-rw-r--r-- | liblog/tests/liblog_test.cpp | 319 | ||||
-rw-r--r-- | liblog/uio.c | 10 |
13 files changed, 1895 insertions, 25 deletions
diff --git a/liblog/Android.mk b/liblog/Android.mk index 6bfb119..0d6c970 100644 --- a/liblog/Android.mk +++ b/liblog/Android.mk @@ -1,5 +1,5 @@ # -# Copyright (C) 2008 The Android Open Source Project +# Copyright (C) 2008-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. @@ -42,7 +42,7 @@ else endif liblog_host_sources := $(liblog_sources) fake_log_device.c - +liblog_target_sources = $(liblog_sources) log_read.c # Shared and static library for host # ======================================================== @@ -67,15 +67,16 @@ LOCAL_LDLIBS := -lpthread LOCAL_CFLAGS := -DFAKE_LOG_DEVICE=1 -m64 include $(BUILD_HOST_STATIC_LIBRARY) - # Shared and static library for target # ======================================================== include $(CLEAR_VARS) LOCAL_MODULE := liblog -LOCAL_SRC_FILES := $(liblog_sources) +LOCAL_SRC_FILES := $(liblog_target_sources) include $(BUILD_STATIC_LIBRARY) include $(CLEAR_VARS) LOCAL_MODULE := liblog LOCAL_WHOLE_STATIC_LIBRARIES := liblog include $(BUILD_SHARED_LIBRARY) + +include $(call first-makefiles-under,$(LOCAL_PATH)) diff --git a/liblog/NOTICE b/liblog/NOTICE index c5b1efa..06a9081 100644 --- a/liblog/NOTICE +++ b/liblog/NOTICE @@ -1,5 +1,5 @@ - Copyright (c) 2005-2008, The Android Open Source Project + Copyright (c) 2005-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. diff --git a/liblog/README b/liblog/README new file mode 100644 index 0000000..d7472e4 --- /dev/null +++ b/liblog/README @@ -0,0 +1,134 @@ +LIBLOG(3) Android NDK Programming Manual LIBLOG(3) + + + +NAME + liblog - Android NDK logger interfaces + +SYNOPSIS + #include <log/log.h> + + ALOG(android_priority, tag, format, ...) + IF_ALOG(android_priority, tag) + LOG_PRI(priority, tag, format, ...) + LOG_PRI_VA(priority, tag, format, args) + #define LOG_TAG NULL + ALOGV(format, ...) + SLOGV(format, ...) + RLOGV(format, ...) + ALOGV_IF(cond, format, ...) + SLOGV_IF(cond, format, ...) + RLOGV_IF(cond, format, ...) + IF_ALOGC() + ALOGD(format, ...) + SLOGD(format, ...) + RLOGD(format, ...) + ALOGD_IF(cond, format, ...) + SLOGD_IF(cond, format, ...) + RLOGD_IF(cond, format, ...) + IF_ALOGD() + ALOGI(format, ...) + SLOGI(format, ...) + RLOGI(format, ...) + ALOGI_IF(cond, format, ...) + SLOGI_IF(cond, format, ...) + RLOGI_IF(cond, format, ...) + IF_ALOGI() + ALOGW(format, ...) + SLOGW(format, ...) + RLOGW(format, ...) + ALOGW_IF(cond, format, ...) + SLOGW_IF(cond, format, ...) + RLOGW_IF(cond, format, ...) + IF_ALOGW() + ALOGE(format, ...) + SLOGE(format, ...) + RLOGE(format, ...) + ALOGE_IF(cond, format, ...) + SLOGE_IF(cond, format, ...) + RLOGE_IF(cond, format, ...) + IF_ALOGE() + LOG_FATAL(format, ...) + LOG_ALWAYS_FATAL(format, ...) + LOG_FATAL_IF(cond, format, ...) + LOG_ALWAYS_FATAL_IF(cond, format, ...) + ALOG_ASSERT(cond, format, ...) + LOG_EVENT_INT(tag, value) + LOG_EVENT_LONG(tag, value) + + Link with -llog + + #include <log/logger.h> + + log_id_t android_logger_get_id(struct logger *logger) + int android_logger_clear(struct logger *logger) + int android_logger_get_log_size(struct logger *logger) + int android_logger_get_log_readable_size(struct logger *logger) + int android_logger_get_log_version(struct logger *logger) + + struct logger_list *android_logger_list_alloc(int mode, unsigned int + tail, pid_t pid) + struct logger *android_logger_open(struct logger_list *logger_list, + log_id_t id) + struct logger_list *android_logger_list_open(log_id_t id, int mode, + unsigned int tail, pid_t pid) + + int android_logger_list_read(struct logger_list *logger_list, struct + log_msg *log_msg + + void android_logger_list_free(struct logger_list *logger_list) + + log_id_t android_name_to_log_id(const char *logName) + const char *android_log_id_to_name(log_id_t log_id) + + Link with -llog + +DESCRIPTION + liblog represents an interface to the volatile Android Logging system + for NDK (Native) applications and libraries. Interfaces for either + writing or reading logs. The log buffers are divided up in Main, Sys‐ + tem, Radio and Events sub-logs. + + The logging interfaces are a series of macros, all of which can be + overridden individually in order to control the verbosity of the appli‐ + cation or library. [ASR]LOG[VDIWE] calls are used to log to BAsic, + System or Radio sub-logs in either the Verbose, Debug, Info, Warning or + Error priorities. [ASR]LOG[VDIWE]_IF calls are used to perform thus + based on a condition being true. IF_ALOG[VDIWE] calls are true if the + current LOG_TAG is enabled at the specified priority. LOG_ALWAYS_FATAL + is used to ALOG a message, then kill the process. LOG_FATAL call is a + variant of LOG_ALWAYS_FATAL, only enabled in engineering, and not + release builds. ALOG_ASSERT is used to ALOG a message if the condition + is false; the condition is part of the logged message. + LOG_EVENT_(INT|LONG) is used to drop binary content into the Events + sub-log. + + The log reading interfaces permit opening the logs either singly or + multiply, retrieving a log entry at a time in time sorted order, + optionally limited to a specific pid and tail of the log(s) and finally + a call closing the logs. A single log can be opened with android_log‐ + ger_list_open; or multiple logs can be opened with android_log‐ + ger_list_alloc, calling in turn the android_logger_open for each log + id. Each entry can be retrieved with android_logger_list_read. The + log(s) can be closed with android_logger_list_free. The logs should be + opened with an O_RDONLY mode. O_NDELAY mode will report when the log + reading is done with an EAGAIN error return code, otherwise the + android_logger_list_read call will block for new entries. + + The value returned by android_logger_open can be used as a parameter to + the android_logger_clear function to empty the sub-log. It is recom‐ + mended to only open log O_WRONLY. + + The value returned by android_logger_open can be used as a parameter to + the android_logger_get_log_(size|readable_size|version) to retrieve the + sub-log maximum size, readable size and log buffer format protocol ver‐ + sion respectively. android_logger_get_id returns the id that was used + when opening the sub-log. It is recommended to open the log O_RDONLY + in these cases. + +SEE ALSO + syslogd(8) + + + + 17 Dec 2013 LIBLOG(3) diff --git a/liblog/fake_log_device.c b/liblog/fake_log_device.c index be34f01..da83a85 100644 --- a/liblog/fake_log_device.c +++ b/liblog/fake_log_device.c @@ -1,5 +1,5 @@ /* - * Copyright (C) 2008 The Android Open Source Project + * Copyright (C) 2008-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. @@ -322,11 +322,11 @@ static const char* getPriorityString(int priority) * Make up something to replace it. */ static ssize_t fake_writev(int fd, const struct iovec *iov, int iovcnt) { - int result = 0; - struct iovec* end = iov + iovcnt; + ssize_t result = 0; + const struct iovec* end = iov + iovcnt; for (; iov < end; iov++) { - int w = write(fd, iov->iov_base, iov->iov_len); - if (w != iov->iov_len) { + ssize_t w = write(fd, iov->iov_base, iov->iov_len); + if (w != (ssize_t) iov->iov_len) { if (w < 0) return w; return result + w; diff --git a/liblog/log_read.c b/liblog/log_read.c new file mode 100644 index 0000000..47aa711 --- /dev/null +++ b/liblog/log_read.c @@ -0,0 +1,665 @@ +/* +** Copyright 2013-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. +*/ + +#define _GNU_SOURCE /* asprintf for x86 host */ +#include <errno.h> +#include <fcntl.h> +#include <poll.h> +#include <string.h> +#include <stdio.h> +#include <stdlib.h> +#include <cutils/list.h> +#include <log/log.h> +#include <log/logger.h> + +#include <sys/ioctl.h> + +#define __LOGGERIO 0xAE + +#define LOGGER_GET_LOG_BUF_SIZE _IO(__LOGGERIO, 1) /* size of log */ +#define LOGGER_GET_LOG_LEN _IO(__LOGGERIO, 2) /* used log len */ +#define LOGGER_GET_NEXT_ENTRY_LEN _IO(__LOGGERIO, 3) /* next entry len */ +#define LOGGER_FLUSH_LOG _IO(__LOGGERIO, 4) /* flush log */ +#define LOGGER_GET_VERSION _IO(__LOGGERIO, 5) /* abi version */ +#define LOGGER_SET_VERSION _IO(__LOGGERIO, 6) /* abi version */ + +typedef char bool; +#define false (const bool)0 +#define true (const bool)1 + +#define LOG_FILE_DIR "/dev/log/" + +/* timeout in milliseconds */ +#define LOG_TIMEOUT_FLUSH 5 +#define LOG_TIMEOUT_NEVER -1 + +#define logger_for_each(logger, logger_list) \ + for (logger = node_to_item((logger_list)->node.next, struct logger, node); \ + logger != node_to_item(&(logger_list)->node, struct logger, node); \ + logger = node_to_item((logger)->node.next, struct logger, node)) + +/* In the future, we would like to make this list extensible */ +static const char *LOG_NAME[LOG_ID_MAX] = { + [LOG_ID_MAIN] = "main", + [LOG_ID_RADIO] = "radio", + [LOG_ID_EVENTS] = "events", + [LOG_ID_SYSTEM] = "system" +}; + +const char *android_log_id_to_name(log_id_t log_id) { + if (log_id >= LOG_ID_MAX) { + log_id = LOG_ID_MAIN; + } + return LOG_NAME[log_id]; +} + +static int accessmode(int mode) +{ + if ((mode & O_ACCMODE) == O_WRONLY) { + return W_OK; + } + if ((mode & O_ACCMODE) == O_RDWR) { + return R_OK | W_OK; + } + return R_OK; +} + +/* repeated fragment */ +static int check_allocate_accessible(char **n, const char *b, int mode) +{ + *n = NULL; + + if (!b) { + return -EINVAL; + } + + asprintf(n, LOG_FILE_DIR "%s", b); + if (!*n) { + return -1; + } + + return access(*n, accessmode(mode)); +} + +log_id_t android_name_to_log_id(const char *logName) { + const char *b; + char *n; + int ret; + + if (!logName) { + return -1; /* NB: log_id_t is unsigned */ + } + b = strrchr(logName, '/'); + if (!b) { + b = logName; + } else { + ++b; + } + + ret = check_allocate_accessible(&n, b, O_RDONLY); + free(n); + if (ret) { + return ret; + } + + for(ret = LOG_ID_MIN; ret < LOG_ID_MAX; ++ret) { + const char *l = LOG_NAME[ret]; + if (l && !strcmp(b, l)) { + return ret; + } + } + return -1; /* should never happen */ +} + +struct logger_list { + struct listnode node; + int mode; + unsigned int tail; + pid_t pid; + unsigned int queued_lines; + int timeout_ms; + int error; + bool flush; + bool valid_entry; /* valiant(?) effort to deal with memory starvation */ + struct log_msg entry; +}; + +struct log_list { + struct listnode node; + struct log_msg entry; /* Truncated to event->len() + 1 to save space */ +}; + +struct logger { + struct listnode node; + struct logger_list *top; + int fd; + log_id_t id; + short *revents; + struct listnode log_list; +}; + +/* android_logger_alloc unimplemented, no use case */ +/* android_logger_free not exported */ +static void android_logger_free(struct logger *logger) +{ + if (!logger) { + return; + } + + while (!list_empty(&logger->log_list)) { + struct log_list *entry = node_to_item( + list_head(&logger->log_list), struct log_list, node); + list_remove(&entry->node); + free(entry); + if (logger->top->queued_lines) { + logger->top->queued_lines--; + } + } + + if (logger->fd >= 0) { + close(logger->fd); + } + + list_remove(&logger->node); + + free(logger); +} + +log_id_t android_logger_get_id(struct logger *logger) +{ + return logger->id; +} + +/* worker for sending the command to the logger */ +static int logger_ioctl(struct logger *logger, int cmd, int mode) +{ + char *n; + int f, ret; + + if (!logger || !logger->top) { + return -EFAULT; + } + + if (((mode & O_ACCMODE) == O_RDWR) + || (((mode ^ logger->top->mode) & O_ACCMODE) == 0)) { + return ioctl(logger->fd, cmd); + } + + /* We go here if android_logger_list_open got mode wrong for this ioctl */ + ret = check_allocate_accessible(&n, android_log_id_to_name(logger->id), mode); + if (ret) { + free(n); + return ret; + } + + f = open(n, mode); + free(n); + if (f < 0) { + return f; + } + + ret = ioctl(f, cmd); + close (f); + + return ret; +} + +int android_logger_clear(struct logger *logger) +{ + return logger_ioctl(logger, LOGGER_FLUSH_LOG, O_WRONLY); +} + +/* returns the total size of the log's ring buffer */ +int android_logger_get_log_size(struct logger *logger) +{ + return logger_ioctl(logger, LOGGER_GET_LOG_BUF_SIZE, O_RDWR); +} + +/* + * returns the readable size of the log's ring buffer (that is, amount of the + * log consumed) + */ +int android_logger_get_log_readable_size(struct logger *logger) +{ + return logger_ioctl(logger, LOGGER_GET_LOG_LEN, O_RDONLY); +} + +/* + * returns the logger version + */ +int android_logger_get_log_version(struct logger *logger) +{ + int ret = logger_ioctl(logger, LOGGER_GET_VERSION, O_RDWR); + return (ret < 0) ? 1 : ret; +} + +struct logger_list *android_logger_list_alloc(int mode, + unsigned int tail, + pid_t pid) +{ + struct logger_list *logger_list; + + logger_list = calloc(1, sizeof(*logger_list)); + if (!logger_list) { + return NULL; + } + list_init(&logger_list->node); + logger_list->mode = mode; + logger_list->tail = tail; + logger_list->pid = pid; + return logger_list; +} + +/* android_logger_list_register unimplemented, no use case */ +/* android_logger_list_unregister unimplemented, no use case */ + +/* Open the named log and add it to the logger list */ +struct logger *android_logger_open(struct logger_list *logger_list, + log_id_t id) +{ + struct listnode *node; + struct logger *logger; + char *n; + + if (!logger_list || (id >= LOG_ID_MAX)) { + goto err; + } + + logger_for_each(logger, logger_list) { + if (logger->id == id) { + goto ok; + } + } + + logger = calloc(1, sizeof(*logger)); + if (!logger) { + goto err; + } + + if (check_allocate_accessible(&n, android_log_id_to_name(id), + logger_list->mode)) { + goto err_name; + } + + logger->fd = open(n, logger_list->mode); + if (logger->fd < 0) { + goto err_name; + } + + free(n); + logger->id = id; + list_init(&logger->log_list); + list_add_tail(&logger_list->node, &logger->node); + logger->top = logger_list; + logger_list->timeout_ms = LOG_TIMEOUT_FLUSH; + goto ok; + +err_name: + free(n); +err_logger: + free(logger); +err: + logger = NULL; +ok: + return logger; +} + +/* Open the single named log and make it part of a new logger list */ +struct logger_list *android_logger_list_open(log_id_t id, + int mode, + unsigned int tail, + pid_t pid) +{ + struct logger_list *logger_list = android_logger_list_alloc(mode, tail, pid); + if (!logger_list) { + return NULL; + } + + if (!android_logger_open(logger_list, id)) { + android_logger_list_free(logger_list); + return NULL; + } + + return logger_list; +} + +/* prevent memory starvation when backfilling */ +static unsigned int queue_threshold(struct logger_list *logger_list) +{ + return (logger_list->tail < 64) ? 64 : logger_list->tail; +} + +static bool low_queue(struct listnode *node) +{ + /* low is considered less than 2 */ + return list_head(node) == list_tail(node); +} + +/* Flush queues in sequential order, one at a time */ +static int android_logger_list_flush(struct logger_list *logger_list, + struct log_msg *log_msg) +{ + int ret = 0; + struct log_list *firstentry = NULL; + + while ((ret == 0) + && (logger_list->flush + || (logger_list->queued_lines > logger_list->tail))) { + struct logger *logger; + + /* Merge sort */ + bool at_least_one_is_low = false; + struct logger *firstlogger = NULL; + firstentry = NULL; + + logger_for_each(logger, logger_list) { + struct listnode *node; + struct log_list *oldest = NULL; + + /* kernel logger channels not necessarily time-sort order */ + list_for_each(node, &logger->log_list) { + struct log_list *entry = node_to_item(node, + struct log_list, node); + if (!oldest + || (entry->entry.entry.sec < oldest->entry.entry.sec) + || ((entry->entry.entry.sec == oldest->entry.entry.sec) + && (entry->entry.entry.nsec < oldest->entry.entry.nsec))) { + oldest = entry; + } + } + + if (!oldest) { + at_least_one_is_low = true; + continue; + } else if (low_queue(&logger->log_list)) { + at_least_one_is_low = true; + } + + if (!firstentry + || (oldest->entry.entry.sec < firstentry->entry.entry.sec) + || ((oldest->entry.entry.sec == firstentry->entry.entry.sec) + && (oldest->entry.entry.nsec < firstentry->entry.entry.nsec))) { + firstentry = oldest; + firstlogger = logger; + } + } + + if (!firstentry) { + break; + } + + /* when trimming list, tries to keep one entry behind in each bucket */ + if (!logger_list->flush + && at_least_one_is_low + && (logger_list->queued_lines < queue_threshold(logger_list))) { + break; + } + + /* within tail?, send! */ + if ((logger_list->tail == 0) + || (logger_list->queued_lines <= logger_list->tail)) { + ret = firstentry->entry.entry.hdr_size; + if (!ret) { + ret = sizeof(firstentry->entry.entry_v1); + } + ret += firstentry->entry.entry.len; + + memcpy(log_msg->buf, firstentry->entry.buf, ret + 1); + log_msg->extra.id = firstlogger->id; + } + + /* next entry */ + list_remove(&firstentry->node); + free(firstentry); + if (logger_list->queued_lines) { + logger_list->queued_lines--; + } + } + + /* Flushed the list, no longer in tail mode for continuing content */ + if (logger_list->flush && !firstentry) { + logger_list->tail = 0; + } + return ret; +} + +/* Read from the selected logs */ +int android_logger_list_read(struct logger_list *logger_list, + struct log_msg *log_msg) +{ + struct logger *logger; + nfds_t nfds; + struct pollfd *p, *pollfds = NULL; + int error = 0, ret = 0; + + memset(log_msg, 0, sizeof(struct log_msg)); + + if (!logger_list) { + return -ENODEV; + } + + if (!(accessmode(logger_list->mode) & R_OK)) { + logger_list->error = EPERM; + goto done; + } + + nfds = 0; + logger_for_each(logger, logger_list) { + ++nfds; + } + if (nfds <= 0) { + error = ENODEV; + goto done; + } + + /* Do we have anything to offer from the buffer or state? */ + if (logger_list->valid_entry) { /* implies we are also in a flush state */ + goto flush; + } + + ret = android_logger_list_flush(logger_list, log_msg); + if (ret) { + goto done; + } + + if (logger_list->error) { /* implies we are also in a flush state */ + goto done; + } + + /* Lets start grinding on metal */ + pollfds = calloc(nfds, sizeof(struct pollfd)); + if (!pollfds) { + error = ENOMEM; + goto flush; + } + + p = pollfds; + logger_for_each(logger, logger_list) { + p->fd = logger->fd; + p->events = POLLIN; + logger->revents = &p->revents; + ++p; + } + + while (!ret && !error) { + int result; + + /* If we oversleep it's ok, i.e. ignore EINTR. */ + result = TEMP_FAILURE_RETRY( + poll(pollfds, nfds, logger_list->timeout_ms)); + + if (result <= 0) { + if (result) { + error = errno; + } else if (logger_list->mode & O_NDELAY) { + error = EAGAIN; + } else { + logger_list->timeout_ms = LOG_TIMEOUT_NEVER; + } + + logger_list->flush = true; + goto try_flush; + } + + logger_list->timeout_ms = LOG_TIMEOUT_FLUSH; + + /* Anti starvation */ + if (!logger_list->flush + && (logger_list->queued_lines > (queue_threshold(logger_list) / 2))) { + /* Any queues with input pending that is low? */ + bool starving = false; + logger_for_each(logger, logger_list) { + if ((*(logger->revents) & POLLIN) + && low_queue(&logger->log_list)) { + starving = true; + break; + } + } + + /* pushback on any queues that are not low */ + if (starving) { + logger_for_each(logger, logger_list) { + if ((*(logger->revents) & POLLIN) + && !low_queue(&logger->log_list)) { + *(logger->revents) &= ~POLLIN; + } + } + } + } + + logger_for_each(logger, logger_list) { + unsigned int hdr_size; + struct log_list *entry; + + if (!(*(logger->revents) & POLLIN)) { + continue; + } + + memset(logger_list->entry.buf, 0, sizeof(struct log_msg)); + /* NOTE: driver guarantees we read exactly one full entry */ + result = read(logger->fd, logger_list->entry.buf, + LOGGER_ENTRY_MAX_LEN); + if (result <= 0) { + if (!result) { + error = EIO; + } else if (errno != EINTR) { + error = errno; + } + continue; + } + + if (logger_list->pid + && (logger_list->pid != logger_list->entry.entry.pid)) { + continue; + } + + hdr_size = logger_list->entry.entry.hdr_size; + if (!hdr_size) { + hdr_size = sizeof(logger_list->entry.entry_v1); + } + + if ((hdr_size > sizeof(struct log_msg)) + || (logger_list->entry.entry.len + > sizeof(logger_list->entry.buf) - hdr_size) + || (logger_list->entry.entry.len != result - hdr_size)) { + error = EINVAL; + continue; + } + + logger_list->entry.extra.id = logger->id; + + /* speedup: If not tail, and only one list, send directly */ + if (!logger_list->tail + && (list_head(&logger_list->node) + == list_tail(&logger_list->node))) { + ret = result; + memcpy(log_msg->buf, logger_list->entry.buf, result + 1); + log_msg->extra.id = logger->id; + break; + } + + entry = malloc(sizeof(*entry) - sizeof(entry->entry) + result + 1); + + if (!entry) { + logger_list->valid_entry = true; + error = ENOMEM; + break; + } + + logger_list->queued_lines++; + + memcpy(entry->entry.buf, logger_list->entry.buf, result); + entry->entry.buf[result] = '\0'; + list_add_tail(&logger->log_list, &entry->node); + } + + if (ret <= 0) { +try_flush: + ret = android_logger_list_flush(logger_list, log_msg); + } + } + + free(pollfds); + +flush: + if (error) { + logger_list->flush = true; + } + + if (ret <= 0) { + ret = android_logger_list_flush(logger_list, log_msg); + + if (!ret && logger_list->valid_entry) { + ret = logger_list->entry.entry.hdr_size; + if (!ret) { + ret = sizeof(logger_list->entry.entry_v1); + } + ret += logger_list->entry.entry.len; + + memcpy(log_msg->buf, logger_list->entry.buf, + sizeof(struct log_msg)); + logger_list->valid_entry = false; + } + } + +done: + if (logger_list->error) { + error = logger_list->error; + } + if (error) { + logger_list->error = error; + if (!ret) { + ret = -error; + } + } + return ret; +} + +/* Close all the logs */ +void android_logger_list_free(struct logger_list *logger_list) +{ + if (logger_list == NULL) { + return; + } + + while (!list_empty(&logger_list->node)) { + struct listnode *node = list_head(&logger_list->node); + struct logger *logger = node_to_item(node, struct logger, node); + android_logger_free(logger); + } + + free(logger_list); +} diff --git a/liblog/logd_write.c b/liblog/logd_write.c index 19d7166..6b35a0f 100644 --- a/liblog/logd_write.c +++ b/liblog/logd_write.c @@ -1,5 +1,5 @@ /* - * Copyright (C) 2007 The Android Open Source Project + * Copyright (C) 2007-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. @@ -31,7 +31,12 @@ #include <log/logd.h> #include <log/log.h> -#define LOG_BUF_SIZE 1024 +#define LOGGER_LOG_MAIN "log/main" +#define LOGGER_LOG_RADIO "log/radio" +#define LOGGER_LOG_EVENTS "log/events" +#define LOGGER_LOG_SYSTEM "log/system" + +#define LOG_BUF_SIZE 1024 #if FAKE_LOG_DEVICE // This will be defined when building for the host. @@ -240,7 +245,7 @@ int __android_log_buf_print(int bufID, int prio, const char *tag, const char *fm } void __android_log_assert(const char *cond, const char *tag, - const char *fmt, ...) + const char *fmt, ...) { char buf[LOG_BUF_SIZE]; diff --git a/liblog/logprint.c b/liblog/logprint.c index 508c825..a7480d5 100644 --- a/liblog/logprint.c +++ b/liblog/logprint.c @@ -1,6 +1,6 @@ -/* //device/libs/cutils/logprint.c +/* ** -** Copyright 2006, The Android Open Source Project +** Copyright 2006-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. @@ -377,8 +377,13 @@ int android_log_processLogBuffer(struct logger_entry *buf, int msgEnd = -1; int i; + char *msg = buf->msg; + struct logger_entry_v2 *buf2 = (struct logger_entry_v2 *)buf; + if (buf2->hdr_size) { + msg = ((char *)buf2) + buf2->hdr_size; + } for (i = 1; i < buf->len; i++) { - if (buf->msg[i] == '\0') { + if (msg[i] == '\0') { if (msgStart == -1) { msgStart = i + 1; } else { @@ -395,12 +400,12 @@ int android_log_processLogBuffer(struct logger_entry *buf, if (msgEnd == -1) { // incoming message not null-terminated; force it msgEnd = buf->len - 1; - buf->msg[msgEnd] = '\0'; + msg[msgEnd] = '\0'; } - entry->priority = buf->msg[0]; - entry->tag = buf->msg + 1; - entry->message = buf->msg + msgStart; + entry->priority = msg[0]; + entry->tag = msg + 1; + entry->message = msg + msgStart; entry->messageLen = msgEnd - msgStart; return 0; @@ -614,6 +619,10 @@ int android_log_processBinaryLogBuffer(struct logger_entry *buf, * Pull the tag out. */ eventData = (const unsigned char*) buf->msg; + struct logger_entry_v2 *buf2 = (struct logger_entry_v2 *)buf; + if (buf2->hdr_size) { + eventData = ((unsigned char *)buf2) + buf2->hdr_size; + } inCount = buf->len; if (inCount < 4) return -1; diff --git a/liblog/tests/Android.mk b/liblog/tests/Android.mk new file mode 100644 index 0000000..db06cf7 --- /dev/null +++ b/liblog/tests/Android.mk @@ -0,0 +1,77 @@ +# +# Copyright (C) 2013-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. +# ----------------------------------------------------------------------------- + +test_module_prefix := liblog- +test_tags := tests + +benchmark_c_flags := \ + -Ibionic/tests \ + -Wall -Wextra \ + -Werror \ + -fno-builtin \ + -std=gnu++11 + +benchmark_src_files := \ + benchmark_main.cpp \ + liblog_benchmark.cpp \ + +# Build benchmarks for the device. Run with: +# adb shell liblog-benchmarks +include $(CLEAR_VARS) +LOCAL_MODULE := $(test_module_prefix)benchmarks +LOCAL_MODULE_TAGS := $(test_tags) +LOCAL_ADDITIONAL_DEPENDENCIES := $(LOCAL_PATH)/Android.mk +LOCAL_CFLAGS += $(benchmark_c_flags) +LOCAL_SHARED_LIBRARIES += liblog libm +LOCAL_SRC_FILES := $(benchmark_src_files) +ifndef LOCAL_SDK_VERSION +LOCAL_C_INCLUDES += bionic bionic/libstdc++/include external/stlport/stlport +LOCAL_SHARED_LIBRARIES += libstlport +endif +LOCAL_MODULE_PATH := $(TARGET_OUT_DATA_NATIVE_TESTS)/$(LOCAL_MODULE) +include $(BUILD_EXECUTABLE) + +# ----------------------------------------------------------------------------- +# Unit tests. +# ----------------------------------------------------------------------------- + +test_c_flags := \ + -fstack-protector-all \ + -g \ + -Wall -Wextra \ + -Werror \ + -fno-builtin \ + +test_src_files := \ + liblog_test.cpp \ + +# Build tests for the device (with .so). Run with: +# adb shell /data/nativetest/liblog-unit-tests/liblog-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_LDLIBS := -lpthread +LOCAL_SHARED_LIBRARIES := liblog +LOCAL_SRC_FILES := $(test_src_files) +include $(BUILD_NATIVE_TEST) diff --git a/liblog/tests/benchmark.h b/liblog/tests/benchmark.h new file mode 100644 index 0000000..7f96e6d --- /dev/null +++ b/liblog/tests/benchmark.h @@ -0,0 +1,147 @@ +/* + * Copyright (C) 2012-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 <stdint.h> +#include <stdio.h> +#include <stdlib.h> +#include <string.h> + +#include <vector> + +#ifndef BIONIC_BENCHMARK_H_ +#define BIONIC_BENCHMARK_H_ + +namespace testing { + +class Benchmark; +template <typename T> class BenchmarkWantsArg; +template <typename T> class BenchmarkWithArg; + +void BenchmarkRegister(Benchmark* bm); +int PrettyPrintInt(char* str, int len, unsigned int arg); + +class Benchmark { + public: + Benchmark(const char* name, void (*fn)(int)) : name_(strdup(name)), fn_(fn) { + BenchmarkRegister(this); + } + Benchmark(const char* name) : name_(strdup(name)), fn_(NULL) {} + + virtual ~Benchmark() { + free(name_); + } + + const char* Name() { return name_; } + virtual const char* ArgName() { return NULL; } + virtual void RunFn(int iterations) { fn_(iterations); } + + protected: + char* name_; + + private: + void (*fn_)(int); +}; + +template <typename T> +class BenchmarkWantsArgBase : public Benchmark { + public: + BenchmarkWantsArgBase(const char* name, void (*fn)(int, T)) : Benchmark(name) { + fn_arg_ = fn; + } + + BenchmarkWantsArgBase<T>* Arg(const char* arg_name, T arg) { + BenchmarkRegister(new BenchmarkWithArg<T>(name_, fn_arg_, arg_name, arg)); + return this; + } + + protected: + virtual void RunFn(int) { printf("can't run arg benchmark %s without arg\n", Name()); } + void (*fn_arg_)(int, T); +}; + +template <typename T> +class BenchmarkWithArg : public BenchmarkWantsArg<T> { + public: + BenchmarkWithArg(const char* name, void (*fn)(int, T), const char* arg_name, T arg) : + BenchmarkWantsArg<T>(name, fn), arg_(arg) { + arg_name_ = strdup(arg_name); + } + + virtual ~BenchmarkWithArg() { + free(arg_name_); + } + + virtual const char* ArgName() { return arg_name_; } + + protected: + virtual void RunFn(int iterations) { BenchmarkWantsArg<T>::fn_arg_(iterations, arg_); } + + private: + T arg_; + char* arg_name_; +}; + +template <typename T> +class BenchmarkWantsArg : public BenchmarkWantsArgBase<T> { + public: + BenchmarkWantsArg<T>(const char* name, void (*fn)(int, T)) : + BenchmarkWantsArgBase<T>(name, fn) { } +}; + +template <> +class BenchmarkWantsArg<int> : public BenchmarkWantsArgBase<int> { + public: + BenchmarkWantsArg<int>(const char* name, void (*fn)(int, int)) : + BenchmarkWantsArgBase<int>(name, fn) { } + + BenchmarkWantsArg<int>* Arg(int arg) { + char arg_name[100]; + PrettyPrintInt(arg_name, sizeof(arg_name), arg); + BenchmarkRegister(new BenchmarkWithArg<int>(name_, fn_arg_, arg_name, arg)); + return this; + } +}; + +static inline Benchmark* BenchmarkFactory(const char* name, void (*fn)(int)) { + return new Benchmark(name, fn); +} + +template <typename T> +static inline BenchmarkWantsArg<T>* BenchmarkFactory(const char* name, void (*fn)(int, T)) { + return new BenchmarkWantsArg<T>(name, fn); +} + +} // namespace testing + +template <typename T> +static inline void BenchmarkAddArg(::testing::Benchmark* b, const char* name, T arg) { + ::testing::BenchmarkWantsArg<T>* ba; + ba = static_cast< ::testing::BenchmarkWantsArg<T>* >(b); + ba->Arg(name, arg); +} + +void SetBenchmarkBytesProcessed(uint64_t); +void ResetBenchmarkTiming(void); +void StopBenchmarkTiming(void); +void StartBenchmarkTiming(void); +void StartBenchmarkTiming(uint64_t); +void StopBenchmarkTiming(uint64_t); + +#define BENCHMARK(f) \ + static ::testing::Benchmark* _benchmark_##f __attribute__((unused)) = \ + (::testing::Benchmark*)::testing::BenchmarkFactory(#f, f) + +#endif // BIONIC_BENCHMARK_H_ diff --git a/liblog/tests/benchmark_main.cpp b/liblog/tests/benchmark_main.cpp new file mode 100644 index 0000000..02df460 --- /dev/null +++ b/liblog/tests/benchmark_main.cpp @@ -0,0 +1,245 @@ +/* + * Copyright (C) 2012-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 <benchmark.h> + +#include <regex.h> +#include <stdio.h> +#include <stdlib.h> + +#include <string> +#include <map> +#include <vector> + +static uint64_t gBytesProcessed; +static uint64_t gBenchmarkTotalTimeNs; +static uint64_t gBenchmarkTotalTimeNsSquared; +static uint64_t gBenchmarkNum; +static uint64_t gBenchmarkStartTimeNs; + +typedef std::vector< ::testing::Benchmark* > BenchmarkList; +static BenchmarkList* gBenchmarks; + +static int Round(int n) { + int base = 1; + while (base*10 < n) { + base *= 10; + } + if (n < 2*base) { + return 2*base; + } + if (n < 5*base) { + return 5*base; + } + return 10*base; +} + +static uint64_t NanoTime() { + struct timespec t; + t.tv_sec = t.tv_nsec = 0; + clock_gettime(CLOCK_MONOTONIC, &t); + return static_cast<uint64_t>(t.tv_sec) * 1000000000ULL + t.tv_nsec; +} + +namespace testing { + +int PrettyPrintInt(char* str, int len, unsigned int arg) +{ + if (arg >= (1<<30) && arg % (1<<30) == 0) { + return snprintf(str, len, "%uGi", arg/(1<<30)); + } else if (arg >= (1<<20) && arg % (1<<20) == 0) { + return snprintf(str, len, "%uMi", arg/(1<<20)); + } else if (arg >= (1<<10) && arg % (1<<10) == 0) { + return snprintf(str, len, "%uKi", arg/(1<<10)); + } else if (arg >= 1000000000 && arg % 1000000000 == 0) { + return snprintf(str, len, "%uG", arg/1000000000); + } else if (arg >= 1000000 && arg % 1000000 == 0) { + return snprintf(str, len, "%uM", arg/1000000); + } else if (arg >= 1000 && arg % 1000 == 0) { + return snprintf(str, len, "%uK", arg/1000); + } else { + return snprintf(str, len, "%u", arg); + } +} + +bool ShouldRun(Benchmark* b, int argc, char* argv[]) { + if (argc == 1) { + return true; // With no arguments, we run all benchmarks. + } + // Otherwise, we interpret each argument as a regular expression and + // see if any of our benchmarks match. + for (int i = 1; i < argc; i++) { + regex_t re; + if (regcomp(&re, argv[i], 0) != 0) { + fprintf(stderr, "couldn't compile \"%s\" as a regular expression!\n", argv[i]); + exit(EXIT_FAILURE); + } + int match = regexec(&re, b->Name(), 0, NULL, 0); + regfree(&re); + if (match != REG_NOMATCH) { + return true; + } + } + return false; +} + +void BenchmarkRegister(Benchmark* b) { + if (gBenchmarks == NULL) { + gBenchmarks = new BenchmarkList; + } + gBenchmarks->push_back(b); +} + +void RunRepeatedly(Benchmark* b, int iterations) { + gBytesProcessed = 0; + ResetBenchmarkTiming(); + uint64_t StartTimeNs = NanoTime(); + b->RunFn(iterations); + // Catch us if we fail to log anything. + if ((gBenchmarkTotalTimeNs == 0) + && (StartTimeNs != 0) + && (gBenchmarkStartTimeNs == 0)) { + gBenchmarkTotalTimeNs = NanoTime() - StartTimeNs; + } +} + +void Run(Benchmark* b) { + // run once in case it's expensive + unsigned iterations = 1; + uint64_t s = NanoTime(); + RunRepeatedly(b, iterations); + s = NanoTime() - s; + while (s < 2e9 && gBenchmarkTotalTimeNs < 1e9 && iterations < 1e9) { + unsigned last = iterations; + if (gBenchmarkTotalTimeNs/iterations == 0) { + iterations = 1e9; + } else { + iterations = 1e9 / (gBenchmarkTotalTimeNs/iterations); + } + iterations = std::max(last + 1, std::min(iterations + iterations/2, 100*last)); + iterations = Round(iterations); + s = NanoTime(); + RunRepeatedly(b, iterations); + s = NanoTime() - s; + } + + char throughput[100]; + throughput[0] = '\0'; + if (gBenchmarkTotalTimeNs > 0 && gBytesProcessed > 0) { + double mib_processed = static_cast<double>(gBytesProcessed)/1e6; + double seconds = static_cast<double>(gBenchmarkTotalTimeNs)/1e9; + snprintf(throughput, sizeof(throughput), " %8.2f MiB/s", mib_processed/seconds); + } + + char full_name[100]; + snprintf(full_name, sizeof(full_name), "%s%s%s", b->Name(), + b->ArgName() ? "/" : "", + b->ArgName() ? b->ArgName() : ""); + + uint64_t mean = gBenchmarkTotalTimeNs / iterations; + uint64_t sdev = 0; + if (gBenchmarkNum == iterations) { + mean = gBenchmarkTotalTimeNs / gBenchmarkNum; + uint64_t nXvariance = gBenchmarkTotalTimeNsSquared * gBenchmarkNum + - (gBenchmarkTotalTimeNs * gBenchmarkTotalTimeNs); + sdev = (sqrt((double)nXvariance) / gBenchmarkNum / gBenchmarkNum) + 0.5; + } + if (mean > (10000 * sdev)) { + printf("%-25s %10llu %10llu%s\n", full_name, + static_cast<uint64_t>(iterations), mean, throughput); + } else { + printf("%-25s %10llu %10llu(\317\203%llu)%s\n", full_name, + static_cast<uint64_t>(iterations), mean, sdev, throughput); + } + fflush(stdout); +} + +} // namespace testing + +void SetBenchmarkBytesProcessed(uint64_t x) { + gBytesProcessed = x; +} + +void ResetBenchmarkTiming() { + gBenchmarkStartTimeNs = 0; + gBenchmarkTotalTimeNs = 0; + gBenchmarkTotalTimeNsSquared = 0; + gBenchmarkNum = 0; +} + +void StopBenchmarkTiming(void) { + if (gBenchmarkStartTimeNs != 0) { + int64_t diff = NanoTime() - gBenchmarkStartTimeNs; + gBenchmarkTotalTimeNs += diff; + gBenchmarkTotalTimeNsSquared += diff * diff; + ++gBenchmarkNum; + } + gBenchmarkStartTimeNs = 0; +} + +void StartBenchmarkTiming(void) { + if (gBenchmarkStartTimeNs == 0) { + gBenchmarkStartTimeNs = NanoTime(); + } +} + +void StopBenchmarkTiming(uint64_t NanoTime) { + if (gBenchmarkStartTimeNs != 0) { + int64_t diff = NanoTime - gBenchmarkStartTimeNs; + gBenchmarkTotalTimeNs += diff; + gBenchmarkTotalTimeNsSquared += diff * diff; + if (NanoTime != 0) { + ++gBenchmarkNum; + } + } + gBenchmarkStartTimeNs = 0; +} + +void StartBenchmarkTiming(uint64_t NanoTime) { + if (gBenchmarkStartTimeNs == 0) { + gBenchmarkStartTimeNs = NanoTime; + } +} + +int main(int argc, char* argv[]) { + if (gBenchmarks->empty()) { + fprintf(stderr, "No benchmarks registered!\n"); + exit(EXIT_FAILURE); + } + + bool need_header = true; + for (auto b : *gBenchmarks) { + if (ShouldRun(b, argc, argv)) { + if (need_header) { + printf("%-25s %10s %10s\n", "", "iterations", "ns/op"); + fflush(stdout); + need_header = false; + } + Run(b); + } + } + + if (need_header) { + fprintf(stderr, "No matching benchmarks!\n"); + fprintf(stderr, "Available benchmarks:\n"); + for (auto b : *gBenchmarks) { + fprintf(stderr, " %s\n", b->Name()); + } + exit(EXIT_FAILURE); + } + + return 0; +} diff --git a/liblog/tests/liblog_benchmark.cpp b/liblog/tests/liblog_benchmark.cpp new file mode 100644 index 0000000..19406fb --- /dev/null +++ b/liblog/tests/liblog_benchmark.cpp @@ -0,0 +1,268 @@ +/* + * Copyright (C) 2013-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 <sys/socket.h> +#include <cutils/sockets.h> +#include <log/log.h> +#include <log/logger.h> +#include <log/log_read.h> + +#include "benchmark.h" + +// enhanced version of LOG_FAILURE_RETRY to add support for EAGAIN and +// non-syscall libs. Since we are benchmarking, or using this in the emergency +// signal to stuff a terminating code, we do NOT want to introduce +// a syscall or usleep on EAGAIN retry. +#define LOG_FAILURE_RETRY(exp) ({ \ + typeof (exp) _rc; \ + do { \ + _rc = (exp); \ + } while (((_rc == -1) \ + && ((errno == EINTR) \ + || (errno == EAGAIN))) \ + || (_rc == -EINTR) \ + || (_rc == -EAGAIN)); \ + _rc; }) + +/* + * Measure the fastest rate we can reliabley stuff print messages into + * the log at high pressure. Expect this to be less than double the process + * wakeup time (2ms?) + */ +static void BM_log_maximum_retry(int iters) { + StartBenchmarkTiming(); + + for (int i = 0; i < iters; ++i) { + LOG_FAILURE_RETRY( + __android_log_print(ANDROID_LOG_INFO, + "BM_log_maximum_retry", "%d", i)); + } + + StopBenchmarkTiming(); +} +BENCHMARK(BM_log_maximum_retry); + +/* + * Measure the fastest rate we can stuff print messages into the log + * at high pressure. Expect this to be less than double the process wakeup + * time (2ms?) + */ +static void BM_log_maximum(int iters) { + StartBenchmarkTiming(); + + for (int i = 0; i < iters; ++i) { + __android_log_print(ANDROID_LOG_INFO, "BM_log_maximum", "%d", i); + } + + StopBenchmarkTiming(); +} +BENCHMARK(BM_log_maximum); + +/* + * Measure the time it takes to submit the android logging call using + * discrete acquisition under light load. Expect this to be a pair of + * syscall periods (2us). + */ +static void BM_clock_overhead(int iters) { + for (int i = 0; i < iters; ++i) { + StartBenchmarkTiming(); + StopBenchmarkTiming(); + } +} +BENCHMARK(BM_clock_overhead); + +/* + * 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 + * syscall periods (40us). + */ +static void BM_log_overhead(int iters) { + for (int i = 0; i < iters; ++i) { + StartBenchmarkTiming(); + __android_log_print(ANDROID_LOG_INFO, "BM_log_overhead", "%d", i); + StopBenchmarkTiming(); + usleep(1000); + } +} +BENCHMARK(BM_log_overhead); + +static void caught_latency(int signum) +{ + unsigned long long v = 0xDEADBEEFA55A5AA5ULL; + + LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); +} + +static unsigned long long caught_convert(char *cp) +{ + unsigned long long l = cp[0] & 0xFF; + l |= (unsigned long long) (cp[1] & 0xFF) << 8; + l |= (unsigned long long) (cp[2] & 0xFF) << 16; + l |= (unsigned long long) (cp[3] & 0xFF) << 24; + l |= (unsigned long long) (cp[4] & 0xFF) << 32; + l |= (unsigned long long) (cp[5] & 0xFF) << 40; + l |= (unsigned long long) (cp[6] & 0xFF) << 48; + l |= (unsigned long long) (cp[7] & 0xFF) << 56; + return l; +} + +static const int alarm_time = 3; + +/* + * Measure the time it takes for the logd posting call to acquire the + * timestamp to place into the internal record. Expect this to be less than + * 4 syscalls (3us). + */ +static void BM_log_latency(int iters) { + pid_t pid = getpid(); + + struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS, + O_RDONLY, 0, pid); + + if (!logger_list) { + fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); + exit(EXIT_FAILURE); + } + + signal(SIGALRM, caught_latency); + alarm(alarm_time); + + for (int j = 0, i = 0; i < iters && j < 10*iters; ++i, ++j) { + log_time ts; + LOG_FAILURE_RETRY(( + clock_gettime(CLOCK_REALTIME, &ts), + android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts)))); + + for (;;) { + log_msg log_msg; + int ret = android_logger_list_read(logger_list, &log_msg); + alarm(alarm_time); + + if (ret <= 0) { + iters = i; + break; + } + 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; + } + log_time tx(eventData + 4 + 1); + if (ts != tx) { + if (0xDEADBEEFA55A5AA5ULL == caught_convert(eventData + 4 + 1)) { + iters = i; + break; + } + continue; + } + + uint64_t start = ts.nsec(); + uint64_t end = log_msg.nsec(); + if (end >= start) { + StartBenchmarkTiming(start); + StopBenchmarkTiming(end); + } else { + --i; + } + break; + } + } + + signal(SIGALRM, SIG_DFL); + alarm(0); + + android_logger_list_free(logger_list); +} +BENCHMARK(BM_log_latency); + +static void caught_delay(int signum) +{ + unsigned long long v = 0xDEADBEEFA55A5AA6ULL; + + LOG_FAILURE_RETRY(__android_log_btwrite(0, EVENT_TYPE_LONG, &v, sizeof(v))); +} + +/* + * Measure the time it takes for the logd posting call to make it into + * the logs. Expect this to be less than double the process wakeup time (2ms). + */ +static void BM_log_delay(int iters) { + pid_t pid = getpid(); + + struct logger_list * logger_list = android_logger_list_open(LOG_ID_EVENTS, + O_RDONLY, 0, pid); + + if (!logger_list) { + fprintf(stderr, "Unable to open events log: %s\n", strerror(errno)); + exit(EXIT_FAILURE); + } + + signal(SIGALRM, caught_delay); + alarm(alarm_time); + + StartBenchmarkTiming(); + + for (int i = 0; i < iters; ++i) { + log_time ts(CLOCK_REALTIME); + + LOG_FAILURE_RETRY( + android_btWriteLog(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); + + for (;;) { + log_msg log_msg; + int ret = android_logger_list_read(logger_list, &log_msg); + alarm(alarm_time); + + if (ret <= 0) { + iters = i; + break; + } + 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; + } + log_time tx(eventData + 4 + 1); + if (ts != tx) { + if (0xDEADBEEFA55A5AA6ULL == caught_convert(eventData + 4 + 1)) { + iters = i; + break; + } + continue; + } + + break; + } + } + + signal(SIGALRM, SIG_DFL); + alarm(0); + + StopBenchmarkTiming(); + + android_logger_list_free(logger_list); +} +BENCHMARK(BM_log_delay); diff --git a/liblog/tests/liblog_test.cpp b/liblog/tests/liblog_test.cpp new file mode 100644 index 0000000..9ae8f22 --- /dev/null +++ b/liblog/tests/liblog_test.cpp @@ -0,0 +1,319 @@ +/* + * Copyright (C) 2013-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 <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", + "radio")); + usleep(1000); + ASSERT_LT(0, __android_log_buf_print(LOG_ID_SYSTEM, ANDROID_LOG_INFO, + "TEST__android_log_buf_print", + "system")); + usleep(1000); + ASSERT_LT(0, __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, + "TEST__android_log_buf_print", + "main")); + usleep(1000); +} + +TEST(liblog, __android_log_buf_write) { + ASSERT_LT(0, __android_log_buf_write(LOG_ID_RADIO, ANDROID_LOG_INFO, + "TEST__android_log_buf_write", + "radio")); + usleep(1000); + ASSERT_LT(0, __android_log_buf_write(LOG_ID_SYSTEM, ANDROID_LOG_INFO, + "TEST__android_log_buf_write", + "system")); + usleep(1000); + ASSERT_LT(0, __android_log_buf_write(LOG_ID_MAIN, ANDROID_LOG_INFO, + "TEST__android_log_buf_write", + "main")); + usleep(1000); +} + +TEST(liblog, __android_log_btwrite) { + int intBuf = 0xDEADBEEF; + ASSERT_LT(0, __android_log_btwrite(0, + EVENT_TYPE_INT, + &intBuf, sizeof(intBuf))); + long long longBuf = 0xDEADBEEFA55A5AA5; + ASSERT_LT(0, __android_log_btwrite(0, + EVENT_TYPE_LONG, + &longBuf, sizeof(longBuf))); + usleep(1000); + char Buf[] = "\20\0\0\0DeAdBeEfA55a5aA5"; + ASSERT_LT(0, __android_log_btwrite(0, + EVENT_TYPE_STRING, + Buf, sizeof(Buf) - 1)); + usleep(1000); +} + +static void* ConcurrentPrintFn(void *arg) { + int ret = __android_log_buf_print(LOG_ID_MAIN, ANDROID_LOG_INFO, + "TEST__android_log_print", "Concurrent %d", + reinterpret_cast<int>(arg)); + return reinterpret_cast<void*>(ret); +} + +#define NUM_CONCURRENT 64 +#define _concurrent_name(a,n) a##__concurrent##n +#define concurrent_name(a,n) _concurrent_name(a,n) + +TEST(liblog, concurrent_name(__android_log_buf_print, NUM_CONCURRENT)) { + pthread_t t[NUM_CONCURRENT]; + int i; + for (i=0; i < NUM_CONCURRENT; i++) { + ASSERT_EQ(0, pthread_create(&t[i], NULL, + ConcurrentPrintFn, + reinterpret_cast<void *>(i))); + } + int ret = 0; + for (i=0; i < NUM_CONCURRENT; i++) { + void* result; + ASSERT_EQ(0, pthread_join(t[i], &result)); + if ((0 == ret) && (0 != reinterpret_cast<int>(result))) { + ret = reinterpret_cast<int>(result); + } + } + ASSERT_LT(0, ret); +} + +TEST(liblog, __android_log_btwrite__android_logger_list_read) { + struct logger_list *logger_list; + + pid_t pid = getpid(); + + ASSERT_EQ(0, NULL == (logger_list = android_logger_list_open( + LOG_ID_EVENTS, O_RDONLY | O_NDELAY, 1000, pid))); + + log_time ts(CLOCK_MONOTONIC); + + ASSERT_LT(0, __android_log_btwrite(0, EVENT_TYPE_LONG, &ts, sizeof(ts))); + usleep(1000000); + + int count = 0; + + for (;;) { + log_msg log_msg; + if (android_logger_list_read(logger_list, &log_msg) <= 0) { + break; + } + + 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; + } + + log_time tx(eventData + 4 + 1); + if (ts == tx) { + ++count; + } + } + + ASSERT_EQ(1, count); + + 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); + + for(int i = LOG_ID_MIN; i < LOG_ID_MAX; ++i) { + log_id_t id = static_cast<log_id_t>(i); + const char *name = android_log_id_to_name(id); + if (id != android_name_to_log_id(name)) { + continue; + } + struct logger * logger; + ASSERT_EQ(0, NULL == (logger = android_logger_open(logger_list, id))); + ASSERT_EQ(id, android_logger_get_id(logger)); + ASSERT_LT(0, android_logger_get_log_size(logger)); + ASSERT_LT(0, android_logger_get_log_readable_size(logger)); + ASSERT_LT(0, android_logger_get_log_version(logger)); + } + + android_logger_list_close(logger_list); +} diff --git a/liblog/uio.c b/liblog/uio.c index cfa4cb1..24a6507 100644 --- a/liblog/uio.c +++ b/liblog/uio.c @@ -1,5 +1,5 @@ /* - * Copyright (C) 2007 The Android Open Source Project + * Copyright (C) 2007-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. @@ -24,8 +24,8 @@ int readv( int fd, struct iovec* vecs, int count ) int total = 0; for ( ; count > 0; count--, vecs++ ) { - const char* buf = vecs->iov_base; - int len = vecs->iov_len; + char* buf = vecs->iov_base; + int len = vecs->iov_len; while (len > 0) { int ret = read( fd, buf, len ); @@ -51,8 +51,8 @@ int writev( int fd, const struct iovec* vecs, int count ) int total = 0; for ( ; count > 0; count--, vecs++ ) { - const char* buf = (const char*)vecs->iov_base; - int len = (int)vecs->iov_len; + const char* buf = vecs->iov_base; + int len = vecs->iov_len; while (len > 0) { int ret = write( fd, buf, len ); |