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