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