EventLog.c 14.4 KB
Newer Older
Simon Marlow's avatar
Simon Marlow committed
1 2 3 4 5 6 7 8
/* -----------------------------------------------------------------------------
 *
 * (c) The GHC Team, 2008-2009
 *
 * Support for fast binary event logging.
 *
 * ---------------------------------------------------------------------------*/

Simon Marlow's avatar
Simon Marlow committed
9
#include "PosixSource.h"
Simon Marlow's avatar
Simon Marlow committed
10
#include "Rts.h"
Simon Marlow's avatar
Simon Marlow committed
11

12 13 14
#ifdef TRACING

#include "Trace.h"
Simon Marlow's avatar
Simon Marlow committed
15 16 17 18
#include "Capability.h"
#include "Trace.h"
#include "RtsUtils.h"
#include "Stats.h"
19
#include "EventLog.h"
Simon Marlow's avatar
Simon Marlow committed
20

Simon Marlow's avatar
Simon Marlow committed
21 22 23 24 25 26 27 28 29 30 31 32 33 34 35 36
#include <string.h> 
#include <stdio.h>

static char *event_log_filename = NULL;

// File for logging events
FILE *event_log_file = NULL;

#define EVENT_LOG_SIZE 2 * (1024 * 1024) // 2MB

static int flushCount;

// Struct for record keeping of buffer to store event types and events.
typedef struct _EventsBuf {
  StgInt8 *begin;
  StgInt8 *pos;
Simon Marlow's avatar
Simon Marlow committed
37
  StgInt8 *marker;
Simon Marlow's avatar
Simon Marlow committed
38 39 40
  StgWord64 size;
} EventsBuf;

41 42 43 44 45 46
EventsBuf *capEventBuf; // one EventsBuf for each Capability

EventsBuf eventBuf; // an EventsBuf not associated with any Capability
#ifdef THREADED_RTS
Mutex eventBufMutex; // protected by this mutex
#endif
Simon Marlow's avatar
Simon Marlow committed
47 48

char *EventDesc[] = {
49 50 51 52 53 54 55 56 57 58 59 60 61
  [EVENT_CREATE_THREAD]       = "Create thread",
  [EVENT_RUN_THREAD]          = "Run thread",
  [EVENT_STOP_THREAD]         = "Stop thread",
  [EVENT_THREAD_RUNNABLE]     = "Thread runnable",
  [EVENT_MIGRATE_THREAD]      = "Migrate thread",
  [EVENT_RUN_SPARK]           = "Run spark",
  [EVENT_STEAL_SPARK]         = "Steal spark",
  [EVENT_SHUTDOWN]            = "Shutdown",
  [EVENT_THREAD_WAKEUP]       = "Wakeup thread",
  [EVENT_GC_START]            = "Starting GC",
  [EVENT_GC_END]              = "Finished GC",
  [EVENT_REQUEST_SEQ_GC]      = "Request sequential GC",
  [EVENT_REQUEST_PAR_GC]      = "Request parallel GC",
62 63 64
  [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
  [EVENT_LOG_CAP_MSG]         = "Log Capability message",
  [EVENT_LOG_MSG]             = "Log message",
Simon Marlow's avatar
Simon Marlow committed
65 66
  [EVENT_STARTUP]             = "Startup",
  [EVENT_BLOCK_MARKER]        = "Block marker"
Simon Marlow's avatar
Simon Marlow committed
67 68 69 70 71 72 73 74 75 76 77 78 79 80
};

// Event type. 

typedef struct _EventType {
  EventTypeNum etNum;  // Event Type number.
  nat   size;     // size of the payload in bytes
  char *desc;     // Description
} EventType;

EventType eventTypes[NUM_EVENT_TAGS];

static void initEventsBuf(EventsBuf* eb, StgWord64 size);
static void resetEventsBuf(EventsBuf* eb);
Simon Marlow's avatar
Simon Marlow committed
81
static void printAndClearEventBuf (EventsBuf *eventsBuf);
Simon Marlow's avatar
Simon Marlow committed
82 83 84

static void postEventType(EventsBuf *eb, EventType *et);

Simon Marlow's avatar
Simon Marlow committed
85 86 87
static void postBlockMarker(EventsBuf *eb);
static void closeBlockMarker(EventsBuf *ebuf);

Simon Marlow's avatar
Simon Marlow committed
88
static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
89
static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);
Simon Marlow's avatar
Simon Marlow committed
90

