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_init_container_sock()42 static bool atrace_init_container_sock()
43 {
44 pthread_rwlock_wrlock(&atrace_container_sock_rwlock);
45 atrace_container_sock_fd =
46 socket_local_client("trace", ANDROID_SOCKET_NAMESPACE_RESERVED, SOCK_SEQPACKET);
47 if (atrace_container_sock_fd < 0) {
48 ALOGE("Error opening container trace socket: %s (%d)", strerror(errno), errno);
49 }
50 pthread_rwlock_unlock(&atrace_container_sock_rwlock);
51 return atrace_container_sock_fd != -1;
52 }
53
atrace_close_container_sock()54 static void atrace_close_container_sock()
55 {
56 pthread_rwlock_wrlock(&atrace_container_sock_rwlock);
57 if (atrace_container_sock_fd != -1) close(atrace_container_sock_fd);
58 atrace_container_sock_fd = -1;
59 pthread_rwlock_unlock(&atrace_container_sock_rwlock);
60 }
61
62 // Set whether tracing is enabled in this process. This is used to prevent
63 // the Zygote process from tracing. We need to close the socket in the container when tracing is
64 // disabled, and reopen it again after Zygote forking.
atrace_set_tracing_enabled(bool enabled)65 void atrace_set_tracing_enabled(bool enabled)
66 {
67 pthread_mutex_lock(&atrace_enabling_mutex);
68 if (atrace_use_container_sock) {
69 bool already_enabled = atomic_load_explicit(&atrace_is_enabled, memory_order_acquire);
70 if (enabled && !already_enabled) {
71 // Trace was disabled previously. Re-initialize container socket.
72 atrace_init_container_sock();
73 } else if (!enabled && already_enabled) {
74 // Trace was enabled previously. Close container socket.
75 atrace_close_container_sock();
76 }
77 }
78 atomic_store_explicit(&atrace_is_enabled, enabled, memory_order_release);
79 pthread_mutex_unlock(&atrace_enabling_mutex);
80 atrace_update_tags();
81 }
82
atrace_init_once()83 static void atrace_init_once()
84 {
85 atrace_marker_fd = open("/sys/kernel/debug/tracing/trace_marker", O_WRONLY | O_CLOEXEC);
86 if (atrace_marker_fd < 0) {
87 // We're in container, ftrace may be disabled. In such case, we use the
88 // socket to write trace event.
89
90 // Protect the initialization of container socket from
91 // atrace_set_tracing_enabled.
92 pthread_mutex_lock(&atrace_enabling_mutex);
93 atrace_use_container_sock = true;
94 bool success = false;
95 if (atomic_load_explicit(&atrace_is_enabled, memory_order_acquire)) {
96 success = atrace_init_container_sock();
97 }
98 pthread_mutex_unlock(&atrace_enabling_mutex);
99
100 if (!success) {
101 atrace_enabled_tags = 0;
102 goto done;
103 }
104 }
105 atrace_enabled_tags = atrace_get_property();
106
107 done:
108 atomic_store_explicit(&atrace_is_ready, true, memory_order_release);
109 }
110
atrace_setup()111 void atrace_setup()
112 {
113 pthread_once(&atrace_once_control, atrace_init_once);
114 }
115
gettime(clockid_t clk_id)116 static inline uint64_t gettime(clockid_t clk_id)
117 {
118 struct timespec ts;
119 clock_gettime(clk_id, &ts);
120 return ts.tv_sec * 1000000 + ts.tv_nsec / 1000;
121 }
122
123 // Write trace events to container trace file. Note that we need to amend tid and time information
124 // here comparing to normal ftrace, where those informations are added by kernel.
125 #define WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value) { \
126 char buf[CONTAINER_ATRACE_MESSAGE_LENGTH]; \
127 int pid = getpid(); \
128 int tid = gettid(); \
129 uint64_t ts = gettime(CLOCK_MONOTONIC); \
130 uint64_t tts = gettime(CLOCK_THREAD_CPUTIME_ID); \
131 int len = snprintf( \
132 buf, sizeof(buf), \
133 ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s" value_format, \
134 pid, tid, ts, tts, name, value); \
135 if (len >= (int) sizeof(buf)) { \
136 int name_len = strlen(name) - (len - sizeof(buf)) - 1; \
137 /* Truncate the name to make the message fit. */ \
138 if (name_len > 0) { \
139 ALOGW("Truncated name in %s: %s\n", __FUNCTION__, name); \
140 len = snprintf( \
141 buf, sizeof(buf), \
142 ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%.*s" value_format, \
143 pid, tid, ts, tts, name_len, name, value); \
144 } else { \
145 /* Data is still too long. Drop it. */ \
146 ALOGW("Data is too long in %s: %s\n", __FUNCTION__, name); \
147 len = 0; \
148 } \
149 } \
150 if (len > 0) { \
151 write(atrace_container_sock_fd, buf, len); \
152 } \
153 }
154
155 #define WRITE_MSG_IN_CONTAINER(ph, sep_before_name, value_format, name, value) { \
156 pthread_rwlock_rdlock(&atrace_container_sock_rwlock); \
157 if (atrace_container_sock_fd != -1) { \
158 WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, name, value); \
159 } \
160 pthread_rwlock_unlock(&atrace_container_sock_rwlock); \
161 }
162
atrace_begin_body(const char * name)163 void atrace_begin_body(const char* name)
164 {
165 if (CC_LIKELY(atrace_use_container_sock)) {
166 WRITE_MSG_IN_CONTAINER("B", "|", "%s", name, "");
167 return;
168 }
169
170 if (atrace_marker_fd < 0) return;
171
172 WRITE_MSG("B|%d|", "%s", name, "");
173 }
174
atrace_end_body()175 void atrace_end_body()
176 {
177 if (CC_LIKELY(atrace_use_container_sock)) {
178 WRITE_MSG_IN_CONTAINER("E", "", "%s", "", "");
179 return;
180 }
181
182 if (atrace_marker_fd < 0) return;
183
184 WRITE_MSG("E|%d", "%s", "", "");
185 }
186
atrace_async_begin_body(const char * name,int32_t cookie)187 void atrace_async_begin_body(const char* name, int32_t cookie)
188 {
189 if (CC_LIKELY(atrace_use_container_sock)) {
190 WRITE_MSG_IN_CONTAINER("S", "|", "|%d", name, cookie);
191 return;
192 }
193
194 if (atrace_marker_fd < 0) return;
195
196 WRITE_MSG("S|%d|", "|%" PRId32, name, cookie);
197 }
198
atrace_async_end_body(const char * name,int32_t cookie)199 void atrace_async_end_body(const char* name, int32_t cookie)
200 {
201 if (CC_LIKELY(atrace_use_container_sock)) {
202 WRITE_MSG_IN_CONTAINER("F", "|", "|%d", name, cookie);
203 return;
204 }
205
206 if (atrace_marker_fd < 0) return;
207
208 WRITE_MSG("F|%d|", "|%" PRId32, name, cookie);
209 }
210
atrace_int_body(const char * name,int32_t value)211 void atrace_int_body(const char* name, int32_t value)
212 {
213 if (CC_LIKELY(atrace_use_container_sock)) {
214 WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId32, name, value);
215 return;
216 }
217
218 if (atrace_marker_fd < 0) return;
219
220 WRITE_MSG("C|%d|", "|%" PRId32, name, value);
221 }
222
atrace_int64_body(const char * name,int64_t value)223 void atrace_int64_body(const char* name, int64_t value)
224 {
225 if (CC_LIKELY(atrace_use_container_sock)) {
226 WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId64, name, value);
227 return;
228 }
229
230 if (atrace_marker_fd < 0) return;
231
232 WRITE_MSG("C|%d|", "|%" PRId64, name, value);
233 }
234