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 };
  54
  55 // Event type.
  56
  57 typedef struct _EventType {
  58   EventTypeNum etNum;  // Event Type number.
  59   nat   size;     // size of the payload in bytes
  60   char *desc;     // Description
  61 } EventType;
  62
  63 EventType eventTypes[NUM_EVENT_TAGS];
  64
  65 static void printAndClearEventBuf (EventsBuf *eventsBuf);
  66 static void initEventsBuf(EventsBuf* eb, StgWord64 size);
  67 static void resetEventsBuf(EventsBuf* eb);
  68
  69 static void beginHeader(EventsBuf *eb);
  70 static void endHeader(EventsBuf *eb);
  71
  72 static void beginData(EventsBuf *eb);
  73 static void endData(EventsBuf *eb);
  74
  75 static void beginEventTypes(EventsBuf *eb);
  76 static void endEventTypes(EventsBuf *eb);
  77
  78 static void postEventType(EventsBuf *eb, EventType *et);
  79
  80 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
  81
  82 static inline void postWord8(EventsBuf *eb, StgWord8 i)
  83 {
  84     *(eb->pos++) = i;
  85 }
  86
  87 static inline void postWord16(EventsBuf *eb, StgWord16 i)
  88 {
  89     postWord8(eb, (StgWord8)(i >> 8));
  90     postWord8(eb, (StgWord8)i);
  91 }
  92
  93 static inline void postWord32(EventsBuf *eb, StgWord32 i)
  94 {
  95     postWord16(eb, (StgWord16)(i >> 16));
  96     postWord16(eb, (StgWord16)i);
  97 }
  98
  99 static inline void postWord64(EventsBuf *eb, StgWord64 i)
 100 {
 101     postWord32(eb, (StgWord32)(i >> 32));
 102     postWord32(eb, (StgWord32)i);
 103 }
 104
 105 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
 106 { postWord16(eb, etNum); }
 107
 108 static inline void postEventTypeID(EventsBuf *eb, StgWord16 etID)
 109 { postWord16(eb, etID); }
 110
 111 static inline void postTimestamp(EventsBuf *eb, Timestamp t)
 112 { postWord64(eb,t); }
 113
 114 static inline void postThreadID(EventsBuf *eb, ThreadID id)
 115 { postWord32(eb,id); }
 116
 117 static inline void postCapNo(EventsBuf *eb, CapNo no)
 118 { postWord16(eb,no); }
 119
 120 static inline void postInt8(EventsBuf *eb, StgInt8 i)
 121 { postWord8(eb, (StgWord8)i); }
 122
 123 static inline void postInt16(EventsBuf *eb, StgInt16 i)
 124 { postWord16(eb, (StgWord16)i); }
 125
 126 static inline void postInt32(EventsBuf *eb, StgInt32 i)
 127 { postWord32(eb, (StgWord32)i); }
 128
 129 static inline void postInt64(EventsBuf *eb, StgInt64 i)
 130 { postWord64(eb, (StgWord64)i); }
 131
 132
 133 void
 134 initEventLogging(void)
 135 {
 136     StgWord8 t, c;
 137
 138     debugTrace(DEBUG_eventlog, "intiEventLog: start");
 139
 140     event_log_filename = stgMallocBytes(strlen(prog_name) + 9,
 141                                         "initEventLogging");
 142
 143     if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
 144         barf("EventDesc array has the wrong number of elements");
 145     }
 146
 147     sprintf(event_log_filename, "%s.eventlog", prog_name);
 148
 149     /* Open event log file for writing. */
 150     if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
 151         sysErrorBelch("initEventLoggin: can't open %s", event_log_filename);
 152         stg_exit(EXIT_FAILURE);
 153     }
 154
 155     /*
 156      * Allocate buffer(s) to store events.
 157      * Create buffer large enough for the header begin marker, all event
 158      * types, and header end marker to prevent checking if buffer has room
 159      * for each of these steps, and remove the need to flush the buffer to
 160      * disk during initialization.
 161      *
 162      * Use a single buffer to store the header with event types, then flush
 163      * the buffer so all buffers are empty for writing events.
 164      */
 165     eventsBuf = stgMallocBytes(n_capabilities * sizeof(EventsBuf),"initEventLogging");
 166
 167     for (c = 0; c < n_capabilities; ++c) {
 168         // Init buffer for events.
 169         initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE);
 170     }
 171
 172     // Write in buffer: the header begin marker.
 173     beginHeader(&eventsBuf[0]);
 174
 175     // Mark beginning of event types in the header.
 176     beginEventTypes(&eventsBuf[0]);
 177     for (t = 0; t < NUM_EVENT_TAGS; ++t) {
 178
 179         eventTypes[t].etNum = t;
 180         eventTypes[t].desc = EventDesc[t];
 181
 182         switch (t) {
 183         case EVENT_CREATE_THREAD:   // (cap, thread)
 184         case EVENT_RUN_THREAD:      // (cap, thread)
 185         case EVENT_THREAD_RUNNABLE: // (cap, thread)
 186         case EVENT_CREATE_SPARK:    // (cap, thread)
 187         case EVENT_RUN_SPARK:       // (cap, thread)
 188             eventTypes[t].size = sizeof(CapNo) + sizeof(ThreadID);
 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(CapNo) + sizeof(ThreadID) + sizeof(CapNo);
 196             break;
 197
 198         case EVENT_STOP_THREAD:     // (cap, thread, status)
 199             eventTypes[t].size =
 200                 sizeof(CapNo) + sizeof(ThreadID) + 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(CapNo);
 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_MIGRATE_THREAD:  // (cap, thread, new_cap)
 316     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 317     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 318     {
 319         postThreadID(eb,thread);
 320         postCapNo(eb,other /* new_cap | victim_cap | other_cap */);
 321         break;
 322     }
 323
 324     case EVENT_STOP_THREAD:     // (cap, thread, status)
 325     {
 326         postThreadID(eb,thread);
 327         postWord16(eb,other /* status */);
 328         break;
 329     }
 330
 331     case EVENT_SHUTDOWN:        // (cap)
 332     case EVENT_REQUEST_SEQ_GC:  // (cap)
 333     case EVENT_REQUEST_PAR_GC:  // (cap)
 334     case EVENT_GC_START:        // (cap)
 335     case EVENT_GC_END:          // (cap)
 336     {
 337         break;
 338     }
 339
 340     default:
 341         barf("postEvent: unknown event tag %d", tag);
 342     }
 343
 344     debugTrace(DEBUG_eventlog,"postEvent: finish");
 345 }
 346
 347 static void printAndClearEventBuf (EventsBuf *eventsBuf)
 348 {
 349     StgWord64 numBytes = 0, written = 0;
 350
 351     if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin)
 352     {
 353         numBytes = eventsBuf->pos - eventsBuf->begin;
 354
 355         debugTrace(DEBUG_eventlog,
 356                    "printAndEventLog: numbytes %" FMT_Word64
 357                    " bytes to fwrite()",
 358                    numBytes);
 359
 360         written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file);
 361         if (written != numBytes) {
 362             debugBelch(
 363                 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
 364                 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
 365             return;
 366         }
 367
 368         debugTrace(DEBUG_eventlog,
 369                    "printAndClearEventLog: fwrite(): %" FMT_Word64
 370                    " bytes written", written);
 371
 372         resetEventsBuf(eventsBuf);
 373         flushCount++;
 374     }
 375 }
 376
 377 void
 378 printAndClearEventLog(Capability *cap)
 379 {
 380     debugTrace(DEBUG_eventlog,"printAndClearEventLog: start");
 381
 382     printAndClearEventBuf(&eventsBuf[cap->no]);
 383
 384     debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish");
 385 }
 386
 387 /* -----------------------------------------------------------------------------
 388    Actual event generation below here
 389    -------------------------------------------------------------------------- */
 390
 391 void initEventsBuf(EventsBuf* eb, StgWord64 size)
 392 {
 393     eb->begin = eb->pos = malloc(size);
 394     eb->size = size;
 395 }
 396
 397 void resetEventsBuf(EventsBuf* eb)
 398 {
 399     eb->pos = eb->begin;
 400 }
 401
 402 // N.B.: Assuming buffer contains enough space for the header begin marker.
 403 void beginHeader(EventsBuf *eb)
 404 {
 405     postInt32(eb, EVENT_HEADER_BEGIN);
 406 }
 407
 408 // N.B.: Assuming buffer contains enough space for the header end marker.
 409 void endHeader(EventsBuf *eb)
 410 {
 411     postInt32(eb, EVENT_HEADER_END);
 412 }
 413
 414 void beginData(EventsBuf *eb)
 415 {
 416     postInt32(eb, EVENT_DATA_BEGIN);
 417 }
 418
 419 void endData(EventsBuf *eb)
 420 {
 421     postEventTypeNum(eb, EVENT_DATA_END);
 422 }
 423
 424 void beginEventTypes(EventsBuf *eb)
 425 {
 426     postInt32(eb, EVENT_HET_BEGIN);
 427 }
 428
 429 void endEventTypes(EventsBuf *eb)
 430 {
 431     postInt32(eb, EVENT_HET_END);
 432 }
 433
 434 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
 435 {
 436   nat size = 0;
 437
 438   size += sizeof(EventTypeNum) + sizeof(Timestamp) + eventTypes[eNum].size;
 439
 440   if (eb->pos + size > eb->begin + eb->size) {
 441       return 0; // Not enough space.
 442   } else  {
 443       return 1; // Buf has enough space for the event.
 444   }
 445 }
 446
 447 static void postEventType(EventsBuf *eb, EventType *et)
 448 {
 449     StgWord8 d;
 450     nat desclen;
 451
 452     postInt32(eb, EVENT_ET_BEGIN);
 453     postEventTypeNum(eb, et->etNum);
 454     postWord16(eb, (StgWord16)et->size);
 455     desclen = strlen(et->desc);
 456     postWord32(eb, desclen);
 457     for (d = 0; d < desclen; ++d) {
 458         postInt8(eb, (StgInt8)et->desc[d]);
 459     }
 460     postWord32(eb, 0); // no extensions yet
 461     postInt32(eb, EVENT_ET_END);
 462 }
 463
 464 #endif /* EVENTLOG */