rts/eventlog/EventLog.c

   1 /* -----------------------------------------------------------------------------
   2  *
   3  * (c) The GHC Team, 2008-2009
   4  *
   5  * Support for fast binary event logging.
   6  *
   7  * ---------------------------------------------------------------------------*/
   8
   9 #ifdef EVENTLOG
  10
  11 #include "Rts.h"
  12 #include "EventLog.h"
  13 #include "Capability.h"
  14 #include "Trace.h"
  15 #include "RtsUtils.h"
  16 #include "Stats.h"
  17 #include <string.h>
  18 #include <stdio.h>
  19
  20 static char *event_log_filename = NULL;
  21
  22 // File for logging events
  23 FILE *event_log_file = NULL;
  24
  25 #define EVENT_LOG_SIZE 2 * (1024 * 1024) // 2MB
  26
  27 static int flushCount;
  28
  29 // Struct for record keeping of buffer to store event types and events.
  30 typedef struct _EventsBuf {
  31   StgInt8 *begin;
  32   StgInt8 *pos;
  33   StgWord64 size;
  34 } EventsBuf;
  35
  36 EventsBuf *eventsBuf;
  37
  38 char *EventDesc[] = {
  39   "Create thread",
  40   "Run thread",
  41   "Stop thread",
  42   "Thread runnable",
  43   "Migrate thread",
  44   "Run spark",
  45   "Steal spark",
  46   "Shutdown",
  47   "Wakeup thread",
  48   "Starting GC",
  49   "Finished GC",
  50   "Request sequential GC",
  51   "Request parallel GC",
  52   "Create spark",
  53   "Spark to thread", /* DEPRECATED! */
  54   "Create spark thread"
  55 };
  56
  57 // Event type.
  58
  59 typedef struct _EventType {
  60   EventTypeNum etNum;  // Event Type number.
  61   nat   size;     // size of the payload in bytes
  62   char *desc;     // Description
  63 } EventType;
  64
  65 EventType eventTypes[NUM_EVENT_TAGS];
  66
  67 static void printAndClearEventBuf (EventsBuf *eventsBuf);
  68 static void initEventsBuf(EventsBuf* eb, StgWord64 size);
  69 static void resetEventsBuf(EventsBuf* eb);
  70
  71 static void beginHeader(EventsBuf *eb);
  72 static void endHeader(EventsBuf *eb);
  73
  74 static void beginData(EventsBuf *eb);
  75 static void endData(EventsBuf *eb);
  76
  77 static void beginEventTypes(EventsBuf *eb);
  78 static void endEventTypes(EventsBuf *eb);
  79
  80 static void postEventType(EventsBuf *eb, EventType *et);
  81
  82 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
  83
  84 static inline void postWord8(EventsBuf *eb, StgWord8 i)
  85 {
  86     *(eb->pos++) = i;
  87 }
  88
  89 static inline void postWord16(EventsBuf *eb, StgWord16 i)
  90 {
  91     postWord8(eb, (StgWord8)(i >> 8));
  92     postWord8(eb, (StgWord8)i);
  93 }
  94
  95 static inline void postWord32(EventsBuf *eb, StgWord32 i)
  96 {
  97     postWord16(eb, (StgWord16)(i >> 16));
  98     postWord16(eb, (StgWord16)i);
  99 }
 100
 101 static inline void postWord64(EventsBuf *eb, StgWord64 i)
 102 {
 103     postWord32(eb, (StgWord32)(i >> 32));
 104     postWord32(eb, (StgWord32)i);
 105 }
 106
 107 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
 108 { postWord16(eb, etNum); }
 109
 110 static inline void postTimestamp(EventsBuf *eb, EventTimestamp t)
 111 { postWord64(eb,t); }
 112
 113 static inline void postThreadID(EventsBuf *eb, EventThreadID id)
 114 { postWord32(eb,id); }
 115
 116 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
 117 { postWord16(eb,no); }
 118
 119 static inline void postInt8(EventsBuf *eb, StgInt8 i)
 120 { postWord8(eb, (StgWord8)i); }
 121
 122 static inline void postInt16(EventsBuf *eb, StgInt16 i)
 123 { postWord16(eb, (StgWord16)i); }
 124
 125 static inline void postInt32(EventsBuf *eb, StgInt32 i)
 126 { postWord32(eb, (StgWord32)i); }
 127
 128 static inline void postInt64(EventsBuf *eb, StgInt64 i)
 129 { postWord64(eb, (StgWord64)i); }
 130
 131
 132 void
 133 initEventLogging(void)
 134 {
 135     StgWord8 t, c;
 136
 137     debugTrace(DEBUG_eventlog, "intiEventLog: start");
 138
 139     event_log_filename = stgMallocBytes(strlen(prog_name) + 9,
 140                                         "initEventLogging");
 141
 142     if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
 143         barf("EventDesc array has the wrong number of elements");
 144     }
 145
 146     sprintf(event_log_filename, "%s.eventlog", prog_name);
 147
 148     /* Open event log file for writing. */
 149     if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
 150         sysErrorBelch("initEventLoggin: can't open %s", event_log_filename);
 151         stg_exit(EXIT_FAILURE);
 152     }
 153
 154     /*
 155      * Allocate buffer(s) to store events.
 156      * Create buffer large enough for the header begin marker, all event
 157      * types, and header end marker to prevent checking if buffer has room
 158      * for each of these steps, and remove the need to flush the buffer to
 159      * disk during initialization.
 160      *
 161      * Use a single buffer to store the header with event types, then flush
 162      * the buffer so all buffers are empty for writing events.
 163      */
 164     eventsBuf = stgMallocBytes(n_capabilities * sizeof(EventsBuf),"initEventLogging");
 165
 166     for (c = 0; c < n_capabilities; ++c) {
 167         // Init buffer for events.
 168         initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE);
 169     }
 170
 171     // Write in buffer: the header begin marker.
 172     beginHeader(&eventsBuf[0]);
 173
 174     // Mark beginning of event types in the header.
 175     beginEventTypes(&eventsBuf[0]);
 176     for (t = 0; t < NUM_EVENT_TAGS; ++t) {
 177
 178         eventTypes[t].etNum = t;
 179         eventTypes[t].desc = EventDesc[t];
 180
 181         switch (t) {
 182         case EVENT_CREATE_THREAD:   // (cap, thread)
 183         case EVENT_RUN_THREAD:      // (cap, thread)
 184         case EVENT_THREAD_RUNNABLE: // (cap, thread)
 185         case EVENT_CREATE_SPARK:    // (cap, thread)
 186         case EVENT_RUN_SPARK:       // (cap, thread)
 187         case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 188             eventTypes[t].size = sizeof(EventCapNo) + sizeof(EventThreadID);
 189             break;
 190
 191         case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 192         case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 193         case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 194             eventTypes[t].size =
 195                 sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(EventCapNo);
 196             break;
 197
 198         case EVENT_STOP_THREAD:     // (cap, thread, status)
 199             eventTypes[t].size =
 200                 sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(StgWord16);
 201             break;
 202
 203         case EVENT_SHUTDOWN:        // (cap)
 204         case EVENT_REQUEST_SEQ_GC:  // (cap)
 205         case EVENT_REQUEST_PAR_GC:  // (cap)
 206         case EVENT_GC_START:        // (cap)
 207         case EVENT_GC_END:          // (cap)
 208             eventTypes[t].size = sizeof(EventCapNo);
 209             break;
 210         }
 211
 212         // Write in buffer: the start event type.
 213         postEventType(&eventsBuf[0], &eventTypes[t]);
 214     }
 215
 216     // Mark end of event types in the header.
 217     endEventTypes(&eventsBuf[0]);
 218
 219     // Write in buffer: the header end marker.
 220     endHeader(&eventsBuf[0]);
 221
 222     // Prepare event buffer for events (data).
 223     beginData(&eventsBuf[0]);
 224
 225     // Flush eventsBuf with header.
 226     /*
 227      * Flush header and data begin marker to the file, thus preparing the
 228      * file to have events written to it.
 229      */
 230     printAndClearEventBuf(&eventsBuf[0]);
 231
 232     debugTrace(DEBUG_eventlog, "initEventLog: finish");
 233 }
 234
 235 void
 236 endEventLogging(void)
 237 {
 238     nat c;
 239
 240     debugTrace(DEBUG_eventlog,"endEventLog: start");
 241
 242     // Flush all events remaining in the buffers.
 243     for (c = 0; c < n_capabilities; ++c) {
 244         printAndClearEventBuf(&eventsBuf[c]);
 245     }
 246
 247     // Mark end of events (data).
 248     endData(&eventsBuf[0]);
 249
 250     // Flush the end of data marker.
 251     printAndClearEventBuf(&eventsBuf[0]);
 252
 253     if (event_log_file != NULL) {
 254         fclose(event_log_file);
 255     }
 256
 257     debugTrace(DEBUG_eventlog,"endEventLog: finish");
 258 }
 259
 260 void
 261 freeEventLogging(void)
 262 {
 263     StgWord8 c;
 264
 265     debugTrace(DEBUG_eventlog,"freeEventLog: start");
 266
 267     // Free events buffer.
 268     for (c = 0; c < n_capabilities; ++c) {
 269         if (eventsBuf[c].begin != NULL)
 270             stgFree(eventsBuf[c].begin);
 271     }
 272     if (eventsBuf != NULL)  {
 273         stgFree(eventsBuf);
 274     }
 275     if (event_log_filename != NULL) {
 276         stgFree(event_log_filename);
 277     }
 278
 279     debugTrace(DEBUG_eventlog,"freeEventLog: finish");
 280 }
 281
 282 /*
 283  * Post an event message to the capability's eventlog buffer.
 284  * If the buffer is full, prints out the buffer and clears it.
 285  */
 286 void
 287 postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, StgWord64 other)
 288 {
 289     EventsBuf *eb;
 290
 291     debugTrace(DEBUG_eventlog,"postEvent: start");
 292
 293     eb = &eventsBuf[cap->no];
 294
 295     if (!hasRoomForEvent(eb, tag)) {
 296         // Flush event buffer to make room for new event.
 297         printAndClearEventBuf(eb);
 298     }
 299
 300     postEventTypeNum(eb, tag);
 301     postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND));
 302     postCapNo(eb, cap->no);
 303
 304     switch (tag) {
 305     case EVENT_CREATE_THREAD:   // (cap, thread)
 306     case EVENT_RUN_THREAD:      // (cap, thread)
 307     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 308     case EVENT_CREATE_SPARK:    // (cap, thread)
 309     case EVENT_RUN_SPARK:       // (cap, thread)
 310     {
 311         postThreadID(eb,thread);
 312         break;
 313     }
 314
 315     case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
 316     {
 317         postThreadID(eb,other /* spark_thread */);
 318         break;
 319     }
 320
 321     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 322     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 323     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 324     {
 325         postThreadID(eb,thread);
 326         postCapNo(eb,other /* new_cap | victim_cap | other_cap */);
 327         break;
 328     }
 329
 330     case EVENT_STOP_THREAD:     // (cap, thread, status)
 331     {
 332         postThreadID(eb,thread);
 333         postWord16(eb,other /* status */);
 334         break;
 335     }
 336
 337     case EVENT_SHUTDOWN:        // (cap)
 338     case EVENT_REQUEST_SEQ_GC:  // (cap)
 339     case EVENT_REQUEST_PAR_GC:  // (cap)
 340     case EVENT_GC_START:        // (cap)
 341     case EVENT_GC_END:          // (cap)
 342     {
 343         break;
 344     }
 345
 346     default:
 347         barf("postEvent: unknown event tag %d", tag);
 348     }
 349
 350     debugTrace(DEBUG_eventlog,"postEvent: finish");
 351 }
 352
 353 static void printAndClearEventBuf (EventsBuf *eventsBuf)
 354 {
 355     StgWord64 numBytes = 0, written = 0;
 356
 357     if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin)
 358     {
 359         numBytes = eventsBuf->pos - eventsBuf->begin;
 360
 361         debugTrace(DEBUG_eventlog,
 362                    "printAndEventLog: numbytes %" FMT_Word64
 363                    " bytes to fwrite()",
 364                    numBytes);
 365
 366         written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file);
 367         if (written != numBytes) {
 368             debugBelch(
 369                 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
 370                 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
 371             return;
 372         }
 373
 374         debugTrace(DEBUG_eventlog,
 375                    "printAndClearEventLog: fwrite(): %" FMT_Word64
 376                    " bytes written", written);
 377
 378         resetEventsBuf(eventsBuf);
 379         flushCount++;
 380     }
 381 }
 382
 383 void
 384 printAndClearEventLog(Capability *cap)
 385 {
 386     debugTrace(DEBUG_eventlog,"printAndClearEventLog: start");
 387
 388     printAndClearEventBuf(&eventsBuf[cap->no]);
 389
 390     debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish");
 391 }
 392
 393 /* -----------------------------------------------------------------------------
 394    Actual event generation below here
 395    -------------------------------------------------------------------------- */
 396
 397 void initEventsBuf(EventsBuf* eb, StgWord64 size)
 398 {
 399     eb->begin = eb->pos = malloc(size);
 400     eb->size = size;
 401 }
 402
 403 void resetEventsBuf(EventsBuf* eb)
 404 {
 405     eb->pos = eb->begin;
 406 }
 407
 408 // N.B.: Assuming buffer contains enough space for the header begin marker.
 409 void beginHeader(EventsBuf *eb)
 410 {
 411     postInt32(eb, EVENT_HEADER_BEGIN);
 412 }
 413
 414 // N.B.: Assuming buffer contains enough space for the header end marker.
 415 void endHeader(EventsBuf *eb)
 416 {
 417     postInt32(eb, EVENT_HEADER_END);
 418 }
 419
 420 void beginData(EventsBuf *eb)
 421 {
 422     postInt32(eb, EVENT_DATA_BEGIN);
 423 }
 424
 425 void endData(EventsBuf *eb)
 426 {
 427     postEventTypeNum(eb, EVENT_DATA_END);
 428 }
 429
 430 void beginEventTypes(EventsBuf *eb)
 431 {
 432     postInt32(eb, EVENT_HET_BEGIN);
 433 }
 434
 435 void endEventTypes(EventsBuf *eb)
 436 {
 437     postInt32(eb, EVENT_HET_END);
 438 }
 439
 440 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
 441 {
 442   nat size = 0;
 443
 444   size += sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
 445
 446   if (eb->pos + size > eb->begin + eb->size) {
 447       return 0; // Not enough space.
 448   } else  {
 449       return 1; // Buf has enough space for the event.
 450   }
 451 }
 452
 453 static void postEventType(EventsBuf *eb, EventType *et)
 454 {
 455     StgWord8 d;
 456     nat desclen;
 457
 458     postInt32(eb, EVENT_ET_BEGIN);
 459     postEventTypeNum(eb, et->etNum);
 460     postWord16(eb, (StgWord16)et->size);
 461     desclen = strlen(et->desc);
 462     postWord32(eb, desclen);
 463     for (d = 0; d < desclen; ++d) {
 464         postInt8(eb, (StgInt8)et->desc[d]);
 465     }
 466     postWord32(eb, 0); // no extensions yet
 467     postInt32(eb, EVENT_ET_END);
 468 }
 469
 470 #endif /* EVENTLOG */