• Home
  • Line#
  • Scopes#
  • Navigate#
  • Raw
  • Download
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 
output_filename()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 
timer_log_push_back(gpr_timer_log_list * list,gpr_timer_log * log)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 
timer_log_pop_front(gpr_timer_log_list * list)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 
timer_log_remove(gpr_timer_log_list * list,gpr_timer_log * log)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 
write_log(gpr_timer_log * log)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 
writing_thread(void * unused)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 
flush_logs(gpr_timer_log_list * list)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 
finish_writing(void)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 
gpr_timers_set_log_filename(const char * filename)206 void gpr_timers_set_log_filename(const char* filename) {
207   output_filename_or_null = filename;
208 }
209 
init_output()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 
rotate_log()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 
gpr_timers_log_add(const char * tagstr,marker_type type,int important,const char * file,int line)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. */
gpr_timer_add_mark(const char * tagstr,int important,const char * file,int line)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 
gpr_timer_begin(const char * tagstr,int important,const char * file,int line)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 
gpr_timer_end(const char * tagstr,int important,const char * file,int line)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 
gpr_timer_set_enabled(int enabled)278 void gpr_timer_set_enabled(int enabled) { g_writing_enabled = enabled; }
279 
280 /* Basic profiler specific API functions. */
gpr_timers_global_init(void)281 void gpr_timers_global_init(void) {}
282 
gpr_timers_global_destroy(void)283 void gpr_timers_global_destroy(void) {}
284 
285 #else  /* !GRPC_BASIC_PROFILER */
gpr_timers_global_init(void)286 void gpr_timers_global_init(void) {}
287 
gpr_timers_global_destroy(void)288 void gpr_timers_global_destroy(void) {}
289 
gpr_timers_set_log_filename(const char *)290 void gpr_timers_set_log_filename(const char* /*filename*/) {}
291 
gpr_timer_set_enabled(int)292 void gpr_timer_set_enabled(int /*enabled*/) {}
293 #endif /* GRPC_BASIC_PROFILER */
294