91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113
static inline void postWord8(EventsBuf *eb, StgWord8 i)
{
    *(eb->pos++) = i; 
}

static inline void postWord16(EventsBuf *eb, StgWord16 i)
{
    postWord8(eb, (StgWord8)(i >> 8));
    postWord8(eb, (StgWord8)i);
}

static inline void postWord32(EventsBuf *eb, StgWord32 i)
{
    postWord16(eb, (StgWord16)(i >> 16));
    postWord16(eb, (StgWord16)i);
}

static inline void postWord64(EventsBuf *eb, StgWord64 i)
{
    postWord32(eb, (StgWord32)(i >> 32));
    postWord32(eb, (StgWord32)i);
}

114 115 116 117 118 119
static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
{
    memcpy(eb->pos, buf, size);
    eb->pos += size;
}

Simon Marlow's avatar
Simon Marlow committed
120 121 122
static inline StgWord64 time_ns(void)
{ return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); }

123 124 125
static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
{ postWord16(eb, etNum); }

Simon Marlow's avatar
Simon Marlow committed
126 127
static inline void postTimestamp(EventsBuf *eb)
{ postWord64(eb, time_ns()); }
128

129
static inline void postThreadID(EventsBuf *eb, EventThreadID id)
130 131
{ postWord32(eb,id); }

132
static inline void postCapNo(EventsBuf *eb, EventCapNo no)
133 134
{ postWord16(eb,no); }

135 136 137
static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
{ postWord16(eb,size); }

Simon Marlow's avatar
Simon Marlow committed
138 139 140 141 142 143
static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
{
    postEventTypeNum(eb, type);
    postTimestamp(eb);
}    

144 145 146 147 148 149 150 151 152 153 154 155
static inline void postInt8(EventsBuf *eb, StgInt8 i)
{ postWord8(eb, (StgWord8)i); }

static inline void postInt16(EventsBuf *eb, StgInt16 i)
{ postWord16(eb, (StgWord16)i); }

static inline void postInt32(EventsBuf *eb, StgInt32 i)
{ postWord32(eb, (StgWord32)i); }

static inline void postInt64(EventsBuf *eb, StgInt64 i)
{ postWord64(eb, (StgWord64)i); }

Simon Marlow's avatar
Simon Marlow committed
156 157 158 159 160

void
initEventLogging(void)
{
    StgWord8 t, c;
161
    nat n_caps;
Simon Marlow's avatar
Simon Marlow committed
162

163
    event_log_filename = stgMallocBytes(strlen(prog_name) + 10,
Simon Marlow's avatar
Simon Marlow committed
164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187
                                        "initEventLogging");

    if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
        barf("EventDesc array has the wrong number of elements");
    }
  
    sprintf(event_log_filename, "%s.eventlog", prog_name);
    
    /* Open event log file for writing. */
    if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
        sysErrorBelch("initEventLoggin: can't open %s", event_log_filename);
        stg_exit(EXIT_FAILURE);    
    }

    /* 
     * Allocate buffer(s) to store events.
     * Create buffer large enough for the header begin marker, all event
     * types, and header end marker to prevent checking if buffer has room
     * for each of these steps, and remove the need to flush the buffer to
     * disk during initialization.
     *
     * Use a single buffer to store the header with event types, then flush 
     * the buffer so all buffers are empty for writing events.
     */
188 189 190 191 192 193 194 195 196
#ifdef THREADED_RTS
    // XXX n_capabilities hasn't been initislised yet
    n_caps = RtsFlags.ParFlags.nNodes;
#else
    n_caps = 1;
#endif
    capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging");

    for (c = 0; c < n_caps; ++c) {
Simon Marlow's avatar
Simon Marlow committed
197
        // Init buffer for events.
198
        initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE);
Simon Marlow's avatar
Simon Marlow committed
199
    }
200
    initEventsBuf(&eventBuf, EVENT_LOG_SIZE);
Simon Marlow's avatar
Simon Marlow committed
201 202

    // Write in buffer: the header begin marker.
Simon Marlow's avatar
Simon Marlow committed
203
    postInt32(&eventBuf, EVENT_HEADER_BEGIN);
Simon Marlow's avatar
Simon Marlow committed
204 205

    // Mark beginning of event types in the header.
Simon Marlow's avatar
Simon Marlow committed
206
    postInt32(&eventBuf, EVENT_HET_BEGIN);
