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   "Request sequential GC",
  49   "Request parallel GC",
  50   "Starting GC",
  51   "Finished 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 postInt8(EventsBuf *eb, StgInt8 i)
 115 { postWord8(eb, (StgWord8)i); }
 116
 117 static inline void postInt16(EventsBuf *eb, StgInt16 i)
 118 { postWord16(eb, (StgWord16)i); }
 119
 120 static inline void postInt32(EventsBuf *eb, StgInt32 i)
 121 { postWord32(eb, (StgWord32)i); }
 122
 123 static inline void postInt64(EventsBuf *eb, StgInt64 i)
 124 { postWord64(eb, (StgWord64)i); }
 125
 126
 127 void
 128 initEventLogging(void)
 129 {
 130     StgWord8 t, c;
 131
 132     debugTrace(DEBUG_eventlog, "intiEventLog: start");
 133
 134     event_log_filename = stgMallocBytes(strlen(prog_name) + 9,
 135                                         "initEventLogging");
 136
 137     if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
 138         barf("EventDesc array has the wrong number of elements");
 139     }
 140
 141     sprintf(event_log_filename, "%s.eventlog", prog_name);
 142
 143     /* Open event log file for writing. */
 144     if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
 145         sysErrorBelch("initEventLoggin: can't open %s", event_log_filename);
 146         stg_exit(EXIT_FAILURE);
 147     }
 148
 149     /*
 150      * Allocate buffer(s) to store events.
 151      * Create buffer large enough for the header begin marker, all event
 152      * types, and header end marker to prevent checking if buffer has room
 153      * for each of these steps, and remove the need to flush the buffer to
 154      * disk during initialization.
 155      *
 156      * Use a single buffer to store the header with event types, then flush
 157      * the buffer so all buffers are empty for writing events.
 158      */
 159     eventsBuf = stgMallocBytes(n_capabilities * sizeof(EventsBuf),"initEventLogging");
 160
 161     for (c = 0; c < n_capabilities; ++c) {
 162         // Init buffer for events.
 163         initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE);
 164     }
 165
 166     // Write in buffer: the header begin marker.
 167     beginHeader(&eventsBuf[0]);
 168
 169     // Mark beginning of event types in the header.
 170     beginEventTypes(&eventsBuf[0]);
 171     for (t = 0; t < NUM_EVENT_TAGS; ++t) {
 172
 173         eventTypes[t].etNum = t;
 174         eventTypes[t].desc = EventDesc[t];
 175
 176         switch (t) {
 177         case EVENT_CREATE_THREAD:   // (cap, thread)
 178         case EVENT_RUN_THREAD:      // (cap, thread)
 179         case EVENT_THREAD_RUNNABLE: // (cap, thread)
 180         case EVENT_CREATE_SPARK:    // (cap, thread)
 181         case EVENT_RUN_SPARK:       // (cap, thread)
 182             eventTypes[t].size = sizeof(CapabilityNum) + sizeof(ThreadID);
 183             break;
 184
 185         case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 186         case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 187         case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 188             eventTypes[t].size =
 189                 sizeof(CapabilityNum) + sizeof(ThreadID) +
 190                 sizeof(CapabilityNum);
 191             break;
 192
 193         case EVENT_STOP_THREAD:     // (cap, thread, status)
 194             eventTypes[t].size =
 195                 sizeof(CapabilityNum) + sizeof(ThreadID) + sizeof(StgWord16);
 196             break;
 197
 198         case EVENT_SHUTDOWN:        // (cap)
 199         case EVENT_REQUEST_SEQ_GC:  // (cap)
 200         case EVENT_REQUEST_PAR_GC:  // (cap)
 201         case EVENT_GC_START:        // (cap)
 202         case EVENT_GC_END:          // (cap)
 203             eventTypes[t].size = sizeof(CapabilityNum);
 204             break;
 205         }
 206
 207         // Write in buffer: the start event type.
 208         postEventType(&eventsBuf[0], &eventTypes[t]);
 209     }
 210
 211     // Mark end of event types in the header.
 212     endEventTypes(&eventsBuf[0]);
 213
 214     // Write in buffer: the header end marker.
 215     endHeader(&eventsBuf[0]);
 216
 217     // Prepare event buffer for events (data).
 218     beginData(&eventsBuf[0]);
 219
 220     // Flush eventsBuf with header.
 221     /*
 222      * Flush header and data begin marker to the file, thus preparing the
 223      * file to have events written to it.
 224      */
 225     printAndClearEventBuf(&eventsBuf[0]);
 226
 227     debugTrace(DEBUG_eventlog, "initEventLog: finish");
 228 }
 229
 230 void
 231 endEventLogging(void)
 232 {
 233     nat c;
 234
 235     debugTrace(DEBUG_eventlog,"endEventLog: start");
 236
 237     // Flush all events remaining in the buffers.
 238     for (c = 0; c < n_capabilities; ++c) {
 239         printAndClearEventBuf(&eventsBuf[c]);
 240     }
 241
 242     // Mark end of events (data).
 243     endData(&eventsBuf[0]);
 244
 245     // Flush the end of data marker.
 246     printAndClearEventBuf(&eventsBuf[0]);
 247
 248     if (event_log_file != NULL) {
 249         fclose(event_log_file);
 250     }
 251
 252     debugTrace(DEBUG_eventlog,"endEventLog: finish");
 253 }
 254
 255 void
 256 freeEventLogging(void)
 257 {
 258     StgWord8 c;
 259
 260     debugTrace(DEBUG_eventlog,"freeEventLog: start");
 261
 262     // Free events buffer.
 263     for (c = 0; c < n_capabilities; ++c) {
 264         if (eventsBuf[c].begin != NULL)
 265             stgFree(eventsBuf[c].begin);
 266     }
 267     if (eventsBuf != NULL)  {
 268         stgFree(eventsBuf);
 269     }
 270     if (event_log_filename != NULL) {
 271         stgFree(event_log_filename);
 272     }
 273
 274     debugTrace(DEBUG_eventlog,"freeEventLog: finish");
 275 }
 276
 277 /*
 278  * Post an event message to the capability's eventlog buffer.
 279  * If the buffer is full, prints out the buffer and clears it.
 280  */
 281 void
 282 postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap)
 283 {
 284     EventsBuf *eb;
 285
 286     debugTrace(DEBUG_eventlog,"postEvent: start");
 287
 288     eb = &eventsBuf[cap->no];
 289
 290     if (!hasRoomForEvent(eb, tag)) {
 291         // Flush event buffer to make room for new event.
 292         printAndClearEventBuf(eb);
 293     }
 294
 295     postEventTypeNum(eb, tag);
 296     postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND));
 297     postWord16(eb, cap->no);
 298
 299     switch (tag) {
 300     case EVENT_CREATE_THREAD:   // (cap, thread)
 301     case EVENT_RUN_THREAD:      // (cap, thread)
 302     case EVENT_THREAD_RUNNABLE: // (cap, thread)
 303     case EVENT_CREATE_SPARK:    // (cap, thread)
 304     case EVENT_RUN_SPARK:       // (cap, thread)
 305     {
 306         postWord64(eb,thread);
 307         break;
 308     }
 309
 310     case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
 311     case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
 312     case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
 313     {
 314         postWord64(eb,thread);
 315         postWord16(eb,other_cap);
 316         break;
 317     }
 318
 319     case EVENT_STOP_THREAD:     // (cap, thread, status)
 320     {
 321         postWord64(eb,thread);
 322         postWord16(eb,other_cap);
 323         break;
 324     }
 325
 326     case EVENT_SHUTDOWN:        // (cap)
 327     case EVENT_REQUEST_SEQ_GC:  // (cap)
 328     case EVENT_REQUEST_PAR_GC:  // (cap)
 329     case EVENT_GC_START:        // (cap)
 330     case EVENT_GC_END:          // (cap)
 331     {
 332         break;
 333     }
 334
 335     default:
 336         barf("postEvent: unknown event tag %d", tag);
 337     }
 338
 339     debugTrace(DEBUG_eventlog,"postEvent: finish");
 340 }
 341
 342 static void printAndClearEventBuf (EventsBuf *eventsBuf)
 343 {
 344     StgWord64 numBytes = 0, written = 0;
 345
 346     if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin)
 347     {
 348         numBytes = eventsBuf->pos - eventsBuf->begin;
 349
 350         debugTrace(DEBUG_eventlog,
 351                    "printAndEventLog: numbytes %" FMT_Word64
 352                    " bytes to fwrite()",
 353                    numBytes);
 354
 355         written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file);
 356         if (written != numBytes) {
 357             debugBelch(
 358                 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
 359                 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
 360             return;
 361         }
 362
 363         debugTrace(DEBUG_eventlog,
 364                    "printAndClearEventLog: fwrite(): %" FMT_Word64
 365                    " bytes written", written);
 366
 367         resetEventsBuf(eventsBuf);
 368         flushCount++;
 369     }
 370 }
 371
 372 void
 373 printAndClearEventLog(Capability *cap)
 374 {
 375     debugTrace(DEBUG_eventlog,"printAndClearEventLog: start");
 376
 377     printAndClearEventBuf(&eventsBuf[cap->no]);
 378
 379     debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish");
 380 }
 381
 382 /* -----------------------------------------------------------------------------
 383    Actual event generation below here
 384    -------------------------------------------------------------------------- */
 385
 386 void initEventsBuf(EventsBuf* eb, StgWord64 size)
 387 {
 388     eb->begin = eb->pos = malloc(size);
 389     eb->size = size;
 390 }
 391
 392 void resetEventsBuf(EventsBuf* eb)
 393 {
 394     eb->pos = eb->begin;
 395 }
 396
 397 // N.B.: Assuming buffer contains enough space for the header begin marker.
 398 void beginHeader(EventsBuf *eb)
 399 {
 400     postInt32(eb, EVENT_HEADER_BEGIN);
 401 }
 402
 403 // N.B.: Assuming buffer contains enough space for the header end marker.
 404 void endHeader(EventsBuf *eb)
 405 {
 406     postInt32(eb, EVENT_HEADER_END);
 407 }
 408
 409 void beginData(EventsBuf *eb)
 410 {
 411     postInt32(eb, EVENT_DATA_BEGIN);
 412 }
 413
 414 void endData(EventsBuf *eb)
 415 {
 416     postEventTypeNum(eb, EVENT_DATA_END);
 417 }
 418
 419 void beginEventTypes(EventsBuf *eb)
 420 {
 421     postInt32(eb, EVENT_HET_BEGIN);
 422 }
 423
 424 void endEventTypes(EventsBuf *eb)
 425 {
 426     postInt32(eb, EVENT_HET_END);
 427 }
 428
 429 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
 430 {
 431   nat size = 0;
 432
 433   size += sizeof(EventTypeNum) + sizeof(Timestamp) + eventTypes[eNum].size;
 434
 435   if (eb->pos + size > eb->begin + eb->size) {
 436       return 0; // Not enough space.
 437   } else  {
 438       return 1; // Buf has enough space for the event.
 439   }
 440 }
 441
 442 static void postEventType(EventsBuf *eb, EventType *et)
 443 {
 444     StgWord8 d;
 445     nat desclen;
 446
 447     postInt32(eb, EVENT_ET_BEGIN);
 448     postEventTypeNum(eb, et->etNum);
 449     postWord16(eb, (StgWord16)et->size);
 450     desclen = strlen(et->desc);
 451     postWord32(eb, desclen);
 452     for (d = 0; d < desclen; ++d) {
 453         postInt8(eb, (StgInt8)et->desc[d]);
 454     }
 455     postWord32(eb, 0); // no extensions yet
 456     postInt32(eb, EVENT_ET_END);
 457 }
 458
 459 #endif /* EVENTLOG */