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