Simon Marlow's avatar
Simon Marlow committed
207 208 209 210 211 212 213 214 215 216
    for (t = 0; t < NUM_EVENT_TAGS; ++t) {

        eventTypes[t].etNum = t;
        eventTypes[t].desc = EventDesc[t];

        switch (t) {
        case EVENT_CREATE_THREAD:   // (cap, thread)
        case EVENT_RUN_THREAD:      // (cap, thread)
        case EVENT_THREAD_RUNNABLE: // (cap, thread)
        case EVENT_RUN_SPARK:       // (cap, thread)
217 218
        case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
            eventTypes[t].size = sizeof(EventCapNo) + sizeof(EventThreadID);
219 220
            break;

Simon Marlow's avatar
Simon Marlow committed
221 222 223 224
        case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
        case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
        case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
            eventTypes[t].size =
225
                sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(EventCapNo);
Simon Marlow's avatar
Simon Marlow committed
226 227 228 229
            break;

        case EVENT_STOP_THREAD:     // (cap, thread, status)
            eventTypes[t].size =
230
                sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(StgWord16);
Simon Marlow's avatar
Simon Marlow committed
231 232 233 234 235 236 237
            break;

        case EVENT_SHUTDOWN:        // (cap)
        case EVENT_REQUEST_SEQ_GC:  // (cap)
        case EVENT_REQUEST_PAR_GC:  // (cap)
        case EVENT_GC_START:        // (cap)
        case EVENT_GC_END:          // (cap)
238
            eventTypes[t].size = sizeof(EventCapNo);
Simon Marlow's avatar
Simon Marlow committed
239
            break;
240 241 242 243 244 245

        case EVENT_LOG_MSG:          // (msg)
        case EVENT_LOG_CAP_MSG:      // (cap,msg)
            eventTypes[t].size = 0xffff;
            break;

Simon Marlow's avatar
Simon Marlow committed
246 247 248 249 250 251 252 253
        case EVENT_STARTUP:
            eventTypes[t].size = sizeof(EventCapNo);
            break;

        case EVENT_BLOCK_MARKER:
            eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp);
            break;

254 255
        default:
            continue; /* ignore deprecated events */
Simon Marlow's avatar
Simon Marlow committed
256 257 258
        }

        // Write in buffer: the start event type.
259
        postEventType(&eventBuf, &eventTypes[t]);
Simon Marlow's avatar
Simon Marlow committed
260 261 262
    }

    // Mark end of event types in the header.
Simon Marlow's avatar
Simon Marlow committed
263
    postInt32(&eventBuf, EVENT_HET_END);
Simon Marlow's avatar
Simon Marlow committed
264 265
    
    // Write in buffer: the header end marker.
Simon Marlow's avatar
Simon Marlow committed
266
    postInt32(&eventBuf, EVENT_HEADER_END);
Simon Marlow's avatar
Simon Marlow committed
267 268
    
    // Prepare event buffer for events (data).
Simon Marlow's avatar
Simon Marlow committed
269
    postInt32(&eventBuf, EVENT_DATA_BEGIN);
Simon Marlow's avatar
Simon Marlow committed
270
    
271
    // Flush capEventBuf with header.
Simon Marlow's avatar
Simon Marlow committed
272 273 274 275
    /*
     * Flush header and data begin marker to the file, thus preparing the
     * file to have events written to it.
     */
276
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
277 278 279 280

    for (c = 0; c < n_caps; ++c) {
        postBlockMarker(&capEventBuf[c]);
    }
Simon Marlow's avatar
Simon Marlow committed
281 282 283 284 285 286 287 288 289
}

void
endEventLogging(void)
{
    nat c;

    // Flush all events remaining in the buffers.
    for (c = 0; c < n_capabilities; ++c) {
290
        printAndClearEventBuf(&capEventBuf[c]);
Simon Marlow's avatar
Simon Marlow committed
291
    }
292
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
293 294

    // Mark end of events (data).
Simon Marlow's avatar
Simon Marlow committed
295
    postEventTypeNum(&eventBuf, EVENT_DATA_END);
Simon Marlow's avatar
Simon Marlow committed
296 297

    // Flush the end of data marker.
298
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
299 300 301 302 303 304 305 306 307 308 309 310 311

    if (event_log_file != NULL) {
        fclose(event_log_file);
    }
}

