Line data Source code
1 : /*
2 : *
3 : * Copyright 2015, Google Inc.
4 : * All rights reserved.
5 : *
6 : * Redistribution and use in source and binary forms, with or without
7 : * modification, are permitted provided that the following conditions are
8 : * met:
9 : *
10 : * * Redistributions of source code must retain the above copyright
11 : * notice, this list of conditions and the following disclaimer.
12 : * * Redistributions in binary form must reproduce the above
13 : * copyright notice, this list of conditions and the following disclaimer
14 : * in the documentation and/or other materials provided with the
15 : * distribution.
16 : * * Neither the name of Google Inc. nor the names of its
17 : * contributors may be used to endorse or promote products derived from
18 : * this software without specific prior written permission.
19 : *
20 : * THIS SOFTWARE IS PROVIDED BY THE COPYRIGHT HOLDERS AND CONTRIBUTORS
21 : * "AS IS" AND ANY EXPRESS OR IMPLIED WARRANTIES, INCLUDING, BUT NOT
22 : * LIMITED TO, THE IMPLIED WARRANTIES OF MERCHANTABILITY AND FITNESS FOR
23 : * A PARTICULAR PURPOSE ARE DISCLAIMED. IN NO EVENT SHALL THE COPYRIGHT
24 : * OWNER OR CONTRIBUTORS BE LIABLE FOR ANY DIRECT, INDIRECT, INCIDENTAL,
25 : * SPECIAL, EXEMPLARY, OR CONSEQUENTIAL DAMAGES (INCLUDING, BUT NOT
26 : * LIMITED TO, PROCUREMENT OF SUBSTITUTE GOODS OR SERVICES; LOSS OF USE,
27 : * DATA, OR PROFITS; OR BUSINESS INTERRUPTION) HOWEVER CAUSED AND ON ANY
28 : * THEORY OF LIABILITY, WHETHER IN CONTRACT, STRICT LIABILITY, OR TORT
29 : * (INCLUDING NEGLIGENCE OR OTHERWISE) ARISING IN ANY WAY OUT OF THE USE
30 : * OF THIS SOFTWARE, EVEN IF ADVISED OF THE POSSIBILITY OF SUCH DAMAGE.
31 : *
32 : */
33 :
34 : #include <grpc/support/port_platform.h>
35 :
36 : #ifdef GRPC_BASIC_PROFILER
37 :
38 : #include "src/core/profiling/timers.h"
39 :
40 : #include <grpc/support/alloc.h>
41 : #include <grpc/support/log.h>
42 : #include <grpc/support/time.h>
43 : #include <grpc/support/sync.h>
44 : #include <grpc/support/thd.h>
45 : #include <stdio.h>
46 :
47 : typedef enum { BEGIN = '{', END = '}', MARK = '.' } marker_type;
48 :
49 : typedef struct gpr_timer_entry {
50 : gpr_timespec tm;
51 : const char *tagstr;
52 : const char *file;
53 : short line;
54 : char type;
55 : gpr_uint8 important;
56 : int thd;
57 : } gpr_timer_entry;
58 :
59 : #define MAX_COUNT 1000000
60 :
61 : typedef struct gpr_timer_log {
62 : size_t num_entries;
63 : struct gpr_timer_log *next;
64 : struct gpr_timer_log *prev;
65 : gpr_timer_entry log[MAX_COUNT];
66 : } gpr_timer_log;
67 :
68 : typedef struct gpr_timer_log_list {
69 : gpr_timer_log *head;
70 : /* valid iff head!=NULL */
71 : gpr_timer_log *tail;
72 : } gpr_timer_log_list;
73 :
74 : static __thread gpr_timer_log *g_thread_log;
75 : static gpr_once g_once_init = GPR_ONCE_INIT;
76 : static FILE *output_file;
77 : static const char *output_filename = "latency_trace.txt";
78 : static pthread_mutex_t g_mu;
79 : static pthread_cond_t g_cv;
80 : static gpr_timer_log_list g_in_progress_logs;
81 : static gpr_timer_log_list g_done_logs;
82 : static int g_shutdown;
83 : static gpr_thd_id g_writing_thread;
84 : static __thread int g_thread_id;
85 : static int g_next_thread_id;
86 :
87 : static int timer_log_push_back(gpr_timer_log_list *list, gpr_timer_log *log) {
88 : if (list->head == NULL) {
89 : list->head = list->tail = log;
90 : log->next = log->prev = NULL;
91 : return 1;
92 : } else {
93 : log->prev = list->tail;
94 : log->next = NULL;
95 : list->tail->next = log;
96 : list->tail = log;
97 : return 0;
98 : }
99 : }
100 :
101 : static gpr_timer_log *timer_log_pop_front(gpr_timer_log_list *list) {
102 : gpr_timer_log *out = list->head;
103 : if (out != NULL) {
104 : list->head = out->next;
105 : if (list->head != NULL) {
106 : list->head->prev = NULL;
107 : } else {
108 : list->tail = NULL;
109 : }
110 : }
111 : return out;
112 : }
113 :
114 : static void timer_log_remove(gpr_timer_log_list *list, gpr_timer_log *log) {
115 : if (log->prev == NULL) {
116 : list->head = log->next;
117 : if (list->head != NULL) {
118 : list->head->prev = NULL;
119 : }
120 : } else {
121 : log->prev->next = log->next;
122 : }
123 : if (log->next == NULL) {
124 : list->tail = log->prev;
125 : if (list->tail != NULL) {
126 : list->tail->next = NULL;
127 : }
128 : } else {
129 : log->next->prev = log->prev;
130 : }
131 : }
132 :
133 : static void write_log(gpr_timer_log *log) {
134 : size_t i;
135 : if (output_file == NULL) {
136 : output_file = fopen(output_filename, "w");
137 : }
138 : for (i = 0; i < log->num_entries; i++) {
139 : gpr_timer_entry *entry = &(log->log[i]);
140 : if (gpr_time_cmp(entry->tm, gpr_time_0(entry->tm.clock_type)) < 0) {
141 : entry->tm = gpr_time_0(entry->tm.clock_type);
142 : }
143 : fprintf(output_file,
144 : "{\"t\": %ld.%09d, \"thd\": \"%d\", \"type\": \"%c\", \"tag\": "
145 : "\"%s\", \"file\": \"%s\", \"line\": %d, \"imp\": %d}\n",
146 : entry->tm.tv_sec, entry->tm.tv_nsec, entry->thd, entry->type,
147 : entry->tagstr, entry->file, entry->line, entry->important);
148 : }
149 : }
150 :
151 : static void writing_thread(void *unused) {
152 : gpr_timer_log *log;
153 : pthread_mutex_lock(&g_mu);
154 : for (;;) {
155 : while ((log = timer_log_pop_front(&g_done_logs)) == NULL && !g_shutdown) {
156 : pthread_cond_wait(&g_cv, &g_mu);
157 : }
158 : if (log != NULL) {
159 : pthread_mutex_unlock(&g_mu);
160 : write_log(log);
161 : free(log);
162 : pthread_mutex_lock(&g_mu);
163 : }
164 : if (g_shutdown) {
165 : pthread_mutex_unlock(&g_mu);
166 : return;
167 : }
168 : }
169 : }
170 :
171 : static void flush_logs(gpr_timer_log_list *list) {
172 : gpr_timer_log *log;
173 : while ((log = timer_log_pop_front(list)) != NULL) {
174 : write_log(log);
175 : free(log);
176 : }
177 : }
178 :
179 : static void finish_writing() {
180 : pthread_mutex_lock(&g_mu);
181 : g_shutdown = 1;
182 : pthread_cond_signal(&g_cv);
183 : pthread_mutex_unlock(&g_mu);
184 : gpr_thd_join(g_writing_thread);
185 :
186 : gpr_log(GPR_INFO, "flushing logs");
187 :
188 : pthread_mutex_lock(&g_mu);
189 : flush_logs(&g_done_logs);
190 : flush_logs(&g_in_progress_logs);
191 : pthread_mutex_unlock(&g_mu);
192 :
193 : if (output_file) {
194 : fclose(output_file);
195 : }
196 : }
197 :
198 : void gpr_timers_set_log_filename(const char *filename) {
199 : output_filename = filename;
200 : }
201 :
202 : static void init_output() {
203 : gpr_thd_options options = gpr_thd_options_default();
204 : gpr_thd_options_set_joinable(&options);
205 : gpr_thd_new(&g_writing_thread, writing_thread, NULL, &options);
206 : atexit(finish_writing);
207 : }
208 :
209 : static void rotate_log() {
210 : gpr_timer_log *new = malloc(sizeof(*new));
211 : gpr_once_init(&g_once_init, init_output);
212 : new->num_entries = 0;
213 : pthread_mutex_lock(&g_mu);
214 : if (g_thread_log != NULL) {
215 : timer_log_remove(&g_in_progress_logs, g_thread_log);
216 : if (timer_log_push_back(&g_done_logs, g_thread_log)) {
217 : pthread_cond_signal(&g_cv);
218 : }
219 : } else {
220 : g_thread_id = g_next_thread_id++;
221 : }
222 : timer_log_push_back(&g_in_progress_logs, new);
223 : pthread_mutex_unlock(&g_mu);
224 : g_thread_log = new;
225 : }
226 :
227 : static void gpr_timers_log_add(const char *tagstr, marker_type type,
228 : int important, const char *file, int line) {
229 : gpr_timer_entry *entry;
230 :
231 : if (g_thread_log == NULL || g_thread_log->num_entries == MAX_COUNT) {
232 : rotate_log();
233 : }
234 :
235 : entry = &g_thread_log->log[g_thread_log->num_entries++];
236 :
237 : entry->tm = gpr_now(GPR_CLOCK_PRECISE);
238 : entry->tagstr = tagstr;
239 : entry->type = type;
240 : entry->file = file;
241 : entry->line = (short)line;
242 : entry->important = important != 0;
243 : entry->thd = g_thread_id;
244 : }
245 :
246 : /* Latency profiler API implementation. */
247 : void gpr_timer_add_mark(const char *tagstr, int important, const char *file,
248 : int line) {
249 : gpr_timers_log_add(tagstr, MARK, important, file, line);
250 : }
251 :
252 : void gpr_timer_begin(const char *tagstr, int important, const char *file,
253 : int line) {
254 : gpr_timers_log_add(tagstr, BEGIN, important, file, line);
255 : }
256 :
257 : void gpr_timer_end(const char *tagstr, int important, const char *file,
258 : int line) {
259 : gpr_timers_log_add(tagstr, END, important, file, line);
260 : }
261 :
262 : /* Basic profiler specific API functions. */
263 : void gpr_timers_global_init(void) {}
264 :
265 : void gpr_timers_global_destroy(void) {}
266 :
267 : #else /* !GRPC_BASIC_PROFILER */
268 3453 : void gpr_timers_global_init(void) {}
269 :
270 3451 : void gpr_timers_global_destroy(void) {}
271 :
272 2 : void gpr_timers_set_log_filename(const char *filename) {}
273 : #endif /* GRPC_BASIC_PROFILER */
|
