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