1 /*
2 * Copyright (C) 2017 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #include <cutils/trace.h>
18
19 #include "trace-dev.inc"
20
21 #include <cutils/sockets.h>
22 #include <sys/stat.h>
23 #include <time.h>
24
25 /**
26 * For tracing in container, tags are written into a socket
27 * instead of ftrace. Additional data is appended so we need extra space.
28 */
29 #define CONTAINER_ATRACE_MESSAGE_LENGTH (ATRACE_MESSAGE_LENGTH + 512)
30
31 static pthread_once_t atrace_once_control = PTHREAD_ONCE_INIT;
32
33 // Variables used for tracing in container with socket.
34 // Note that we need to manually close and reopen socket when Zygote is forking. This requires
35 // writing and closing sockets on multiple threads. A rwlock is used for avoiding concurrent
36 // operation on the file descriptor.
37 static bool atrace_use_container_sock = false;
38 static int atrace_container_sock_fd = -1;
39 static pthread_mutex_t atrace_enabling_mutex = PTHREAD_MUTEX_INITIALIZER;
40 static pthread_rwlock_t atrace_container_sock_rwlock = PTHREAD_RWLOCK_INITIALIZER;
41
atrace_seq_number_changed(uint32_t,uint32_t seq_no)42 static void atrace_seq_number_changed(uint32_t, uint32_t seq_no) {
43 pthread_once(&atrace_once_control, atrace_init_once);
44 atomic_store_explicit(&last_sequence_number, seq_no, memory_order_relaxed);
45 }
46
atrace_init_container_sock()47 static bool atrace_init_container_sock()
48 {
49 pthread_rwlock_wrlock(&atrace_container_sock_rwlock);
50 atrace_container_sock_fd =
51 socket_local_client("trace", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET);
52 if (atrace_container_sock_fd < 0) {
53 ALOGE("Error opening container trace socket: %s (%d)", strerror(errno), errno);
54 }
55 pthread_rwlock_unlock(&atrace_container_sock_rwlock);
56 return atrace_container_sock_fd != -1;
57 }
58
atrace_close_container_sock()59 static void atrace_close_container_sock()
60 {
61 pthread_rwlock_wrlock(&atrace_container_sock_rwlock);
62 if (atrace_container_sock_fd != -1) close(atrace_container_sock_fd);
63 atrace_container_sock_fd = -1;
64 pthread_rwlock_unlock(&atrace_container_sock_rwlock);
65 }
66
67 // Set whether tracing is enabled in this process. This is used to prevent
68 // the Zygote process from tracing. We need to close the socket in the container when tracing is
69 // disabled, and reopen it again after Zygote forking.
atrace_set_tracing_enabled(bool enabled)70 void atrace_set_tracing_enabled(bool enabled)
71 {
72 pthread_mutex_lock(&atrace_enabling_mutex);
73 if (atrace_use_container_sock) {
74 bool already_enabled = atomic_load_explicit(&atrace_is_enabled, memory_order_acquire);
75 if (enabled && !already_enabled) {
76 // Trace was disabled previously. Re-initialize container socket.
77 atrace_init_container_sock();
78 } else if (!enabled && already_enabled) {
79 // Trace was enabled previously. Close container socket.
80 atrace_close_container_sock();
81 }
82 }
83 atomic_store_explicit(&atrace_is_enabled, enabled, memory_order_release);
84 pthread_mutex_unlock(&atrace_enabling_mutex);
85 atrace_update_tags();
86 }
87
atrace_init_once()88 static void atrace_init_once()
89 {
90 atrace_marker_fd = open("/sys/kernel/tracing/trace_marker", O_WRONLY | O_CLOEXEC);
91 if (atrace_marker_fd < 0) {
92 // try debugfs
93 atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC);
94 if (atrace_marker_fd < 0) {
95 // We're in container, ftrace may be disabled. In such case, we use the
96 // socket to write trace event.
97
98 // Protect the initialization of container socket from
99 // atrace_set_tracing_enabled.
100 pthread_mutex_lock(&atrace_enabling_mutex);
101 atrace_use_container_sock = true;
102 bool success = false;
103 if (atomic_load_explicit(&atrace_is_enabled, memory_order_acquire)) {
104 success = atrace_init_container_sock();
105 }
106 pthread_mutex_unlock(&atrace_enabling_mutex);
107
108 if (!success) {
109 atrace_enabled_tags = 0;
110 goto done;
111 }
112 }
113 }
114 atrace_enabled_tags = atrace_get_property();
115
116 done:
117 atomic_store_explicit(&atrace_is_ready, true, memory_order_release);
118 }
119
atrace_setup()120 void atrace_setup()
121 {
122 pthread_once(&atrace_once_control, atrace_init_once);
123 }
124
gettime(clockid_t clk_id)125 static inline uint64_t gettime(clockid_t clk_id)
126 {
127 struct timespec ts;
128 clock_gettime(clk_id, &ts);
129 return ts.tv_sec * 1000000 + ts.tv_nsec / 1000;
130 }
131
132 // Write trace events to container trace file. Note that we need to amend tid and time information
133 // here comparing to normal ftrace, where those informations are added by kernel.
134 #define WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value) { \
135 char buf[CONTAINER_ATRACE_MESSAGE_LENGTH]; \
136 int pid = getpid(); \
137 int tid = gettid(); \
138 uint64_t ts = gettime(CLOCK_MONOTONIC); \
139 uint64_t tts = gettime(CLOCK_THREAD_CPUTIME_ID); \
140 int len = snprintf( \
141 buf, sizeof(buf), \
142 ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s" value_format, \
143 pid, tid, ts, tts, name, value); \
144 if (len >= (int) sizeof(buf)) { \
145 int name_len = strlen(name) - (len - sizeof(buf)) - 1; \
146 /* Truncate the name to make the message fit. */ \
147 if (name_len > 0) { \
148 ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \
149 len = snprintf( \
150 buf, sizeof(buf), \
151 ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%.*s" value_format, \
152 pid, tid, ts, tts, name_len, name, value); \
153 } else { \
154 /* Data is still too long. Drop it. */ \
155 ALOGW("Data is too long in %s: %s\n", __FUNCTION__, name); \
156 len = 0; \
157 } \
158 } \
159 if (len > 0) { \
160 write(atrace_container_sock_fd, buf, len); \
161 } \
162 }
163
164 #define WRITE_MSG_IN_CONTAINER(ph, sep_before_name, value_format, name, value) { \
165 pthread_rwlock_rdlock(&atrace_container_sock_rwlock); \
166 if (atrace_container_sock_fd != -1) { \
167 WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value); \
168 } \
169 pthread_rwlock_unlock(&atrace_container_sock_rwlock); \
170 }
171
atrace_begin_body(const char * name)172 void atrace_begin_body(const char* name)
173 {
174 if (CC_LIKELY(atrace_use_container_sock)) {
175 WRITE_MSG_IN_CONTAINER("B", "|", "%s", name, "");
176 return;
177 }
178
179 if (atrace_marker_fd < 0) return;
180
181 WRITE_MSG("B|%d|", "%s", name, "");
182 }
183
atrace_end_body()184 void atrace_end_body()
185 {
186 if (CC_LIKELY(atrace_use_container_sock)) {
187 WRITE_MSG_IN_CONTAINER("E", "", "%s", "", "");
188 return;
189 }
190
191 if (atrace_marker_fd < 0) return;
192
193 WRITE_MSG("E|%d", "%s", "", "");
194 }
195
atrace_async_begin_body(const char * name,int32_t cookie)196 void atrace_async_begin_body(const char* name, int32_t cookie)
197 {
198 if (CC_LIKELY(atrace_use_container_sock)) {
199 WRITE_MSG_IN_CONTAINER("S", "|", "|%d", name, cookie);
200 return;
201 }
202
203 if (atrace_marker_fd < 0) return;
204
205 WRITE_MSG("S|%d|", "|%" PRId32, name, cookie);
206 }
207
atrace_async_end_body(const char * name,int32_t cookie)208 void atrace_async_end_body(const char* name, int32_t cookie)
209 {
210 if (CC_LIKELY(atrace_use_container_sock)) {
211 WRITE_MSG_IN_CONTAINER("F", "|", "|%d", name, cookie);
212 return;
213 }
214
215 if (atrace_marker_fd < 0) return;
216
217 WRITE_MSG("F|%d|", "|%" PRId32, name, cookie);
218 }
219
atrace_int_body(const char * name,int32_t value)220 void atrace_int_body(const char* name, int32_t value)
221 {
222 if (CC_LIKELY(atrace_use_container_sock)) {
223 WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId32, name, value);
224 return;
225 }
226
227 if (atrace_marker_fd < 0) return;
228
229 WRITE_MSG("C|%d|", "|%" PRId32, name, value);
230 }
231
atrace_int64_body(const char * name,int64_t value)232 void atrace_int64_body(const char* name, int64_t value)
233 {
234 if (CC_LIKELY(atrace_use_container_sock)) {
235 WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId64, name, value);
236 return;
237 }
238
239 if (atrace_marker_fd < 0) return;
240
241 WRITE_MSG("C|%d|", "|%" PRId64, name, value);
242 }
243