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