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