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