legacy-libs/grpc/deps/grpc/src/core/lib/profiling/basic_timers.cc

   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/gprpp/global_config.h"
  35 #include "src/core/lib/profiling/timers.h"
  36
  37 typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type;
  38
  39 typedef struct gpr_timer_entry {
  40   gpr_timespec tm;
  41   const char* tagstr;
  42   const char* file;
  43   short line;
  44   char type;
  45   uint8_t important;
  46   int thd;
  47 } gpr_timer_entry;
  48
  49 #define MAX_COUNT 1000000
  50
  51 typedef struct gpr_timer_log {
  52   size_t num_entries;
  53   struct gpr_timer_log* next;
  54   struct gpr_timer_log* prev;
  55   gpr_timer_entry log[MAX_COUNT];
  56 } gpr_timer_log;
  57
  58 typedef struct gpr_timer_log_list {
  59   gpr_timer_log* head;
  60   /* valid iff head!=NULL */
  61   gpr_timer_log* tail;
  62 } gpr_timer_log_list;
  63
  64 static __thread gpr_timer_log* g_thread_log;
  65 static gpr_once g_once_init = GPR_ONCE_INIT;
  66 static FILE* output_file;
  67 static const char* output_filename_or_null = NULL;
  68 static pthread_mutex_t g_mu;
  69 static pthread_cond_t g_cv;
  70 static gpr_timer_log_list g_in_progress_logs;
  71 static gpr_timer_log_list g_done_logs;
  72 static int g_shutdown;
  73 static pthread_t g_writing_thread;
  74 static __thread int g_thread_id;
  75 static int g_next_thread_id;
  76 static int g_writing_enabled = 1;
  77
  78 GPR_GLOBAL_CONFIG_DEFINE_STRING(grpc_latency_trace, "latency_trace.txt",
  79                                 "Output file name for latency trace")
  80
  81 static const char* output_filename() {
  82   if (output_filename_or_null == NULL) {
  83     grpc_core::UniquePtr<char> value =
  84         GPR_GLOBAL_CONFIG_GET(grpc_latency_trace);
  85     if (strlen(value.get()) > 0) {
  86       output_filename_or_null = value.release();
  87     } else {
  88       output_filename_or_null = "latency_trace.txt";
  89     }
  90   }
  91   return output_filename_or_null;
  92 }
  93
  94 static int timer_log_push_back(gpr_timer_log_list* list, gpr_timer_log* log) {
  95   if (list->head == NULL) {
  96     list->head = list->tail = log;
  97     log->next = log->prev = NULL;
  98     return 1;
  99   } else {
 100     log->prev = list->tail;
 101     log->next = NULL;
 102     list->tail->next = log;
 103     list->tail = log;
 104     return 0;
 105   }
 106 }
 107
 108 static gpr_timer_log* timer_log_pop_front(gpr_timer_log_list* list) {
 109   gpr_timer_log* out = list->head;
 110   if (out != NULL) {
 111     list->head = out->next;
 112     if (list->head != NULL) {
 113       list->head->prev = NULL;
 114     } else {
 115       list->tail = NULL;
 116     }
 117   }
 118   return out;
 119 }
 120
 121 static void timer_log_remove(gpr_timer_log_list* list, gpr_timer_log* log) {
 122   if (log->prev == NULL) {
 123     list->head = log->next;
 124     if (list->head != NULL) {
 125       list->head->prev = NULL;
 126     }
 127   } else {
 128     log->prev->next = log->next;
 129   }
 130   if (log->next == NULL) {
 131     list->tail = log->prev;
 132     if (list->tail != NULL) {
 133       list->tail->next = NULL;
 134     }
 135   } else {
 136     log->next->prev = log->prev;
 137   }
 138 }
 139
 140 static void write_log(gpr_timer_log* log) {
 141   size_t i;
 142   if (output_file == NULL) {
 143     output_file = fopen(output_filename(), "w");
 144   }
 145   for (i = 0; i < log->num_entries; i++) {
 146     gpr_timer_entry* entry = &(log->log[i]);
 147     if (gpr_time_cmp(entry->tm, gpr_time_0(entry->tm.clock_type)) < 0) {
 148       entry->tm = gpr_time_0(entry->tm.clock_type);
 149     }
 150     fprintf(output_file,
 151             "{\"t\": %" PRId64
 152             ".%09d, \"thd\": \"%d\", \"type\": \"%c\", \"tag\": "
 153             "\"%s\", \"file\": \"%s\", \"line\": %d, \"imp\": %d}\n",
 154             entry->tm.tv_sec, entry->tm.tv_nsec, entry->thd, entry->type,
 155             entry->tagstr, entry->file, entry->line, entry->important);
 156   }
 157 }
 158
 159 static void* writing_thread(void* unused) {
 160   gpr_timer_log* log;
 161   pthread_mutex_lock(&g_mu);
 162   for (;;) {
 163     while ((log = timer_log_pop_front(&g_done_logs)) == NULL && !g_shutdown) {
 164       pthread_cond_wait(&g_cv, &g_mu);
 165     }
 166     if (log != NULL) {
 167       pthread_mutex_unlock(&g_mu);
 168       write_log(log);
 169       free(log);
 170       pthread_mutex_lock(&g_mu);
 171     }
 172     if (g_shutdown) {
 173       pthread_mutex_unlock(&g_mu);
 174       return NULL;
 175     }
 176   }
 177 }
 178
 179 static void flush_logs(gpr_timer_log_list* list) {
 180   gpr_timer_log* log;
 181   while ((log = timer_log_pop_front(list)) != NULL) {
 182     write_log(log);
 183     free(log);
 184   }
 185 }
 186
 187 static void finish_writing(void) {
 188   pthread_mutex_lock(&g_mu);
 189   g_shutdown = 1;
 190   pthread_cond_signal(&g_cv);
 191   pthread_mutex_unlock(&g_mu);
 192   pthread_join(g_writing_thread, NULL);
 193
 194   gpr_log(GPR_INFO, "flushing logs");
 195
 196   pthread_mutex_lock(&g_mu);
 197   flush_logs(&g_done_logs);
 198   flush_logs(&g_in_progress_logs);
 199   pthread_mutex_unlock(&g_mu);
 200
 201   if (output_file) {
 202     fclose(output_file);
 203   }
 204 }
 205
 206 void gpr_timers_set_log_filename(const char* filename) {
 207   output_filename_or_null = filename;
 208 }
 209
 210 static void init_output() {
 211   pthread_attr_t attr;
 212   pthread_attr_init(&attr);
 213   pthread_attr_setdetachstate(&attr, PTHREAD_CREATE_JOINABLE);
 214   pthread_create(&g_writing_thread, &attr, &writing_thread, NULL);
 215   pthread_attr_destroy(&attr);
 216
 217   atexit(finish_writing);
 218 }
 219
 220 static void rotate_log() {
 221   /* Using malloc here, as this code could end up being called by gpr_malloc */
 222   gpr_timer_log* log = static_cast<gpr_timer_log*>(malloc(sizeof(*log)));
 223   gpr_once_init(&g_once_init, init_output);
 224   log->num_entries = 0;
 225   pthread_mutex_lock(&g_mu);
 226   if (g_thread_log != NULL) {
 227     timer_log_remove(&g_in_progress_logs, g_thread_log);
 228     if (timer_log_push_back(&g_done_logs, g_thread_log)) {
 229       pthread_cond_signal(&g_cv);
 230     }
 231   } else {
 232     g_thread_id = g_next_thread_id++;
 233   }
 234   timer_log_push_back(&g_in_progress_logs, log);
 235   pthread_mutex_unlock(&g_mu);
 236   g_thread_log = log;
 237 }
 238
 239 static void gpr_timers_log_add(const char* tagstr, marker_type type,
 240                                int important, const char* file, int line) {
 241   gpr_timer_entry* entry;
 242
 243   if (!g_writing_enabled) {
 244     return;
 245   }
 246
 247   if (g_thread_log == NULL || g_thread_log->num_entries == MAX_COUNT) {
 248     rotate_log();
 249   }
 250
 251   entry = &g_thread_log->log[g_thread_log->num_entries++];
 252
 253   entry->tm = gpr_now(GPR_CLOCK_PRECISE);
 254   entry->tagstr = tagstr;
 255   entry->type = type;
 256   entry->file = file;
 257   entry->line = (short)line;
 258   entry->important = important != 0;
 259   entry->thd = g_thread_id;
 260 }
 261
 262 /* Latency profiler API implementation. */
 263 void gpr_timer_add_mark(const char* tagstr, int important, const char* file,
 264                         int line) {
 265   gpr_timers_log_add(tagstr, MARK, important, file, line);
 266 }
 267
 268 void gpr_timer_begin(const char* tagstr, int important, const char* file,
 269                      int line) {
 270   gpr_timers_log_add(tagstr, BEGIN, important, file, line);
 271 }
 272
 273 void gpr_timer_end(const char* tagstr, int important, const char* file,
 274                    int line) {
 275   gpr_timers_log_add(tagstr, END, important, file, line);
 276 }
 277
 278 void gpr_timer_set_enabled(int enabled) { g_writing_enabled = enabled; }
 279
 280 /* Basic profiler specific API functions. */
 281 void gpr_timers_global_init(void) {}
 282
 283 void gpr_timers_global_destroy(void) {}
 284
 285 #else  /* !GRPC_BASIC_PROFILER */
 286 void gpr_timers_global_init(void) {}
 287
 288 void gpr_timers_global_destroy(void) {}
 289
 290 void gpr_timers_set_log_filename(const char* filename) {}
 291
 292 void gpr_timer_set_enabled(int enabled) {}
 293 #endif /* GRPC_BASIC_PROFILER */