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