diff --git a/libcutils/trace-container.c b/libcutils/trace-container.c new file mode 100644 index 000000000..03e91b1f2 --- /dev/null +++ b/libcutils/trace-container.c @@ -0,0 +1,231 @@ +/* + * Copyright (C) 2017 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 "trace-dev.inc" + +#include +#include +#include + +/** + * For tracing in container, tags are written into a socket + * instead of ftrace. Additional data is appended so we need extra space. + */ +#define CONTAINER_ATRACE_MESSAGE_LENGTH (ATRACE_MESSAGE_LENGTH + 512) + +static pthread_once_t atrace_once_control = PTHREAD_ONCE_INIT; + +// Variables used for tracing in container with socket. +// Note that we need to manually close and reopen socket when Zygote is forking. This requires +// writing and closing sockets on multiple threads. A rwlock is used for avoiding concurrent +// operation on the file descriptor. +static bool atrace_use_container_sock = false; +static int atrace_container_sock_fd = -1; +static pthread_mutex_t atrace_enabling_mutex = PTHREAD_MUTEX_INITIALIZER; +static pthread_rwlock_t atrace_container_sock_rwlock = PTHREAD_RWLOCK_INITIALIZER; + +static bool atrace_init_container_sock() +{ + pthread_rwlock_wrlock(&atrace_container_sock_rwlock); + atrace_container_sock_fd = + socket_local_client("trace", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET); + if (atrace_container_sock_fd < 0) { + ALOGE("Error opening container trace socket: %s (%d)", strerror(errno), errno); + } + pthread_rwlock_unlock(&atrace_container_sock_rwlock); + return atrace_container_sock_fd != -1; +} + +static void atrace_close_container_sock() +{ + pthread_rwlock_wrlock(&atrace_container_sock_rwlock); + if (atrace_container_sock_fd != -1) close(atrace_container_sock_fd); + atrace_container_sock_fd = -1; + pthread_rwlock_unlock(&atrace_container_sock_rwlock); +} + +// Set whether tracing is enabled in this process. This is used to prevent +// the Zygote process from tracing. We need to close the socket in the container when tracing is +// disabled, and reopen it again after Zygote forking. +void atrace_set_tracing_enabled(bool enabled) +{ + pthread_mutex_lock(&atrace_enabling_mutex); + if (atrace_use_container_sock) { + bool already_enabled = atomic_load_explicit(&atrace_is_enabled, memory_order_acquire); + if (enabled && !already_enabled) { + // Trace was disabled previously. Re-initialize container socket. + atrace_init_container_sock(); + } else if (!enabled && already_enabled) { + // Trace was enabled previously. Close container socket. + atrace_close_container_sock(); + } + } + atomic_store_explicit(&atrace_is_enabled, enabled, memory_order_release); + pthread_mutex_unlock(&atrace_enabling_mutex); + atrace_update_tags(); +} + +static void atrace_init_once() +{ + atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC); + if (atrace_marker_fd < 0) { + // We're in container, ftrace may be disabled. In such case, we use the + // socket to write trace event. + + // Protect the initialization of container socket from + // atrace_set_tracing_enabled. + pthread_mutex_lock(&atrace_enabling_mutex); + atrace_use_container_sock = true; + bool success = false; + if (atomic_load_explicit(&atrace_is_enabled, memory_order_acquire)) { + success = atrace_init_container_sock(); + } + pthread_mutex_unlock(&atrace_enabling_mutex); + + if (!success) { + atrace_enabled_tags = 0; + goto done; + } + } + atrace_enabled_tags = atrace_get_property(); + +done: + atomic_store_explicit(&atrace_is_ready, true, memory_order_release); +} + +void atrace_setup() +{ + pthread_once(&atrace_once_control, atrace_init_once); +} + +static inline uint64_t gettime(clockid_t clk_id) +{ + struct timespec ts; + clock_gettime(clk_id, &ts); + return ts.tv_sec * 1000000 + ts.tv_nsec / 1000; +} + +// Write trace events to container trace file. Note that we need to amend tid and time information +// here comparing to normal ftrace, where those informations are added by kernel. +#define WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value) { \ + char buf[CONTAINER_ATRACE_MESSAGE_LENGTH]; \ + int pid = getpid(); \ + int tid = gettid(); \ + uint64_t ts = gettime(CLOCK_MONOTONIC); \ + uint64_t tts = gettime(CLOCK_THREAD_CPUTIME_ID); \ + int len = snprintf( \ + buf, sizeof(buf), \ + ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s" value_format, \ + pid, tid, ts, tts, name, value); \ + if (len >= (int) sizeof(buf)) { \ + int name_len = strlen(name) - (len - sizeof(buf)) - 1; \ + /* Truncate the name to make the message fit. */ \ + if (name_len > 0) { \ + ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \ + len = snprintf( \ + buf, sizeof(buf), \ + ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%.*s" value_format, \ + pid, tid, ts, tts, name_len, name, value); \ + } else { \ + /* Data is still too long. Drop it. */ \ + ALOGW("Data is too long in %s: %s\n", __FUNCTION__, name); \ + len = 0; \ + } \ + } \ + if (len > 0) { \ + write(atrace_container_sock_fd, buf, len); \ + } \ +} + +#define WRITE_MSG_IN_CONTAINER(ph, sep_before_name, value_format, name, value) { \ + pthread_rwlock_rdlock(&atrace_container_sock_rwlock); \ + if (atrace_container_sock_fd != -1) { \ + WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value); \ + } \ + pthread_rwlock_unlock(&atrace_container_sock_rwlock); \ +} + +void atrace_begin_body(const char* name) +{ + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("B", "|", "%s", name, ""); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("B|%d|", "%s", name, ""); +} + +void atrace_end_body() +{ + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("E", "", "%s", "", ""); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("E|%d", "%s", "", ""); +} + +void atrace_async_begin_body(const char* name, int32_t cookie) +{ + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("S", "|", "|%d", name, cookie); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("S|%d|", "|%" PRId32, name, cookie); +} + +void atrace_async_end_body(const char* name, int32_t cookie) +{ + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("F", "|", "|%d", name, cookie); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("F|%d|", "|%" PRId32, name, cookie); +} + +void atrace_int_body(const char* name, int32_t value) +{ + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId32, name, value); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("C|%d|", "|%" PRId32, name, value); +} + +void atrace_int64_body(const char* name, int64_t value) +{ + if (CC_LIKELY(atrace_use_container_sock)) { + WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId64, name, value); + return; + } + + if (atrace_marker_fd < 0) return; + + WRITE_MSG("C|%d|", "|%" PRId64, name, value); +} diff --git a/libcutils/trace-dev.c b/libcutils/trace-dev.c index d45e5a98e..4468e83f6 100644 --- a/libcutils/trace-dev.c +++ b/libcutils/trace-dev.c @@ -14,47 +14,9 @@ * limitations under the License. */ -#define LOG_TAG "cutils-trace" +#include "trace-dev.inc" -#include -#include -#include -#include -#include -#include -#include -#include -#include - -#include -#include -#include -#include -#include - -/** - * Maximum size of a message that can be logged to the trace buffer. - * Note this message includes a tag, the pid, and the string given as the name. - * Names should be kept short to get the most use of the trace buffer. - */ -#define ATRACE_MESSAGE_LENGTH 1024 - -atomic_bool atrace_is_ready = ATOMIC_VAR_INIT(false); -int atrace_marker_fd = -1; -uint64_t atrace_enabled_tags = ATRACE_TAG_NOT_READY; -static bool atrace_is_debuggable = false; -static atomic_bool atrace_is_enabled = ATOMIC_VAR_INIT(true); -static pthread_once_t atrace_once_control = PTHREAD_ONCE_INIT; -static pthread_mutex_t atrace_tags_mutex = PTHREAD_MUTEX_INITIALIZER; - -// Set whether this process is debuggable, which determines whether -// application-level tracing is allowed when the ro.debuggable system property -// is not set to '1'. -void atrace_set_debuggable(bool debuggable) -{ - atrace_is_debuggable = debuggable; - atrace_update_tags(); -} +static pthread_once_t atrace_once_control = PTHREAD_ONCE_INIT; // Set whether tracing is enabled in this process. This is used to prevent // the Zygote process from tracing. @@ -64,101 +26,6 @@ void atrace_set_tracing_enabled(bool enabled) atrace_update_tags(); } -// Check whether the given command line matches one of the comma-separated -// values listed in the app_cmdlines property. -static bool atrace_is_cmdline_match(const char* cmdline) -{ - int count = property_get_int32("debug.atrace.app_number", 0); - - char buf[PROPERTY_KEY_MAX]; - char value[PROPERTY_VALUE_MAX]; - - for (int i = 0; i < count; i++) { - snprintf(buf, sizeof(buf), "debug.atrace.app_%d", i); - property_get(buf, value, ""); - if (strcmp(value, cmdline) == 0) { - return true; - } - } - - return false; -} - -// Determine whether application-level tracing is enabled for this process. -static bool atrace_is_app_tracing_enabled() -{ - bool sys_debuggable = __android_log_is_debuggable(); - bool result = false; - - if (sys_debuggable || atrace_is_debuggable) { - // Check whether tracing is enabled for this process. - FILE * file = fopen("/proc/self/cmdline", "re"); - if (file) { - char cmdline[4096]; - if (fgets(cmdline, sizeof(cmdline), file)) { - result = atrace_is_cmdline_match(cmdline); - } else { - ALOGE("Error reading cmdline: %s (%d)", strerror(errno), errno); - } - fclose(file); - } else { - ALOGE("Error opening /proc/self/cmdline: %s (%d)", strerror(errno), - errno); - } - } - - return result; -} - -// Read the sysprop and return the value tags should be set to -static uint64_t atrace_get_property() -{ - char value[PROPERTY_VALUE_MAX]; - char *endptr; - uint64_t tags; - - property_get("debug.atrace.tags.enableflags", value, "0"); - errno = 0; - tags = strtoull(value, &endptr, 0); - if (value[0] == '\0' || *endptr != '\0') { - ALOGE("Error parsing trace property: Not a number: %s", value); - return 0; - } else if (errno == ERANGE || tags == ULLONG_MAX) { - ALOGE("Error parsing trace property: Number too large: %s", value); - return 0; - } - - // Only set the "app" tag if this process was selected for app-level debug - // tracing. - if (atrace_is_app_tracing_enabled()) { - tags |= ATRACE_TAG_APP; - } else { - tags &= ~ATRACE_TAG_APP; - } - - return (tags | ATRACE_TAG_ALWAYS) & ATRACE_TAG_VALID_MASK; -} - -// Update tags if tracing is ready. Useful as a sysprop change callback. -void atrace_update_tags() -{ - uint64_t tags; - if (CC_UNLIKELY(atomic_load_explicit(&atrace_is_ready, memory_order_acquire))) { - if (atomic_load_explicit(&atrace_is_enabled, memory_order_acquire)) { - tags = atrace_get_property(); - pthread_mutex_lock(&atrace_tags_mutex); - atrace_enabled_tags = tags; - pthread_mutex_unlock(&atrace_tags_mutex); - } else { - // Tracing is disabled for this process, so we simply don't - // initialize the tags. - pthread_mutex_lock(&atrace_tags_mutex); - atrace_enabled_tags = ATRACE_TAG_NOT_READY; - pthread_mutex_unlock(&atrace_tags_mutex); - } - } -} - static void atrace_init_once() { atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC); @@ -181,54 +48,30 @@ void atrace_setup() void atrace_begin_body(const char* name) { - char buf[ATRACE_MESSAGE_LENGTH]; - - int len = snprintf(buf, sizeof(buf), "B|%d|%s", getpid(), name); - if (len >= (int) sizeof(buf)) { - ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); - len = sizeof(buf) - 1; - } - write(atrace_marker_fd, buf, len); + WRITE_MSG("B|%d|", "%s", name, ""); } void atrace_end_body() { - char c = 'E'; - write(atrace_marker_fd, &c, 1); -} - -#define WRITE_MSG(format_begin, format_end, pid, name, value) { \ - char buf[ATRACE_MESSAGE_LENGTH]; \ - int len = snprintf(buf, sizeof(buf), format_begin "%s" format_end, pid, \ - name, value); \ - if (len >= (int) sizeof(buf)) { \ - /* Given the sizeof(buf), and all of the current format buffers, \ - * it is impossible for name_len to be < 0 if len >= sizeof(buf). */ \ - int name_len = strlen(name) - (len - sizeof(buf)) - 1; \ - /* Truncate the name to make the message fit. */ \ - ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \ - len = snprintf(buf, sizeof(buf), format_begin "%.*s" format_end, pid, \ - name_len, name, value); \ - } \ - write(atrace_marker_fd, buf, len); \ + WRITE_MSG("E|%d", "%s", "", ""); } void atrace_async_begin_body(const char* name, int32_t cookie) { - WRITE_MSG("S|%d|", "|%" PRId32, getpid(), name, cookie); + WRITE_MSG("S|%d|", "|%" PRId32, name, cookie); } void atrace_async_end_body(const char* name, int32_t cookie) { - WRITE_MSG("F|%d|", "|%" PRId32, getpid(), name, cookie); + WRITE_MSG("F|%d|", "|%" PRId32, name, cookie); } void atrace_int_body(const char* name, int32_t value) { - WRITE_MSG("C|%d|", "|%" PRId32, getpid(), name, value); + WRITE_MSG("C|%d|", "|%" PRId32, name, value); } void atrace_int64_body(const char* name, int64_t value) { - WRITE_MSG("C|%d|", "|%" PRId64, getpid(), name, value); + WRITE_MSG("C|%d|", "|%" PRId64, name, value); } diff --git a/libcutils/trace-dev.inc b/libcutils/trace-dev.inc new file mode 100644 index 000000000..f32330a4c --- /dev/null +++ b/libcutils/trace-dev.inc @@ -0,0 +1,173 @@ +/* + * Copyright (C) 2017 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. + */ + +#ifndef __TRACE_DEV_INC +#define __TRACE_DEV_INC + +#define LOG_TAG "cutils-trace" + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include + +/** + * Maximum size of a message that can be logged to the trace buffer. + * Note this message includes a tag, the pid, and the string given as the name. + * Names should be kept short to get the most use of the trace buffer. + */ +#define ATRACE_MESSAGE_LENGTH 1024 + +atomic_bool atrace_is_ready = ATOMIC_VAR_INIT(false); +int atrace_marker_fd = -1; +uint64_t atrace_enabled_tags = ATRACE_TAG_NOT_READY; +static bool atrace_is_debuggable = false; +static atomic_bool atrace_is_enabled = ATOMIC_VAR_INIT(true); +static pthread_mutex_t atrace_tags_mutex = PTHREAD_MUTEX_INITIALIZER; + +// Set whether this process is debuggable, which determines whether +// application-level tracing is allowed when the ro.debuggable system property +// is not set to '1'. +void atrace_set_debuggable(bool debuggable) +{ + atrace_is_debuggable = debuggable; + atrace_update_tags(); +} + +// Check whether the given command line matches one of the comma-separated +// values listed in the app_cmdlines property. +static bool atrace_is_cmdline_match(const char* cmdline) +{ + int count = property_get_int32("debug.atrace.app_number", 0); + + char buf[PROPERTY_KEY_MAX]; + char value[PROPERTY_VALUE_MAX]; + + for (int i = 0; i < count; i++) { + snprintf(buf, sizeof(buf), "debug.atrace.app_%d", i); + property_get(buf, value, ""); + if (strcmp(value, cmdline) == 0) { + return true; + } + } + + return false; +} + +// Determine whether application-level tracing is enabled for this process. +static bool atrace_is_app_tracing_enabled() +{ + bool sys_debuggable = __android_log_is_debuggable(); + bool result = false; + + if (sys_debuggable || atrace_is_debuggable) { + // Check whether tracing is enabled for this process. + FILE * file = fopen("/proc/self/cmdline", "re"); + if (file) { + char cmdline[4096]; + if (fgets(cmdline, sizeof(cmdline), file)) { + result = atrace_is_cmdline_match(cmdline); + } else { + ALOGE("Error reading cmdline: %s (%d)", strerror(errno), errno); + } + fclose(file); + } else { + ALOGE("Error opening /proc/self/cmdline: %s (%d)", strerror(errno), + errno); + } + } + + return result; +} + +// Read the sysprop and return the value tags should be set to +static uint64_t atrace_get_property() +{ + char value[PROPERTY_VALUE_MAX]; + char *endptr; + uint64_t tags; + + property_get("debug.atrace.tags.enableflags", value, "0"); + errno = 0; + tags = strtoull(value, &endptr, 0); + if (value[0] == '\0' || *endptr != '\0') { + ALOGE("Error parsing trace property: Not a number: %s", value); + return 0; + } else if (errno == ERANGE || tags == ULLONG_MAX) { + ALOGE("Error parsing trace property: Number too large: %s", value); + return 0; + } + + // Only set the "app" tag if this process was selected for app-level debug + // tracing. + if (atrace_is_app_tracing_enabled()) { + tags |= ATRACE_TAG_APP; + } else { + tags &= ~ATRACE_TAG_APP; + } + + return (tags | ATRACE_TAG_ALWAYS) & ATRACE_TAG_VALID_MASK; +} + +// Update tags if tracing is ready. Useful as a sysprop change callback. +void atrace_update_tags() +{ + uint64_t tags; + if (CC_UNLIKELY(atomic_load_explicit(&atrace_is_ready, memory_order_acquire))) { + if (atomic_load_explicit(&atrace_is_enabled, memory_order_acquire)) { + tags = atrace_get_property(); + pthread_mutex_lock(&atrace_tags_mutex); + atrace_enabled_tags = tags; + pthread_mutex_unlock(&atrace_tags_mutex); + } else { + // Tracing is disabled for this process, so we simply don't + // initialize the tags. + pthread_mutex_lock(&atrace_tags_mutex); + atrace_enabled_tags = ATRACE_TAG_NOT_READY; + pthread_mutex_unlock(&atrace_tags_mutex); + } + } +} + +#define WRITE_MSG(format_begin, format_end, name, value) { \ + char buf[ATRACE_MESSAGE_LENGTH]; \ + int pid = getpid(); \ + int len = snprintf(buf, sizeof(buf), format_begin "%s" format_end, pid, \ + name, value); \ + if (len >= (int) sizeof(buf)) { \ + /* Given the sizeof(buf), and all of the current format buffers, \ + * it is impossible for name_len to be < 0 if len >= sizeof(buf). */ \ + int name_len = strlen(name) - (len - sizeof(buf)) - 1; \ + /* Truncate the name to make the message fit. */ \ + ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \ + len = snprintf(buf, sizeof(buf), format_begin "%.*s" format_end, pid, \ + name_len, name, value); \ + } \ + write(atrace_marker_fd, buf, len); \ +} + +#endif // __TRACE_DEV_INC