src/minitrace.c

   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
  78 static int get_cur_thread_id() {
  79         return (int)GetCurrentThreadId();
  80 }
  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;
  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
  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
 107 void mtr_register_sigint_handler() {
 108         // For console apps:
 109         SetConsoleCtrlHandler(&CtrlHandler, TRUE);
 110 }
 111
 112 #else
 113
 114 static inline int get_cur_thread_id() {
 115         return (int)(intptr_t)pthread_self();
 116 }
 117 static inline int get_cur_process_id() {
 118         return (int)getpid();
 119 }
 120
 121 #if defined(BLACKBERRY)
 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
 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;
 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
 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
 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
 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
 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
 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
 221 void mtr_start() {
 222 #ifndef MTR_ENABLED
 223         return;
 224 #endif
 225         is_tracing = 1;
 226 }
 227
 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.
 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
 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
 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