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