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