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