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
  StgWord64 size;
39
  EventCapNo capno; // which capability this buffer belongs to, or -1
Simon Marlow's avatar
Simon Marlow committed
40 41
} EventsBuf;

42 43 44 45 46 47
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
48 49

char *EventDesc[] = {
50 51 52 53 54 55 56 57 58 59 60 61 62
  [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",
63 64
  [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
  [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
};

// 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];

79
static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
Simon Marlow's avatar
Simon Marlow committed
80
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);

85 86
static void postLogMsg(EventsBuf *eb, char *msg, va_list ap);

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

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

93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115
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);
}

116 117 118 119 120 121
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
122 123 124
static inline StgWord64 time_ns(void)
{ return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); }

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

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

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

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

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

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

146 147 148 149 150 151 152 153 154 155 156 157
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
158 159 160 161 162

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

165
    event_log_filename = stgMallocBytes(strlen(prog_name) + 10,
Simon Marlow's avatar
Simon Marlow committed
166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189
                                        "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.
     */
190 191 192 193 194 195 196 197 198
#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
199
        // Init buffer for events.
200
        initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
Simon Marlow's avatar
Simon Marlow committed
201
    }
202
    initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
Simon Marlow's avatar
Simon Marlow committed
203 204

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

    // Mark beginning of event types in the header.
Simon Marlow's avatar
Simon Marlow committed
208
    postInt32(&eventBuf, EVENT_HET_BEGIN);
Simon Marlow's avatar
Simon Marlow committed
209 210 211 212 213 214 215 216 217 218
    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)
219
        case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
220
            eventTypes[t].size = sizeof(EventThreadID);
221 222
            break;

Simon Marlow's avatar
Simon Marlow committed
223 224 225 226
        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 =
227
                sizeof(EventThreadID) + sizeof(EventCapNo);
Simon Marlow's avatar
Simon Marlow committed
228 229 230 231
            break;

        case EVENT_STOP_THREAD:     // (cap, thread, status)
            eventTypes[t].size =
232
                sizeof(EventThreadID) + sizeof(StgWord16);
Simon Marlow's avatar
Simon Marlow committed
233 234 235 236 237 238 239
            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)
240 241
        case EVENT_STARTUP:
            eventTypes[t].size = 0;
Simon Marlow's avatar
Simon Marlow committed
242
            break;
243 244 245 246 247

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

Simon Marlow's avatar
Simon Marlow committed
248
        case EVENT_BLOCK_MARKER:
249 250
            eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) + 
                sizeof(EventCapNo);
Simon Marlow's avatar
Simon Marlow committed
251 252
            break;

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

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

    // Mark end of event types in the header.
Simon Marlow's avatar
Simon Marlow committed
262
    postInt32(&eventBuf, EVENT_HET_END);
Simon Marlow's avatar
Simon Marlow committed
263 264
    
    // Write in buffer: the header end marker.
Simon Marlow's avatar
Simon Marlow committed
265
    postInt32(&eventBuf, EVENT_HEADER_END);
Simon Marlow's avatar
Simon Marlow committed
266 267
    
    // Prepare event buffer for events (data).
Simon Marlow's avatar
Simon Marlow committed
268
    postInt32(&eventBuf, EVENT_DATA_BEGIN);
Simon Marlow's avatar
Simon Marlow committed
269
    
270 271 272 273
    // Post a STARTUP event with the number of capabilities
    postEventHeader(&eventBuf, EVENT_STARTUP);
    postCapNo(&eventBuf, n_caps);

274
    // Flush capEventBuf with header.
Simon Marlow's avatar
Simon Marlow committed
275 276 277 278
    /*
     * Flush header and data begin marker to the file, thus preparing the
     * file to have events written to it.
     */
279
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
280 281 282 283

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

void
endEventLogging(void)
{
    nat c;

    // Flush all events remaining in the buffers.
    for (c = 0; c < n_capabilities; ++c) {
293
        printAndClearEventBuf(&capEventBuf[c]);
Simon Marlow's avatar
Simon Marlow committed
294
    }
295
    printAndClearEventBuf(&eventBuf);
296
    resetEventsBuf(&eventBuf); // we don't want the block marker
Simon Marlow's avatar
Simon Marlow committed
297 298

    // Mark end of events (data).
Simon Marlow's avatar
Simon Marlow committed
299
    postEventTypeNum(&eventBuf, EVENT_DATA_END);
Simon Marlow's avatar
Simon Marlow committed
300 301

    // Flush the end of data marker.
302
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
303 304 305 306 307 308 309 310 311 312 313 314 315

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

void 
freeEventLogging(void)
{
    StgWord8 c;
    
    // Free events buffer.
    for (c = 0; c < n_capabilities; ++c) {
316 317
        if (capEventBuf[c].begin != NULL) 
            stgFree(capEventBuf[c].begin);
Simon Marlow's avatar
Simon Marlow committed
318
    }
319 320
    if (capEventBuf != NULL)  {
        stgFree(capEventBuf);
Simon Marlow's avatar
Simon Marlow committed
321 322 323 324 325 326 327 328 329 330 331
    }
    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
332 333 334 335
postSchedEvent (Capability *cap, 
                EventTypeNum tag, 
                StgThreadID thread, 
                StgWord64 other)
Simon Marlow's avatar
Simon Marlow committed
336 337 338
{
    EventsBuf *eb;

339
    eb = &capEventBuf[cap->no];
Simon Marlow's avatar
Simon Marlow committed
340 341 342 343 344 345

    if (!hasRoomForEvent(eb, tag)) {
        // Flush event buffer to make room for new event.
        printAndClearEventBuf(eb);
    }
    
Simon Marlow's avatar
Simon Marlow committed
346
    postEventHeader(eb, tag);
Simon Marlow's avatar
Simon Marlow committed
347 348 349 350 351 352 353

    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)
    {
354
        postThreadID(eb,thread);
Simon Marlow's avatar
Simon Marlow committed
355 356 357
        break;
    }

358
    case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
359 360 361 362 363
    {
        postThreadID(eb,other /* spark_thread */);
        break;
    }

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

    case EVENT_STOP_THREAD:     // (cap, thread, status)
    {
375 376
        postThreadID(eb,thread);
        postWord16(eb,other /* status */);
Simon Marlow's avatar
Simon Marlow committed
377 378 379 380 381 382 383 384 385 386 387 388 389 390 391
        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);
    }
392 393 394 395
}