void 
freeEventLogging(void)
{
    StgWord8 c;
    
    // Free events buffer.
    for (c = 0; c < n_capabilities; ++c) {
312 313
        if (capEventBuf[c].begin != NULL) 
            stgFree(capEventBuf[c].begin);
Simon Marlow's avatar
Simon Marlow committed
314
    }
315 316
    if (capEventBuf != NULL)  {
        stgFree(capEventBuf);
Simon Marlow's avatar
Simon Marlow committed
317 318 319 320 321 322 323 324 325 326 327
    }
    if (event_log_filename != NULL) {
        stgFree(event_log_filename);
    }
}

/*
 * Post an event message to the capability's eventlog buffer.
 * If the buffer is full, prints out the buffer and clears it.
 */
void
328 329 330 331
postSchedEvent (Capability *cap, 
                EventTypeNum tag, 
                StgThreadID thread, 
                StgWord64 other)
Simon Marlow's avatar
Simon Marlow committed
332 333 334
{
    EventsBuf *eb;

335
    eb = &capEventBuf[cap->no];
Simon Marlow's avatar
Simon Marlow committed
336 337 338 339 340 341

    if (!hasRoomForEvent(eb, tag)) {
        // Flush event buffer to make room for new event.
        printAndClearEventBuf(eb);
    }
    
Simon Marlow's avatar
Simon Marlow committed
342
    postEventHeader(eb, tag);
343
    postCapNo(eb, cap->no);
Simon Marlow's avatar
Simon Marlow committed
344 345 346 347 348 349 350

    switch (tag) {
    case EVENT_CREATE_THREAD:   // (cap, thread)
    case EVENT_RUN_THREAD:      // (cap, thread)
    case EVENT_THREAD_RUNNABLE: // (cap, thread)
    case EVENT_RUN_SPARK:       // (cap, thread)
    {
351
        postThreadID(eb,thread);
Simon Marlow's avatar
Simon Marlow committed
352 353 354
        break;
    }

355
    case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
356 357 358 359 360
    {
        postThreadID(eb,other /* spark_thread */);
        break;
    }

Simon Marlow's avatar
Simon Marlow committed
361 362 363 364
    case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
    case EVENT_STEAL_SPARK:     // (cap, thread, victim_cap)
    case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
    {
365 366
        postThreadID(eb,thread);
        postCapNo(eb,other /* new_cap | victim_cap | other_cap */);
Simon Marlow's avatar
Simon Marlow committed
367
        break;
368
   }
Simon Marlow's avatar
Simon Marlow committed
369 370 371

    case EVENT_STOP_THREAD:     // (cap, thread, status)
    {
372 373
        postThreadID(eb,thread);
        postWord16(eb,other /* status */);
Simon Marlow's avatar
Simon Marlow committed
374 375 376 377 378 379 380 381 382 383 384 385 386 387 388
        break;
    }

    case EVENT_SHUTDOWN:        // (cap)
    case EVENT_REQUEST_SEQ_GC:  // (cap)
    case EVENT_REQUEST_PAR_GC:  // (cap)
    case EVENT_GC_START:        // (cap)
    case EVENT_GC_END:          // (cap)
    {
        break;
    }

    default:
        barf("postEvent: unknown event tag %d", tag);
    }
389 390 391 392 393 394 395 396 397 398 399 400 401 402 403 404 405 406 407 408 409 410 411 412
}

#define BUF 512

void postMsg(char *msg, va_list ap)
{
    EventsBuf *eb;
    char buf[BUF];
    nat size;

    size = vsnprintf(buf,BUF,msg,ap);
    if (size > BUF) {
        buf[BUF-1] = '\0';
        size = BUF;
    }

    ACQUIRE_LOCK(&eventBufMutex);
    eb = &eventBuf;

    if (!hasRoomForVariableEvent(eb, size)) {
        // Flush event buffer to make room for new event.
        printAndClearEventBuf(eb);
    }

Simon Marlow's avatar
Simon Marlow committed
413
    postEventHeader(eb, EVENT_LOG_MSG);
414 415 416 417 418 419 420 421 422 423 424 425 426 427 428 429 430 431 432 433 434 435 436 437
    postPayloadSize(eb, size);
    postBuf(eb,(StgWord8*)buf,size);

    RELEASE_LOCK(&eventBufMutex);
}

