1 /* 2 * 3 * Copyright 2015 gRPC authors. 4 * 5 * Licensed under the Apache License, Version 2.0 (the "License"); 6 * you may not use this file except in compliance with the License. 7 * You may obtain a copy of the License at 8 * 9 * http://www.apache.org/licenses/LICENSE-2.0 10 * 11 * Unless required by applicable law or agreed to in writing, software 12 * distributed under the License is distributed on an "AS IS" BASIS, 13 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. 14 * See the License for the specific language governing permissions and 15 * limitations under the License. 16 * 17 */ 18 19 #include <grpc/support/port_platform.h> 20 21 #include "src/core/lib/profiling/timers.h" 22 23 #ifdef GRPC_BASIC_PROFILER 24 25 #include <grpc/support/alloc.h> 26 #include <grpc/support/log.h> 27 #include <grpc/support/sync.h> 28 #include <grpc/support/time.h> 29 #include <inttypes.h> 30 #include <pthread.h> 31 #include <stdio.h> 32 #include <string.h> 33 34 #include "src/core/lib/gpr/env.h" 35 36 typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type; 37 38 typedef struct gpr_timer_entry { 39 gpr_timespec tm; 40 const char* tagstr; 41 const char* file; 42 short line; 43 char type; 44 uint8_t important; 45 int thd; 46 } gpr_timer_entry; 47 48 #define MAX_COUNT 1000000 49 50 typedef struct gpr_timer_log { 51 size_t num_entries; 52 struct gpr_timer_log* next; 53 struct gpr_timer_log* prev; 54 gpr_timer_entry log[MAX_COUNT]; 55 } gpr_timer_log; 56 57 typedef struct gpr_timer_log_list { 58 gpr_timer_log* head; 59 /* valid iff head!=NULL */ 60 gpr_timer_log* tail; 61 } gpr_timer_log_list; 62 63 static __thread gpr_timer_log* g_thread_log; 64 static gpr_once g_once_init = GPR_ONCE_INIT; 65 static FILE* output_file; 66 static const char* output_filename_or_null = NULL; 67 static pthread_mutex_t g_mu; 68 static pthread_cond_t g_cv; 69 static gpr_timer_log_list g_in_progress_logs; 70 static gpr_timer_log_list g_done_logs; 71 static int g_shutdown; 72 static pthread_t g_writing_thread; 73 static __thread int g_thread_id; 74 static int g_next_thread_id; 75 static int g_writing_enabled = 1; 76 77 static const char* output_filename() { 78 if (output_filename_or_null == NULL) { 79 output_filename_or_null = gpr_getenv("LATENCY_TRACE"); 80 if (output_filename_or_null == NULL || 81 strlen(output_filename_or_null) == 0) { 82 output_filename_or_null = "latency_trace.txt"; 83 } 84 } 85 return output_filename_or_null; 86 } 87 88 static int timer_log_push_back(gpr_timer_log_list* list, gpr_timer_log* log) { 89 if (list->head == NULL) { 90 list->head = list->tail = log; 91 log->next = log->prev = NULL; 92 return 1; 93 } else { 94 log->prev = list->tail; 95 log->next = NULL; 96 list->tail->next = log; 97 list->tail = log; 98 return 0; 99 } 100 } 101 102 static gpr_timer_log* timer_log_pop_front(gpr_timer_log_list* list) { 103 gpr_timer_log* out = list->head; 104 if (out != NULL) { 105 list->head = out->next; 106 if (list->head != NULL) { 107 list->head->prev = NULL; 108 } else { 109 list->tail = NULL; 110 } 111 } 112 return out; 113 } 114 115 static void timer_log_remove(gpr_timer_log_list* list, gpr_timer_log* log) { 116 if (log->prev == NULL) { 117 list->head = log->next; 118 if (list->head != NULL) { 119 list->head->prev = NULL; 120 } 121 } else { 122 log->prev->next = log->next; 123 } 124 if (log->next == NULL) { 125 list->tail = log->prev; 126 if (list->tail != NULL) { 127 list->tail->next = NULL; 128 } 129 } else { 130 log->next->prev = log->prev; 131 } 132 } 133 134 static void write_log(gpr_timer_log* log) { 135 size_t i; 136 if (output_file == NULL) { 137 output_file = fopen(output_filename(), "w"); 138 } 139 for (i = 0; i < log->num_entries; i++) { 140 gpr_timer_entry* entry = &(log->log[i]); 141 if (gpr_time_cmp(entry->tm, gpr_time_0(entry->tm.clock_type)) < 0) { 142 entry->tm = gpr_time_0(entry->tm.clock_type); 143 } 144 fprintf(output_file, 145 "{\"t\": %" PRId64 146 ".%09d, \"thd\": \"%d\", \"type\": \"%c\", \"tag\": " 147 "\"%s\", \"file\": \"%s\", \"line\": %d, \"imp\": %d}\n", 148 entry->tm.tv_sec, entry->tm.tv_nsec, entry->thd, entry->type, 149 entry->tagstr, entry->file, entry->line, entry->important); 150 } 151 } 152 153 static void* writing_thread(void* unused) { 154 gpr_timer_log* log; 155 pthread_mutex_lock(&g_mu); 156 for (;;) { 157 while ((log = timer_log_pop_front(&g_done_logs)) == NULL && !g_shutdown) { 158 pthread_cond_wait(&g_cv, &g_mu); 159 } 160 if (log != NULL) { 161 pthread_mutex_unlock(&g_mu); 162 write_log(log); 163 free(log); 164 pthread_mutex_lock(&g_mu); 165 } 166 if (g_shutdown) { 167 pthread_mutex_unlock(&g_mu); 168 return NULL; 169 } 170 } 171 } 172 173 static void flush_logs(gpr_timer_log_list* list) { 174 gpr_timer_log* log; 175 while ((log = timer_log_pop_front(list)) != NULL) { 176 write_log(log); 177 free(log); 178 } 179 } 180 181 static void finish_writing(void) { 182 pthread_mutex_lock(&g_mu); 183 g_shutdown = 1; 184 pthread_cond_signal(&g_cv); 185 pthread_mutex_unlock(&g_mu); 186 pthread_join(g_writing_thread, NULL); 187 188 gpr_log(GPR_INFO, "flushing logs"); 189 190 pthread_mutex_lock(&g_mu); 191 flush_logs(&g_done_logs); 192 flush_logs(&g_in_progress_logs); 193 pthread_mutex_unlock(&g_mu); 194 195 if (output_file) { 196 fclose(output_file); 197 } 198 } 199 200 void gpr_timers_set_log_filename(const char* filename) { 201 output_filename_or_null = filename; 202 } 203 204 static void init_output() { 205 pthread_attr_t attr; 206 pthread_attr_init(&attr); 207 pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_JOINABLE); 208 pthread_create(&g_writing_thread, &attr, &writing_thread, NULL); 209 pthread_attr_destroy(&attr); 210 211 atexit(finish_writing); 212 } 213 214 static void rotate_log() { 215 /* Using malloc here, as this code could end up being called by gpr_malloc */ 216 gpr_timer_log* log = static_cast<gpr_timer_log*>(malloc(sizeof(*log))); 217 gpr_once_init(&g_once_init, init_output); 218 log->num_entries = 0; 219 pthread_mutex_lock(&g_mu); 220 if (g_thread_log != NULL) { 221 timer_log_remove(&g_in_progress_logs, g_thread_log); 222 if (timer_log_push_back(&g_done_logs, g_thread_log)) { 223 pthread_cond_signal(&g_cv); 224 } 225 } else { 226 g_thread_id = g_next_thread_id++; 227 } 228 timer_log_push_back(&g_in_progress_logs, log); 229 pthread_mutex_unlock(&g_mu); 230 g_thread_log = log; 231 } 232 233 static void gpr_timers_log_add(const char* tagstr, marker_type type, 234 int important, const char* file, int line) { 235 gpr_timer_entry* entry; 236 237 if (!g_writing_enabled) { 238 return; 239 } 240 241 if (g_thread_log == NULL || g_thread_log->num_entries == MAX_COUNT) { 242 rotate_log(); 243 } 244 245 entry = &g_thread_log->log[g_thread_log->num_entries++]; 246 247 entry->tm = gpr_now(GPR_CLOCK_PRECISE); 248 entry->tagstr = tagstr; 249 entry->type = type; 250 entry->file = file; 251 entry->line = (short)line; 252 entry->important = important != 0; 253 entry->thd = g_thread_id; 254 } 255 256 /* Latency profiler API implementation. */ 257 void gpr_timer_add_mark(const char* tagstr, int important, const char* file, 258 int line) { 259 gpr_timers_log_add(tagstr, MARK, important, file, line); 260 } 261 262 void gpr_timer_begin(const char* tagstr, int important, const char* file, 263 int line) { 264 gpr_timers_log_add(tagstr, BEGIN, important, file, line); 265 } 266 267 void gpr_timer_end(const char* tagstr, int important, const char* file, 268 int line) { 269 gpr_timers_log_add(tagstr, END, important, file, line); 270 } 271 272 void gpr_timer_set_enabled(int enabled) { g_writing_enabled = enabled; } 273 274 /* Basic profiler specific API functions. */ 275 void gpr_timers_global_init(void) {} 276 277 void gpr_timers_global_destroy(void) {} 278 279 #else /* !GRPC_BASIC_PROFILER */ 280 void gpr_timers_global_init(void) {} 281 282 void gpr_timers_global_destroy(void) {} 283 284 void gpr_timers_set_log_filename(const char* filename) {} 285 286 void gpr_timer_set_enabled(int enabled) {} 287 #endif /* GRPC_BASIC_PROFILER */ 288
