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