void postCapMsg(Capability *cap, char *msg, va_list ap)
{
    EventsBuf *eb;
    char buf[BUF];
    nat size;

    size = vsnprintf(buf,BUF,msg,ap);
    if (size > BUF) {
        buf[BUF-1] = '\0';
        size = BUF;
    }

    eb = &capEventBuf[cap->no];

    if (!hasRoomForVariableEvent(eb, size)) {
        // Flush event buffer to make room for new event.
        printAndClearEventBuf(eb);
    }
Simon Marlow's avatar
Simon Marlow committed
438

Simon Marlow's avatar
Simon Marlow committed
439
    postEventHeader(eb, EVENT_LOG_MSG);
440 441 442
    postPayloadSize(eb, size + sizeof(EventCapNo));
    postCapNo(eb, cap->no);
    postBuf(eb,(StgWord8*)buf,size);
Simon Marlow's avatar
Simon Marlow committed
443 444
}

Simon Marlow's avatar
Simon Marlow committed
445 446 447 448 449 450 451 452 453 454 455 456 457 458 459 460 461 462 463 464 465 466 467 468 469 470 471
void closeBlockMarker (EventsBuf *ebuf)
{
    if (ebuf->marker)
    {
        // (type:16, time:64, size:32, end_time:64)
        *(StgWord32 *)(ebuf->marker + 10) = ebuf->pos - ebuf->marker;
        *(StgWord64 *)(ebuf->marker + 14) = time_ns();
        ebuf->marker = NULL;
    }
}


void postBlockMarker (EventsBuf *eb)
{
    if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
        printAndClearEventBuf(eb);
    }

    closeBlockMarker(eb);

    eb->marker = eb->pos;
    postEventHeader(eb, EVENT_BLOCK_MARKER);
    postWord32(eb,0); // these get filled in later by closeBlockMarker();
    postWord64(eb,0);
}

void printAndClearEventBuf (EventsBuf *ebuf)
Simon Marlow's avatar
Simon Marlow committed
472 473 474
{
    StgWord64 numBytes = 0, written = 0;

Simon Marlow's avatar
Simon Marlow committed
475 476
    closeBlockMarker(ebuf);

477
    if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
Simon Marlow's avatar
Simon Marlow committed
478
    {
479
        numBytes = ebuf->pos - ebuf->begin;
Simon Marlow's avatar
Simon Marlow committed
480
        
481
        written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
Simon Marlow's avatar
Simon Marlow committed
482 483 484 485 486 487 488
        if (written != numBytes) {
            debugBelch(
                "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
                " doesn't match numBytes=%" FMT_Word64, written, numBytes);
            return;
        }
        
489
        resetEventsBuf(ebuf);
Simon Marlow's avatar
Simon Marlow committed
490 491
        flushCount++;

Simon Marlow's avatar
Simon Marlow committed
492 493
        postBlockMarker(ebuf);
    }
Simon Marlow's avatar
Simon Marlow committed
494 495 496 497
}

void initEventsBuf(EventsBuf* eb, StgWord64 size)
{
498
    eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
Simon Marlow's avatar
Simon Marlow committed
499
    eb->size = size;
Simon Marlow's avatar
Simon Marlow committed
500
    eb->marker = NULL;
Simon Marlow's avatar
Simon Marlow committed
501 502 503 504 505 506 507 508 509
}

void resetEventsBuf(EventsBuf* eb)
{
    eb->pos = eb->begin;
}

StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
{
510
  nat size;
Simon Marlow's avatar
Simon Marlow committed
511

512
  size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
Simon Marlow's avatar
Simon Marlow committed
513 514 515 516 517 518 519 520

  if (eb->pos + size > eb->begin + eb->size) {
      return 0; // Not enough space.
  } else  {
      return 1; // Buf has enough space for the event.
  }
}

521 522 523 524 525 526 527 528 529 530 531 532 533 534
StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
{
  nat size;

  size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
      sizeof(EventPayloadSize) + payload_bytes;

  if (eb->pos + size > eb->begin + eb->size) {
      return 0; // Not enough space.
  } else  {
      return 1; // Buf has enough space for the event.
  }
}    

Simon Marlow's avatar
Simon Marlow committed
535
void postEventType(EventsBuf *eb, EventType *et)
Simon Marlow's avatar
Simon Marlow committed
536 537 538 539 540 541 542 543 544 545 546 547 548 549 550 551
{
    StgWord8 d;
    nat desclen;

    postInt32(eb, EVENT_ET_BEGIN);
    postEventTypeNum(eb, et->etNum);
    postWord16(eb, (StgWord16)et->size);
    desclen = strlen(et->desc);
    postWord32(eb, desclen);
    for (d = 0; d < desclen; ++d) {
        postInt8(eb, (StgInt8)et->desc[d]);
    }
    postWord32(eb, 0); // no extensions yet
    postInt32(eb, EVENT_ET_END);
}

552
#endif /* TRACING */