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