1 // minitrace
2 // Copyright 2014 by Henrik Rydgård
3 // http://www.github.com/hrydgard/minitrace
4 // Released under the MIT license.
5
6 // See minitrace.h for basic documentation.
7
8 #include <stdlib.h>
9 #include <stdio.h>
10 #include <string.h>
11
12 #ifdef _WIN32
13 #pragma warning (disable:4996)
14 #define WIN32_LEAN_AND_MEAN
15 #include <windows.h>
16 #define __thread __declspec(thread)
17 #define pthread_mutex_t CRITICAL_SECTION
18 #define pthread_mutex_init(a, b) InitializeCriticalSection(a)
19 #define pthread_mutex_lock(a) EnterCriticalSection(a)
20 #define pthread_mutex_unlock(a) LeaveCriticalSection(a)
21 #define pthread_mutex_destroy(a) DeleteCriticalSection(a)
22 #else
23 #include <signal.h>
24 #include <pthread.h>
25 #include <sys/time.h>
26 #include <unistd.h>
27 #endif
28
29 #include "minitrace.h"
30
31 #ifdef __GNUC__
32 #define ATTR_NORETURN __attribute__((noreturn))
33 #else
34 #define ATTR_NORETURN
35 #endif
36
37 #define ARRAY_SIZE(x) sizeof(x)/sizeof(x[0])
38
39 // Ugh, this struct is already pretty heavy.
40 // Will probably need to move arguments to a second buffer to support more than one.
41 typedef struct raw_event {
42 const char *name;
43 const char *cat;
44 void *id;
45 int64_t ts;
46 uint32_t pid;
47 uint32_t tid;
48 char ph;
49 mtr_arg_type arg_type;
50 const char *arg_name;
51 union {
52 const char *a_str;
53 int a_int;
54 double a_double;
55 };
56 } raw_event_t;
57
58 static raw_event_t *buffer;
59 static volatile int count;
60 static int is_tracing = 0;
61 static int64_t time_offset;
62 static int first_line = 1;
63 static FILE *f;
64 static __thread int cur_thread_id; // Thread local storage
65 static int cur_process_id;
66 static pthread_mutex_t mutex;
67
68 #define STRING_POOL_SIZE 100
69 static char *str_pool[100];
70
71 // Tiny portability layer.
72 // Exposes:
73 // get_cur_thread_id()
74 // get_cur_process_id()
75 // mtr_time_s()
76 // pthread basics
77 #ifdef _WIN32
get_cur_thread_id()78 static int get_cur_thread_id() {
79 return (int)GetCurrentThreadId();
80 }
get_cur_process_id()81 static int get_cur_process_id() {
82 return (int)GetCurrentProcessId();
83 }
84
85 static uint64_t _frequency = 0;
86 static uint64_t _starttime = 0;
mtr_time_s()87 double mtr_time_s() {
88 if (_frequency == 0) {
89 QueryPerformanceFrequency((LARGE_INTEGER*)&_frequency);
90 QueryPerformanceCounter((LARGE_INTEGER*)&_starttime);
91 }
92 __int64 time;
93 QueryPerformanceCounter((LARGE_INTEGER*)&time);
94 return ((double) (time - _starttime) / (double) _frequency);
95 }
96
97 // Ctrl+C handling for Windows console apps
CtrlHandler(DWORD fdwCtrlType)98 static BOOL WINAPI CtrlHandler(DWORD fdwCtrlType) {
99 if (is_tracing && fdwCtrlType == CTRL_C_EVENT) {
100 printf("Ctrl-C detected! Flushing trace and shutting down.\n\n");
101 mtr_flush();
102 mtr_shutdown();
103 }
104 ExitProcess(1);
105 }
106
mtr_register_sigint_handler()107 void mtr_register_sigint_handler() {
108 // For console apps:
109 SetConsoleCtrlHandler(&CtrlHandler, TRUE);
110 }
111
112 #else
113
get_cur_thread_id()114 static inline int get_cur_thread_id() {
115 return (int)(intptr_t)pthread_self();
116 }
get_cur_process_id()117 static inline int get_cur_process_id() {
118 return (int)getpid();
119 }
120
121 #if defined(BLACKBERRY)
mtr_time_s()122 double mtr_time_s() {
123 struct timespec time;
124 clock_gettime(CLOCK_MONOTONIC, &time); // Linux must use CLOCK_MONOTONIC_RAW due to time warps
125 return time.tv_sec + time.tv_nsec / 1.0e9;
126 }
127 #else
mtr_time_s()128 double mtr_time_s() {
129 static time_t start;
130 struct timeval tv;
131 gettimeofday(&tv, NULL);
132 if (start == 0) {
133 start = tv.tv_sec;
134 }
135 tv.tv_sec -= start;
136 return (double)tv.tv_sec + (double)tv.tv_usec / 1000000.0;
137 }
138 #endif // !BLACKBERRY
139
140 static void termination_handler(int signum) ATTR_NORETURN;
termination_handler(int signum)141 static void termination_handler(int signum) {
142 (void) signum;
143 if (is_tracing) {
144 printf("Ctrl-C detected! Flushing trace and shutting down.\n\n");
145 mtr_flush();
146 fwrite("\n]}\n", 1, 4, f);
147 fclose(f);
148 }
149 exit(1);
150 }
151
mtr_register_sigint_handler()152 void mtr_register_sigint_handler() {
153 #ifndef MTR_ENABLED
154 return;
155 #endif
156 // Avoid altering set-to-be-ignored handlers while registering.
157 if (signal(SIGINT, &termination_handler) == SIG_IGN)
158 signal(SIGINT, SIG_IGN);
159 }
160
161 #endif
162
mtr_init_from_stream(void * stream)163 void mtr_init_from_stream(void *stream) {
164 #ifndef MTR_ENABLED
165 return;
166 #endif
167 buffer = (raw_event_t *)malloc(INTERNAL_MINITRACE_BUFFER_SIZE * sizeof(raw_event_t));
168 is_tracing = 1;
169 count = 0;
170 f = (FILE *)stream;
171 const char *header = "{\"traceEvents\":[\n";
172 fwrite(header, 1, strlen(header), f);
173 time_offset = (uint64_t)(mtr_time_s() * 1000000);
174 first_line = 1;
175 pthread_mutex_init(&mutex, 0);
176 }
177
mtr_init(const char * json_file)178 void mtr_init(const char *json_file) {
179 #ifndef MTR_ENABLED
180 return;
181 #endif
182 mtr_init_from_stream(fopen(json_file, "wb"));
183 }
184
mtr_shutdown()185 void mtr_shutdown() {
186 int i;
187 #ifndef MTR_ENABLED
188 return;
189 #endif
190 is_tracing = 0;
191 mtr_flush();
192 fwrite("\n]}\n", 1, 4, f);
193 fclose(f);
194 pthread_mutex_destroy(&mutex);
195 f = 0;
196 free(buffer);
197 buffer = 0;
198 for (i = 0; i < STRING_POOL_SIZE; i++) {
199 if (str_pool[i]) {
200 free(str_pool[i]);
201 str_pool[i] = 0;
202 }
203 }
204 }
205
mtr_pool_string(const char * str)206 const char *mtr_pool_string(const char *str) {
207 int i;
208 for (i = 0; i < STRING_POOL_SIZE; i++) {
209 if (!str_pool[i]) {
210 str_pool[i] = (char*)malloc(strlen(str) + 1);
211 strcpy(str_pool[i], str);
212 return str_pool[i];
213 } else {
214 if (!strcmp(str, str_pool[i]))
215 return str_pool[i];
216 }
217 }
218 return "string pool full";
219 }
220
mtr_start()221 void mtr_start() {
222 #ifndef MTR_ENABLED
223 return;
224 #endif
225 is_tracing = 1;
226 }
227
mtr_stop()228 void mtr_stop() {
229 #ifndef MTR_ENABLED
230 return;
231 #endif
232 is_tracing = 0;
233 }
234
235 // TODO: fwrite more than one line at a time.
mtr_flush()236 void mtr_flush() {
237 #ifndef MTR_ENABLED
238 return;
239 #endif
240 int i = 0;
241 char linebuf[1024];
242 char arg_buf[1024];
243 char id_buf[256];
244 // We have to lock while flushing. So we really should avoid flushing as much as possible.
245
246
247 pthread_mutex_lock(&mutex);
248 int old_tracing = is_tracing;
249 is_tracing = 0; // Stop logging even if using interlocked increments instead of the mutex. Can cause data loss.
250
251 for (i = 0; i < count; i++) {
252 raw_event_t *raw = &buffer[i];
253 int len;
254 switch (raw->arg_type) {
255 case MTR_ARG_TYPE_INT:
256 snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":%i", raw->arg_name, raw->a_int);
257 break;
258 case MTR_ARG_TYPE_STRING_CONST:
259 snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":\"%s\"", raw->arg_name, raw->a_str);
260 break;
261 case MTR_ARG_TYPE_STRING_COPY:
262 if (strlen(raw->a_str) > 700) {
263 snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":\"%.*s\"", raw->arg_name, 700, raw->a_str);
264 } else {
265 snprintf(arg_buf, ARRAY_SIZE(arg_buf), "\"%s\":\"%s\"", raw->arg_name, raw->a_str);
266 }
267 break;
268 case MTR_ARG_TYPE_NONE:
269 arg_buf[0] = '\0';
270 break;
271 }
272 if (raw->id) {
273 switch (raw->ph) {
274 case 'S':
275 case 'T':
276 case 'F':
277 // TODO: Support full 64-bit pointers
278 snprintf(id_buf, ARRAY_SIZE(id_buf), ",\"id\":\"0x%08x\"", (uint32_t)(uintptr_t)raw->id);
279 break;
280 case 'X':
281 snprintf(id_buf, ARRAY_SIZE(id_buf), ",\"dur\":%i", (int)raw->a_double);
282 break;
283 }
284 } else {
285 id_buf[0] = 0;
286 }
287 const char *cat = raw->cat;
288 #ifdef _WIN32
289 // On Windows, we often end up with backslashes in category.
290 char temp[256];
291 {
292 int len = (int)strlen(cat);
293 int i;
294 if (len > 255) len = 255;
295 for (i = 0; i < len; i++) {
296 temp[i] = cat[i] == '\\' ? '/' : cat[i];
297 }
298 temp[len] = 0;
299 cat = temp;
300 }
301 #endif
302
303 len = snprintf(linebuf, ARRAY_SIZE(linebuf), "%s{\"cat\":\"%s\",\"pid\":%i,\"tid\":%i,\"ts\":%" PRId64 ",\"ph\":\"%c\",\"name\":\"%s\",\"args\":{%s}%s}",
304 first_line ? "" : ",\n",
305 cat, raw->pid, raw->tid, raw->ts - time_offset, raw->ph, raw->name, arg_buf, id_buf);
306 fwrite(linebuf, 1, len, f);
307 first_line = 0;
308 }
309 count = 0;
310 is_tracing = old_tracing;
311 pthread_mutex_unlock(&mutex);
312 }
313
internal_mtr_raw_event(const char * category,const char * name,char ph,void * id)314 void internal_mtr_raw_event(const char *category, const char *name, char ph, void *id) {
315 #ifndef MTR_ENABLED
316 return;
317 #endif
318 if (!is_tracing || count >= INTERNAL_MINITRACE_BUFFER_SIZE)
319 return;
320 double ts = mtr_time_s();
321 if (!cur_thread_id) {
322 cur_thread_id = get_cur_thread_id();
323 }
324 if (!cur_process_id) {
325 cur_process_id = get_cur_process_id();
326 }
327
328 #if 0 && _WIN32 // This should work, feel free to enable if you're adventurous and need performance.
329 int bufPos = InterlockedExchangeAdd((LONG volatile *)&count, 1);
330 raw_event_t *ev = &buffer[bufPos];
331 #else
332 pthread_mutex_lock(&mutex);
333 raw_event_t *ev = &buffer[count];
334 count++;
335 pthread_mutex_unlock(&mutex);
336 #endif
337
338 ev->cat = category;
339 ev->name = name;
340 ev->id = id;
341 ev->ph = ph;
342 if (ev->ph == 'X') {
343 double x;
344 memcpy(&x, id, sizeof(double));
345 ev->ts = (int64_t)(x * 1000000);
346 ev->a_double = (ts - x) * 1000000;
347 } else {
348 ev->ts = (int64_t)(ts * 1000000);
349 }
350 ev->tid = cur_thread_id;
351 ev->pid = cur_process_id;
352 ev->arg_type = MTR_ARG_TYPE_NONE;
353 }
354
internal_mtr_raw_event_arg(const char * category,const char * name,char ph,void * id,mtr_arg_type arg_type,const char * arg_name,void * arg_value)355 void internal_mtr_raw_event_arg(const char *category, const char *name, char ph, void *id, mtr_arg_type arg_type, const char *arg_name, void *arg_value) {
356 #ifndef MTR_ENABLED
357 return;
358 #endif
359 if (!is_tracing || count >= INTERNAL_MINITRACE_BUFFER_SIZE)
360 return;
361 if (!cur_thread_id) {
362 cur_thread_id = get_cur_thread_id();
363 }
364 if (!cur_process_id) {
365 cur_process_id = get_cur_process_id();
366 }
367 double ts = mtr_time_s();
368
369 #if 0 && _WIN32 // This should work, feel free to enable if you're adventurous and need performance.
370 int bufPos = InterlockedExchangeAdd((LONG volatile *)&count, 1);
371 raw_event_t *ev = &buffer[bufPos];
372 #else
373 pthread_mutex_lock(&mutex);
374 raw_event_t *ev = &buffer[count];
375 count++;
376 pthread_mutex_unlock(&mutex);
377 #endif
378
379 ev->cat = category;
380 ev->name = name;
381 ev->id = id;
382 ev->ts = (int64_t)(ts * 1000000);
383 ev->ph = ph;
384 ev->tid = cur_thread_id;
385 ev->pid = cur_process_id;
386 ev->arg_type = arg_type;
387 ev->arg_name = arg_name;
388 switch (arg_type) {
389 case MTR_ARG_TYPE_INT: ev->a_int = (int)(uintptr_t)arg_value; break;
390 case MTR_ARG_TYPE_STRING_CONST: ev->a_str = (const char*)arg_value; break;
391 case MTR_ARG_TYPE_STRING_COPY: ev->a_str = strdup((const char*)arg_value); break;
392 case MTR_ARG_TYPE_NONE: break;
393 }
394 }
395
396