Merge "libcutils: write trace event into socket in container" am: 59b33cb01c am: 08d9cc3744 (9435b3ed) · Commits · e / os / android_system_core

libcutils/trace-container.c

0 → 100644

+231 −0

Original line number	Diff line number	Diff line
		/*
		* 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 <cutils/sockets.h>
		#include <sys/stat.h>
		#include <time.h>

		/**
		* 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);
		}

libcutils/trace-dev.c

+8 −165

Original line number	Diff line number	Diff line
		@@ -14,47 +14,9 @@
		* limitations under the License.
		*/

		#define LOG_TAG "cutils-trace"
		#include "trace-dev.inc"

		#include <errno.h>
		#include <fcntl.h>
		#include <limits.h>
		#include <pthread.h>
		#include <stdatomic.h>
		#include <stdbool.h>
		#include <stdlib.h>
		#include <string.h>
		#include <sys/types.h>

		#include <cutils/compiler.h>
		#include <cutils/properties.h>
		#include <cutils/trace.h>
		#include <log/log.h>
		#include <log/log_properties.h>

		/**
		* 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();
		}

		// 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);
		}

libcutils/trace-dev.inc

0 → 100644

+173 −0

Original line number	Diff line number	Diff line
		/*
		* 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 <errno.h>
		#include <fcntl.h>
		#include <limits.h>
		#include <pthread.h>
		#include <stdatomic.h>
		#include <stdbool.h>
		#include <stdlib.h>
		#include <string.h>
		#include <sys/types.h>

		#include <cutils/compiler.h>
		#include <cutils/properties.h>
		#include <cutils/trace.h>
		#include <log/log.h>
		#include <log/log_properties.h>

		/**
		* 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