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, \
135         track_name, name, value) { \
136     char buf[CONTAINER_ATRACE_MESSAGE_LENGTH]; \
137     const char* track_name_sep = track_name[0] != '\0' ? "|" : ""; \
138     int pid = getpid(); \
139     int tid = gettid(); \
140     uint64_t ts = gettime(CLOCK_MONOTONIC); \
141     uint64_t tts = gettime(CLOCK_THREAD_CPUTIME_ID); \
142     int len = snprintf( \
143             buf, sizeof(buf), \
144             ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s%s%s" value_format, \
145             pid, tid, ts, tts, track_name, track_name_sep, name, value); \
146     if (len >= (int) sizeof(buf)) { \
147         int name_len = strlen(name) - (len - sizeof(buf)) - 1; \
148         /* Truncate the name to make the message fit. */ \
149         if (name_len > 0) { \
150             len = snprintf( \
151                 buf, sizeof(buf), \
152                 ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%s%s%.*s" value_format, \
153                 pid, tid, ts, tts, track_name, track_name_sep, name_len, name, value); \
154         } else { \
155             int track_name_len = 0; \
156             if (track_name[0] != '\0') { \
157                 track_name_len = strlen(track_name) - (len - strlen(name) - sizeof(buf)) - 2; \
158             } \
159             if (track_name_len <= 0){ \
160                 /* Data is still too long. Drop it. */ \
161                 len = 0; \
162             } else { \
163                 /* Truncate the trackName and name to make the message fit. */ \
164                 len = snprintf( \
165                     buf, sizeof(buf), \
166                     ph "|%d|%d|%" PRIu64 "|%" PRIu64 sep_before_name "%.*s|%.1s" value_format, \
167                     pid, tid, ts, tts, track_name_len, track_name, name, value); \
168             } \
169         } \
170     } \
171     if (len > 0) { \
172         write(atrace_container_sock_fd, buf, len); \
173     } \
174 }
175 
176 #define WRITE_MSG_IN_CONTAINER(ph, sep_before_name, value_format, track_name, name, value) { \
177     pthread_rwlock_rdlock(&atrace_container_sock_rwlock); \
178     if (atrace_container_sock_fd != -1) { \
179        WRITE_MSG_IN_CONTAINER_LOCKED(ph, sep_before_name, value_format, track_name, name, value); \
180     } \
181     pthread_rwlock_unlock(&atrace_container_sock_rwlock); \
182 }
183 
atrace_begin_body(const char * name)184 void atrace_begin_body(const char* name)
185 {
186     if (CC_LIKELY(atrace_use_container_sock)) {
187         WRITE_MSG_IN_CONTAINER("B", "|", "%s", "", name, "");
188         return;
189     }
190 
191     if (atrace_marker_fd < 0) return;
192 
193     WRITE_MSG("B|%d|", "%s", "", name, "");
194 }
195 
atrace_end_body()196 void atrace_end_body()
197 {
198     if (CC_LIKELY(atrace_use_container_sock)) {
199         WRITE_MSG_IN_CONTAINER("E", "", "%s", "", "", "");
200         return;
201     }
202 
203     if (atrace_marker_fd < 0) return;
204 
205     WRITE_MSG("E|%d", "%s", "", "", "");
206 }
207 
atrace_async_begin_body(const char * name,int32_t cookie)208 void atrace_async_begin_body(const char* name, int32_t cookie)
209 {
210     if (CC_LIKELY(atrace_use_container_sock)) {
211         WRITE_MSG_IN_CONTAINER("S", "|", "|%d", "", name, cookie);
212         return;
213     }
214 
215     if (atrace_marker_fd < 0) return;
216 
217     WRITE_MSG("S|%d|", "|%" PRId32, "", name, cookie);
218 }
219 
atrace_async_end_body(const char * name,int32_t cookie)220 void atrace_async_end_body(const char* name, int32_t cookie)
221 {
222     if (CC_LIKELY(atrace_use_container_sock)) {
223         WRITE_MSG_IN_CONTAINER("F", "|", "|%d", "", name, cookie);
224         return;
225     }
226 
227     if (atrace_marker_fd < 0) return;
228 
229     WRITE_MSG("F|%d|", "|%" PRId32, "", name, cookie);
230 }
231 
atrace_async_for_track_begin_body(const char * track_name,const char * name,int32_t cookie)232 void atrace_async_for_track_begin_body(const char* track_name, const char* name, int32_t cookie) {
233     if (CC_LIKELY(atrace_use_container_sock)) {
234         WRITE_MSG_IN_CONTAINER("G", "|", "|%d", track_name, name, cookie);
235         return;
236     }
237 
238     if (atrace_marker_fd < 0) return;
239 
240     WRITE_MSG("G|%d|", "|%" PRId32, track_name, name, cookie);
241 }
242 
atrace_async_for_track_end_body(const char * track_name,int32_t cookie)243 void atrace_async_for_track_end_body(const char* track_name, int32_t cookie) {
244     if (CC_LIKELY(atrace_use_container_sock)) {
245         WRITE_MSG_IN_CONTAINER("H", "|", "|%d", "", track_name, cookie);
246         return;
247     }
248 
249     if (atrace_marker_fd < 0) return;
250 
251     WRITE_MSG("H|%d|", "|%" PRId32, "", track_name, cookie);
252 }
253 
atrace_instant_body(const char * name)254 void atrace_instant_body(const char* name) {
255     if (CC_LIKELY(atrace_use_container_sock)) {
256         WRITE_MSG_IN_CONTAINER("I", "|", "%s", "", name, "");
257         return;
258     }
259 
260     if (atrace_marker_fd < 0) return;
261 
262     WRITE_MSG("I|%d|", "%s", "", name, "");
263 }
264 
atrace_instant_for_track_body(const char * track_name,const char * name)265 void atrace_instant_for_track_body(const char* track_name, const char* name) {
266     if (CC_LIKELY(atrace_use_container_sock)) {
267         WRITE_MSG_IN_CONTAINER("N", "|", "%s", track_name, name, "");
268         return;
269     }
270 
271     if (atrace_marker_fd < 0) return;
272 
273     WRITE_MSG("N|%d|", "%s", track_name, name, "");
274 }
275 
atrace_int_body(const char * name,int32_t value)276 void atrace_int_body(const char* name, int32_t value)
277 {
278     if (CC_LIKELY(atrace_use_container_sock)) {
279         WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId32, "", name, value);
280         return;
281     }
282 
283     if (atrace_marker_fd < 0) return;
284 
285     WRITE_MSG("C|%d|", "|%" PRId32, "", name, value);
286 }
287 
atrace_int64_body(const char * name,int64_t value)288 void atrace_int64_body(const char* name, int64_t value)
289 {
290     if (CC_LIKELY(atrace_use_container_sock)) {
291         WRITE_MSG_IN_CONTAINER("C", "|", "|%" PRId64, "", name, value);
292         return;
293     }
294 
295     if (atrace_marker_fd < 0) return;
296 
297     WRITE_MSG("C|%d|", "|%" PRId64, "", name, value);
298 }
299