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