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   "Create thread",
  43   "Run thread",
  44   "Stop thread",
  45   "Thread runnable",
  46   "Migrate thread",
  47   "Run spark",
  48   "Steal spark",
  49   "Shutdown",
  50   "Wakeup thread",
  51   "Starting GC",
  52   "Finished GC",
  53   "Request sequential GC",
  54   "Request parallel GC",
  55   "Create spark",
  56   "Spark to thread", /* DEPRECATED! */
  57   "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) + 9,
 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 = malloc(size);
 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 */