#define BUF 512

396
void postLogMsg(EventsBuf *eb, char *msg, va_list ap)
397 398 399 400 401 402 403 404 405 406 407 408 409 410 411
{
    char buf[BUF];
    nat size;

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

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

Simon Marlow's avatar
Simon Marlow committed
412
    postEventHeader(eb, EVENT_LOG_MSG);
413 414
    postPayloadSize(eb, size);
    postBuf(eb,(StgWord8*)buf,size);
415
}
416

417 418 419 420
void postMsg(char *msg, va_list ap)
{
    ACQUIRE_LOCK(&eventBufMutex);
    postLogMsg(&eventBuf, msg, ap);
421 422 423 424 425
    RELEASE_LOCK(&eventBufMutex);
}

void postCapMsg(Capability *cap, char *msg, va_list ap)
{
426
    postLogMsg(&capEventBuf[cap->no], msg, ap);
Simon Marlow's avatar
Simon Marlow committed
427 428
}

Simon Marlow's avatar
Simon Marlow committed
429 430
void closeBlockMarker (EventsBuf *ebuf)
{
431 432
    StgInt8* save_pos;

Simon Marlow's avatar
Simon Marlow committed
433 434 435
    if (ebuf->marker)
    {
        // (type:16, time:64, size:32, end_time:64)
436 437 438 439 440 441 442

        save_pos = ebuf->pos;
        ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
                    sizeof(EventTimestamp);
        postWord32(ebuf, save_pos - ebuf->marker);
        postTimestamp(ebuf);
        ebuf->pos = save_pos;
Simon Marlow's avatar
Simon Marlow committed
443 444 445 446 447 448 449 450 451 452 453 454 455 456 457 458 459
        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);
460
    postCapNo(eb, eb->capno);
Simon Marlow's avatar
Simon Marlow committed
461 462 463
}

void printAndClearEventBuf (EventsBuf *ebuf)
Simon Marlow's avatar
Simon Marlow committed
464 465 466
{
    StgWord64 numBytes = 0, written = 0;

Simon Marlow's avatar
Simon Marlow committed
467 468
    closeBlockMarker(ebuf);

469
    if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
Simon Marlow's avatar
Simon Marlow committed
470
    {
471
        numBytes = ebuf->pos - ebuf->begin;
Simon Marlow's avatar
Simon Marlow committed
472
        
473
        written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
Simon Marlow's avatar
Simon Marlow committed
474 475 476 477 478 479 480
        if (written != numBytes) {
            debugBelch(
                "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
                " doesn't match numBytes=%" FMT_Word64, written, numBytes);
            return;
        }
        
481
        resetEventsBuf(ebuf);
Simon Marlow's avatar
Simon Marlow committed
482 483
        flushCount++;

Simon Marlow's avatar
Simon Marlow committed
484 485
        postBlockMarker(ebuf);
    }
Simon Marlow's avatar
Simon Marlow committed
486 487
}

488
void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
Simon Marlow's avatar
Simon Marlow committed
489
{
490
    eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
Simon Marlow's avatar
Simon Marlow committed
491
    eb->size = size;
Simon Marlow's avatar
Simon Marlow committed
492
    eb->marker = NULL;
493
    eb->capno = capno;
Simon Marlow's avatar
Simon Marlow committed
494 495 496 497 498
}

void resetEventsBuf(EventsBuf* eb)
{
    eb->pos = eb->begin;
499
    eb->marker = NULL;
Simon Marlow's avatar
Simon Marlow committed
500 501 502 503
}

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

506
  size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
Simon Marlow's avatar
Simon Marlow committed
507 508 509 510 511 512 513 514

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

515 516 517 518 519 520 521 522 523 524 525 526 527 528
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
529
void postEventType(EventsBuf *eb, EventType *et)
Simon Marlow's avatar
Simon Marlow committed
530 531 532 533 534 535 536 537 538 539 540 541 542 543 544 545
{
    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);
}

546
#endif /* TRACING */