EventLog.c 41.7 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

Ben Gamari's avatar
Ben Gamari committed
12
#if defined(TRACING)
13 14

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

20
#include <string.h>
Simon Marlow's avatar
Simon Marlow committed
21
#include <stdio.h>
Ben Gamari's avatar
Ben Gamari committed
22
#if defined(HAVE_SYS_TYPES_H)
23 24
#include <sys/types.h>
#endif
Ben Gamari's avatar
Ben Gamari committed
25
#if defined(HAVE_UNISTD_H)
26 27 28
#include <unistd.h>
#endif

29
static const EventLogWriter *event_log_writer;
Simon Marlow's avatar
Simon Marlow committed
30 31 32 33 34 35 36 37 38

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

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

EventsBuf eventBuf; // an EventsBuf not associated with any Capability
Ben Gamari's avatar
Ben Gamari committed
47
#if defined(THREADED_RTS)
48 49
Mutex eventBufMutex; // protected by this mutex
#endif
Simon Marlow's avatar
Simon Marlow committed
50 51

char *EventDesc[] = {
52 53 54 55 56 57
  [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_THREAD_WAKEUP]       = "Wakeup thread",
58
  [EVENT_THREAD_LABEL]        = "Thread label",
59 60 61 62
  [EVENT_CAP_CREATE]          = "Create capability",
  [EVENT_CAP_DELETE]          = "Delete capability",
  [EVENT_CAP_DISABLE]         = "Disable capability",
  [EVENT_CAP_ENABLE]          = "Enable capability",
63 64 65 66
  [EVENT_GC_START]            = "Starting GC",
  [EVENT_GC_END]              = "Finished GC",
  [EVENT_REQUEST_SEQ_GC]      = "Request sequential GC",
  [EVENT_REQUEST_PAR_GC]      = "Request parallel GC",
67
  [EVENT_GC_GLOBAL_SYNC]      = "Synchronise stop-the-world GC",
68 69 70 71 72
  [EVENT_GC_STATS_GHC]        = "GC statistics",
  [EVENT_HEAP_INFO_GHC]       = "Heap static parameters",
  [EVENT_HEAP_ALLOCATED]      = "Total heap mem ever allocated",
  [EVENT_HEAP_SIZE]           = "Current heap size",
  [EVENT_HEAP_LIVE]           = "Current heap live data",
73 74
  [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
  [EVENT_LOG_MSG]             = "Log message",
75
  [EVENT_USER_MSG]            = "User message",
76
  [EVENT_USER_MARKER]         = "User marker",
77 78 79
  [EVENT_GC_IDLE]             = "GC idle",
  [EVENT_GC_WORK]             = "GC working",
  [EVENT_GC_DONE]             = "GC done",
80 81 82 83
  [EVENT_BLOCK_MARKER]        = "Block marker",
  [EVENT_CAPSET_CREATE]       = "Create capability set",
  [EVENT_CAPSET_DELETE]       = "Delete capability set",
  [EVENT_CAPSET_ASSIGN_CAP]   = "Add capability to capability set",
84 85 86 87 88
  [EVENT_CAPSET_REMOVE_CAP]   = "Remove capability from capability set",
  [EVENT_RTS_IDENTIFIER]      = "RTS name and version",
  [EVENT_PROGRAM_ARGS]        = "Program arguments",
  [EVENT_PROGRAM_ENV]         = "Program environment variables",
  [EVENT_OSPROCESS_PID]       = "Process ID",
Duncan Coutts's avatar
Duncan Coutts committed
89
  [EVENT_OSPROCESS_PPID]      = "Parent process ID",
90
  [EVENT_WALL_CLOCK_TIME]     = "Wall clock time",
91 92 93 94 95 96 97 98
  [EVENT_SPARK_COUNTERS]      = "Spark counters",
  [EVENT_SPARK_CREATE]        = "Spark create",
  [EVENT_SPARK_DUD]           = "Spark dud",
  [EVENT_SPARK_OVERFLOW]      = "Spark overflow",
  [EVENT_SPARK_RUN]           = "Spark run",
  [EVENT_SPARK_STEAL]         = "Spark steal",
  [EVENT_SPARK_FIZZLE]        = "Spark fizzle",
  [EVENT_SPARK_GC]            = "Spark GC",
99 100 101
  [EVENT_TASK_CREATE]         = "Task create",
  [EVENT_TASK_MIGRATE]        = "Task migrate",
  [EVENT_TASK_DELETE]         = "Task delete",
102
  [EVENT_HACK_BUG_T9003]      = "Empty event for bug #9003",
103 104 105
  [EVENT_HEAP_PROF_BEGIN]     = "Start of heap profile",
  [EVENT_HEAP_PROF_COST_CENTRE]   = "Cost center definition",
  [EVENT_HEAP_PROF_SAMPLE_BEGIN]  = "Start of heap profile sample",
106
  [EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN]  = "Start of heap profile (biographical) sample",
107
  [EVENT_HEAP_PROF_SAMPLE_END]    = "End of heap profile sample",
108 109
  [EVENT_HEAP_PROF_SAMPLE_STRING] = "Heap profile string sample",
  [EVENT_HEAP_PROF_SAMPLE_COST_CENTRE] = "Heap profile cost-centre sample",
Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
110
  [EVENT_USER_BINARY_MSG]     = "User binary message"
Simon Marlow's avatar
Simon Marlow committed
111 112
};

113
// Event type.
Simon Marlow's avatar
Simon Marlow committed
114 115 116

typedef struct _EventType {
  EventTypeNum etNum;  // Event Type number.
117
  uint32_t   size;     // size of the payload in bytes
Simon Marlow's avatar
Simon Marlow committed
118 119 120
  char *desc;     // Description
} EventType;

121
EventType eventTypes[NUM_GHC_EVENT_TAGS];
Simon Marlow's avatar
Simon Marlow committed
122

123
static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
Simon Marlow's avatar
Simon Marlow committed
124
static void resetEventsBuf(EventsBuf* eb);
Simon Marlow's avatar
Simon Marlow committed
125
static void printAndClearEventBuf (EventsBuf *eventsBuf);
Simon Marlow's avatar
Simon Marlow committed
126 127 128

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

129
static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap);
130

Simon Marlow's avatar
Simon Marlow committed
131 132 133
static void postBlockMarker(EventsBuf *eb);
static void closeBlockMarker(EventsBuf *ebuf);

Simon Marlow's avatar
Simon Marlow committed
134
static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
135
static StgBool hasRoomForVariableEvent(EventsBuf *eb, uint32_t payload_bytes);
Simon Marlow's avatar
Simon Marlow committed
136

137 138 139
static void ensureRoomForEvent(EventsBuf *eb, EventTypeNum tag);
static int ensureRoomForVariableEvent(EventsBuf *eb, StgWord16 size);

140 141
static inline void postWord8(EventsBuf *eb, StgWord8 i)
{
142
    *(eb->pos++) = i;
143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162
}

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);
}

163
static inline void postBuf(EventsBuf *eb, StgWord8 *buf, uint32_t size)
164 165 166 167 168
{
    memcpy(eb->pos, buf, size);
    eb->pos += size;
}

169 170 171 172 173 174 175
/* Post a null-terminated string to the event log.
 * It is the caller's responsibility to ensure that there is
 * enough room for strlen(buf)+1 bytes.
 */
static inline void postString(EventsBuf *eb, const char *buf)
{
    if (buf) {
176
        const int len = strlen(buf);
177 178 179 180 181 182 183 184
        ASSERT(eb->begin + eb->size > eb->pos + len);
        memcpy(eb->pos, buf, len);
        eb->pos += len;
    }
    *eb->pos = 0;
    eb->pos++;
}

Simon Marlow's avatar
Simon Marlow committed
185
static inline StgWord64 time_ns(void)
Simon Marlow's avatar
Simon Marlow committed
186
{ return TimeToNS(stat_getElapsedTime()); }
Simon Marlow's avatar
Simon Marlow committed
187

188 189 190
static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
{ postWord16(eb, etNum); }

Simon Marlow's avatar
Simon Marlow committed
191 192
static inline void postTimestamp(EventsBuf *eb)
{ postWord64(eb, time_ns()); }
193

194
static inline void postThreadID(EventsBuf *eb, EventThreadID id)
195 196
{ postWord32(eb,id); }

197
static inline void postCapNo(EventsBuf *eb, EventCapNo no)
198 199
{ postWord16(eb,no); }

200 201 202 203 204 205
static inline void postCapsetID(EventsBuf *eb, EventCapsetID id)
{ postWord32(eb,id); }

static inline void postCapsetType(EventsBuf *eb, EventCapsetType type)
{ postWord16(eb,type); }

206 207 208 209 210 211 212 213 214
static inline void postOSProcessId(EventsBuf *eb, pid_t pid)
{ postWord32(eb, pid); }

static inline void postKernelThreadId(EventsBuf *eb, EventKernelThreadId tid)
{ postWord64(eb, tid); }

static inline void postTaskId(EventsBuf *eb, EventTaskId tUniq)
{ postWord64(eb, tUniq); }

215 216 217
static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
{ postWord16(eb,size); }

Simon Marlow's avatar
Simon Marlow committed
218 219 220 221
static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
{
    postEventTypeNum(eb, type);
    postTimestamp(eb);
222
}
Simon Marlow's avatar
Simon Marlow committed
223

224 225 226 227 228 229
static inline void postInt8(EventsBuf *eb, StgInt8 i)
{ postWord8(eb, (StgWord8)i); }

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

230
#define EVENT_SIZE_DYNAMIC (-1)
Simon Marlow's avatar
Simon Marlow committed
231

232 233
static void
initEventLogWriter(void)
Simon Marlow's avatar
Simon Marlow committed
234
{
235 236 237
    if (event_log_writer != NULL &&
            event_log_writer->initEventLogWriter != NULL) {
        event_log_writer->initEventLogWriter();
238
    }
239
}
Simon Marlow's avatar
Simon Marlow committed
240

241 242 243 244 245 246 247 248 249 250
static bool
writeEventLog(void *eventlog, size_t eventlog_size)
{
    if (event_log_writer != NULL &&
            event_log_writer->writeEventLog != NULL) {
        return event_log_writer->writeEventLog(eventlog, eventlog_size);
    } else {
        return false;
    }
}
Simon Marlow's avatar
Simon Marlow committed
251

252 253 254 255 256 257
static void
stopEventLogWriter(void)
{
    if (event_log_writer != NULL &&
            event_log_writer->stopEventLogWriter != NULL) {
        event_log_writer->stopEventLogWriter();
Simon Marlow's avatar
Simon Marlow committed
258
    }
259
}
260

261 262 263 264 265 266
void
flushEventLog(void)
{
    if (event_log_writer != NULL &&
            event_log_writer->flushEventLog != NULL) {
        event_log_writer->flushEventLog();
267
    }
268 269
}

270
static void
271
init_event_types(void)
272
{
273
    for (int t = 0; t < NUM_GHC_EVENT_TAGS; ++t) {
Simon Marlow's avatar
Simon Marlow committed
274 275 276 277 278 279 280
        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)
281
        case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
282
            eventTypes[t].size = sizeof(EventThreadID);
283 284
            break;

Simon Marlow's avatar
Simon Marlow committed
285 286 287
        case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
        case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
            eventTypes[t].size =
288
                sizeof(EventThreadID) + sizeof(EventCapNo);
Simon Marlow's avatar
Simon Marlow committed
289 290 291
            break;

        case EVENT_STOP_THREAD:     // (cap, thread, status)
292 293 294
            eventTypes[t].size = sizeof(EventThreadID)
                               + sizeof(StgWord16)
                               + sizeof(EventThreadID);
Simon Marlow's avatar
Simon Marlow committed
295 296
            break;

297 298 299 300
        case EVENT_CAP_CREATE:      // (cap)
        case EVENT_CAP_DELETE:      // (cap)
        case EVENT_CAP_ENABLE:      // (cap)
        case EVENT_CAP_DISABLE:     // (cap)
301 302 303
            eventTypes[t].size = sizeof(EventCapNo);
            break;

304 305 306 307 308 309 310 311 312 313 314 315 316 317 318
        case EVENT_CAPSET_CREATE:   // (capset, capset_type)
            eventTypes[t].size =
                sizeof(EventCapsetID) + sizeof(EventCapsetType);
            break;

        case EVENT_CAPSET_DELETE:   // (capset)
            eventTypes[t].size = sizeof(EventCapsetID);
            break;

        case EVENT_CAPSET_ASSIGN_CAP:  // (capset, cap)
        case EVENT_CAPSET_REMOVE_CAP:
            eventTypes[t].size =
                sizeof(EventCapsetID) + sizeof(EventCapNo);
            break;

319 320 321 322 323 324
        case EVENT_OSPROCESS_PID:   // (cap, pid)
        case EVENT_OSPROCESS_PPID:
            eventTypes[t].size =
                sizeof(EventCapsetID) + sizeof(StgWord32);
            break;

325 326 327 328 329
        case EVENT_WALL_CLOCK_TIME: // (capset, unix_epoch_seconds, nanoseconds)
            eventTypes[t].size =
                sizeof(EventCapsetID) + sizeof(StgWord64) + sizeof(StgWord32);
            break;

330 331 332 333 334
        case EVENT_SPARK_STEAL:     // (cap, victim_cap)
            eventTypes[t].size =
                sizeof(EventCapNo);
            break;

Simon Marlow's avatar
Simon Marlow committed
335 336 337 338
        case EVENT_REQUEST_SEQ_GC:  // (cap)
        case EVENT_REQUEST_PAR_GC:  // (cap)
        case EVENT_GC_START:        // (cap)
        case EVENT_GC_END:          // (cap)
339 340 341
        case EVENT_GC_IDLE:
        case EVENT_GC_WORK:
        case EVENT_GC_DONE:
342
        case EVENT_GC_GLOBAL_SYNC:  // (cap)
343 344 345 346 347 348
        case EVENT_SPARK_CREATE:    // (cap)
        case EVENT_SPARK_DUD:       // (cap)
        case EVENT_SPARK_OVERFLOW:  // (cap)
        case EVENT_SPARK_RUN:       // (cap)
        case EVENT_SPARK_FIZZLE:    // (cap)
        case EVENT_SPARK_GC:        // (cap)
349
            eventTypes[t].size = 0;
Simon Marlow's avatar
Simon Marlow committed
350
            break;
351 352

        case EVENT_LOG_MSG:          // (msg)
353
        case EVENT_USER_MSG:         // (msg)
354
        case EVENT_USER_MARKER:      // (markername)
355 356 357
        case EVENT_RTS_IDENTIFIER:   // (capset, str)
        case EVENT_PROGRAM_ARGS:     // (capset, strvec)
        case EVENT_PROGRAM_ENV:      // (capset, strvec)
358
        case EVENT_THREAD_LABEL:     // (thread, str)
359 360 361
            eventTypes[t].size = 0xffff;
            break;

Duncan Coutts's avatar
Duncan Coutts committed
362 363 364 365
        case EVENT_SPARK_COUNTERS:   // (cap, 7*counter)
            eventTypes[t].size = 7 * sizeof(StgWord64);
            break;

366 367 368 369 370 371 372 373 374 375 376 377 378 379 380 381 382
        case EVENT_HEAP_ALLOCATED:    // (heap_capset, alloc_bytes)
        case EVENT_HEAP_SIZE:         // (heap_capset, size_bytes)
        case EVENT_HEAP_LIVE:         // (heap_capset, live_bytes)
            eventTypes[t].size = sizeof(EventCapsetID) + sizeof(StgWord64);
            break;

        case EVENT_HEAP_INFO_GHC:     // (heap_capset, n_generations,
                                      //  max_heap_size, alloc_area_size,
                                      //  mblock_size, block_size)
            eventTypes[t].size = sizeof(EventCapsetID)
                               + sizeof(StgWord16)
                               + sizeof(StgWord64) * 4;
            break;

        case EVENT_GC_STATS_GHC:      // (heap_capset, generation,
                                      //  copied_bytes, slop_bytes, frag_bytes,
                                      //  par_n_threads,
383 384 385
                                      //  par_max_copied, par_tot_copied,
                                      //  par_balanced_copied
                                      //  )
386 387 388 389
            eventTypes[t].size = sizeof(EventCapsetID)
                               + sizeof(StgWord16)
                               + sizeof(StgWord64) * 3
                               + sizeof(StgWord32)
390
                               + sizeof(StgWord64) * 3;
391 392
            break;

393
        case EVENT_TASK_CREATE:   // (taskId, cap, tid)
394 395 396
            eventTypes[t].size = sizeof(EventTaskId)
                               + sizeof(EventCapNo)
                               + sizeof(EventKernelThreadId);
397 398 399 400 401 402 403 404 405 406 407
            break;

        case EVENT_TASK_MIGRATE:   // (taskId, cap, new_cap)
            eventTypes[t].size =
                sizeof(EventTaskId) + sizeof(EventCapNo) + sizeof(EventCapNo);
            break;

        case EVENT_TASK_DELETE:   // (taskId)
            eventTypes[t].size = sizeof(EventTaskId);
            break;

Simon Marlow's avatar
Simon Marlow committed
408
        case EVENT_BLOCK_MARKER:
409
            eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) +
410
                sizeof(EventCapNo);
Simon Marlow's avatar
Simon Marlow committed
411 412
            break;

413 414 415 416
        case EVENT_HACK_BUG_T9003:
            eventTypes[t].size = 0;
            break;

417 418 419 420 421 422 423 424 425 426 427 428
        case EVENT_HEAP_PROF_BEGIN:
            eventTypes[t].size = EVENT_SIZE_DYNAMIC;
            break;

        case EVENT_HEAP_PROF_COST_CENTRE:
            eventTypes[t].size = EVENT_SIZE_DYNAMIC;
            break;

        case EVENT_HEAP_PROF_SAMPLE_BEGIN:
            eventTypes[t].size = 8;
            break;

429 430 431 432
        case EVENT_HEAP_BIO_PROF_SAMPLE_BEGIN:
            eventTypes[t].size = 16;
            break;

433 434 435 436
        case EVENT_HEAP_PROF_SAMPLE_END:
            eventTypes[t].size = 8;
            break;

437 438 439 440 441 442 443 444
        case EVENT_HEAP_PROF_SAMPLE_STRING:
            eventTypes[t].size = EVENT_SIZE_DYNAMIC;
            break;

        case EVENT_HEAP_PROF_SAMPLE_COST_CENTRE:
            eventTypes[t].size = EVENT_SIZE_DYNAMIC;
            break;

Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
445 446 447 448
        case EVENT_USER_BINARY_MSG:
            eventTypes[t].size = EVENT_SIZE_DYNAMIC;
            break;

449 450
        default:
            continue; /* ignore deprecated events */
Simon Marlow's avatar
Simon Marlow committed
451
        }
452 453 454 455 456 457 458 459
    }
}

static void
postHeaderEvents(void)
{
    // Write in buffer: the header begin marker.
    postInt32(&eventBuf, EVENT_HEADER_BEGIN);
Simon Marlow's avatar
Simon Marlow committed
460

461 462 463 464
    // Mark beginning of event types in the header.
    postInt32(&eventBuf, EVENT_HET_BEGIN);

    for (int t = 0; t < NUM_GHC_EVENT_TAGS; ++t) {
Simon Marlow's avatar
Simon Marlow committed
465
        // Write in buffer: the start event type.
466 467
        if (eventTypes[t].desc)
            postEventType(&eventBuf, &eventTypes[t]);
Simon Marlow's avatar
Simon Marlow committed
468 469 470
    }

    // Mark end of event types in the header.
Simon Marlow's avatar
Simon Marlow committed
471
    postInt32(&eventBuf, EVENT_HET_END);
472

Simon Marlow's avatar
Simon Marlow committed
473
    // Write in buffer: the header end marker.
Simon Marlow's avatar
Simon Marlow committed
474
    postInt32(&eventBuf, EVENT_HEADER_END);
475

Simon Marlow's avatar
Simon Marlow committed
476
    // Prepare event buffer for events (data).
Simon Marlow's avatar
Simon Marlow committed
477
    postInt32(&eventBuf, EVENT_DATA_BEGIN);
478 479 480 481 482 483 484
}

void
initEventLogging(const EventLogWriter *ev_writer)
{
    uint32_t n_caps;

485 486
    init_event_types();

487 488 489 490 491 492 493 494 495 496 497 498 499 500 501 502 503 504 505 506 507 508 509 510 511 512 513 514 515 516 517
    event_log_writer = ev_writer;
    initEventLogWriter();

    if (sizeof(EventDesc) / sizeof(char*) != NUM_GHC_EVENT_TAGS) {
        barf("EventDesc array has the wrong number of elements");
    }

    /*
     * 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.
     */
#if defined(THREADED_RTS)
    // XXX n_capabilities hasn't been initialized yet
    n_caps = RtsFlags.ParFlags.nCapabilities;
#else
    n_caps = 1;
#endif
    moreCapEventBufs(0, n_caps);

    initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
#if defined(THREADED_RTS)
    initMutex(&eventBufMutex);
#endif

    postHeaderEvents();
518

519
    // Flush capEventBuf with header.
Simon Marlow's avatar
Simon Marlow committed
520 521 522 523
    /*
     * Flush header and data begin marker to the file, thus preparing the
     * file to have events written to it.
     */
524
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
525

526
    for (uint32_t c = 0; c < n_caps; ++c) {
Simon Marlow's avatar
Simon Marlow committed
527 528
        postBlockMarker(&capEventBuf[c]);
    }
Simon Marlow's avatar
Simon Marlow committed
529 530 531 532 533 534
}

void
endEventLogging(void)
{
    // Flush all events remaining in the buffers.
535
    for (uint32_t c = 0; c < n_capabilities; ++c) {
536
        printAndClearEventBuf(&capEventBuf[c]);
Simon Marlow's avatar
Simon Marlow committed
537
    }
538
    printAndClearEventBuf(&eventBuf);
539
    resetEventsBuf(&eventBuf); // we don't want the block marker
Simon Marlow's avatar
Simon Marlow committed
540 541

    // Mark end of events (data).
Simon Marlow's avatar
Simon Marlow committed
542
    postEventTypeNum(&eventBuf, EVENT_DATA_END);
Simon Marlow's avatar
Simon Marlow committed
543 544

    // Flush the end of data marker.
545
    printAndClearEventBuf(&eventBuf);
Simon Marlow's avatar
Simon Marlow committed
546

547
    stopEventLogWriter();
Simon Marlow's avatar
Simon Marlow committed
548 549
}

550
void
551
moreCapEventBufs (uint32_t from, uint32_t to)
552 553 554 555 556 557 558 559 560
{
    if (from > 0) {
        capEventBuf = stgReallocBytes(capEventBuf, to * sizeof(EventsBuf),
                                      "moreCapEventBufs");
    } else {
        capEventBuf = stgMallocBytes(to * sizeof(EventsBuf),
                                     "moreCapEventBufs");
    }

561
    for (uint32_t c = from; c < to; ++c) {
562 563
        initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
    }
564 565 566 567

    // The from == 0 already covered in initEventLogging, so we are interested
    // only in case when we are increasing capabilities number
    if (from > 0) {
568
        for (uint32_t c = from; c < to; ++c) {
569 570 571
           postBlockMarker(&capEventBuf[c]);
        }
    }
572 573 574 575
}


void
Simon Marlow's avatar
Simon Marlow committed
576 577 578
freeEventLogging(void)
{
    // Free events buffer.
579
    for (uint32_t c = 0; c < n_capabilities; ++c) {
580
        if (capEventBuf[c].begin != NULL)
581
            stgFree(capEventBuf[c].begin);
Simon Marlow's avatar
Simon Marlow committed
582
    }
583 584
    if (capEventBuf != NULL)  {
        stgFree(capEventBuf);
Simon Marlow's avatar
Simon Marlow committed
585
    }
586 587
}

588
void
589 590 591
abortEventLogging(void)
{
    freeEventLogging();
592
    stopEventLogWriter();
593
}
594

Simon Marlow's avatar
Simon Marlow committed
595 596 597 598 599
/*
 * Post an event message to the capability's eventlog buffer.
 * If the buffer is full, prints out the buffer and clears it.
 */
void
600 601 602
postSchedEvent (Capability *cap,
                EventTypeNum tag,
                StgThreadID thread,
603 604
                StgWord info1,
                StgWord info2)
Simon Marlow's avatar
Simon Marlow committed
605
{
606
    EventsBuf *eb = &capEventBuf[cap->no];
607
    ensureRoomForEvent(eb, tag);
608

Simon Marlow's avatar
Simon Marlow committed
609
    postEventHeader(eb, tag);
Simon Marlow's avatar
Simon Marlow committed
610 611 612 613 614 615

    switch (tag) {
    case EVENT_CREATE_THREAD:   // (cap, thread)
    case EVENT_RUN_THREAD:      // (cap, thread)
    case EVENT_THREAD_RUNNABLE: // (cap, thread)
    {
616
        postThreadID(eb,thread);
Simon Marlow's avatar
Simon Marlow committed
617 618 619
        break;
    }

620
    case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
621
    {
622
        postThreadID(eb,info1 /* spark_thread */);
623 624 625
        break;
    }

Simon Marlow's avatar
Simon Marlow committed
626 627 628
    case EVENT_MIGRATE_THREAD:  // (cap, thread, new_cap)
    case EVENT_THREAD_WAKEUP:   // (cap, thread, other_cap)
    {
629
        postThreadID(eb,thread);
630
        postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */);
Simon Marlow's avatar
Simon Marlow committed
631
        break;
632
   }
Simon Marlow's avatar
Simon Marlow committed
633 634 635

    case EVENT_STOP_THREAD:     // (cap, thread, status)
    {
636
        postThreadID(eb,thread);
637 638
        postWord16(eb,info1 /* status */);
        postThreadID(eb,info2 /* blocked on thread */);
Simon Marlow's avatar
Simon Marlow committed
639 640 641 642
        break;
    }

    default:
643
        barf("postSchedEvent: unknown event tag %d", tag);
Simon Marlow's avatar
Simon Marlow committed
644
    }
645 646
}

647 648 649 650 651
void
postSparkEvent (Capability *cap,
                EventTypeNum tag,
                StgWord info1)
{
652
    EventsBuf *eb = &capEventBuf[cap->no];
653
    ensureRoomForEvent(eb, tag);
654 655 656 657 658 659 660 661 662 663 664 665 666 667 668 669 670 671 672 673 674 675 676 677 678 679 680 681 682 683 684

    postEventHeader(eb, tag);

    switch (tag) {
    case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
    {
        postThreadID(eb,info1 /* spark_thread */);
        break;
    }

    case EVENT_SPARK_STEAL:         // (cap, victim_cap)
    {
        postCapNo(eb,info1 /* victim_cap */);
        break;
   }

    case EVENT_SPARK_CREATE:        // (cap)
    case EVENT_SPARK_DUD:           // (cap)
    case EVENT_SPARK_OVERFLOW:      // (cap)
    case EVENT_SPARK_RUN:           // (cap)
    case EVENT_SPARK_FIZZLE:        // (cap)
    case EVENT_SPARK_GC:            // (cap)
    {
        break;
    }

    default:
        barf("postSparkEvent: unknown event tag %d", tag);
    }
}

Duncan Coutts's avatar
Duncan Coutts committed
685
void
686
postSparkCountersEvent (Capability *cap,
Duncan Coutts's avatar
Duncan Coutts committed
687 688 689
                        SparkCounters counters,
                        StgWord remaining)
{
690
    EventsBuf *eb = &capEventBuf[cap->no];
691
    ensureRoomForEvent(eb, EVENT_SPARK_COUNTERS);
692

Duncan Coutts's avatar
Duncan Coutts committed
693
    postEventHeader(eb, EVENT_SPARK_COUNTERS);
694
    /* EVENT_SPARK_COUNTERS (crt,dud,ovf,cnv,gcd,fiz,rem) */
Duncan Coutts's avatar
Duncan Coutts committed
695 696 697 698 699 700 701 702 703
    postWord64(eb,counters.created);
    postWord64(eb,counters.dud);
    postWord64(eb,counters.overflowed);
    postWord64(eb,counters.converted);
    postWord64(eb,counters.gcd);
    postWord64(eb,counters.fizzled);
    postWord64(eb,remaining);
}

704 705 706 707 708
void
postCapEvent (EventTypeNum  tag,
              EventCapNo    capno)
{
    ACQUIRE_LOCK(&eventBufMutex);
709
    ensureRoomForEvent(&eventBuf, tag);
710

711 712 713 714 715 716 717 718 719 720 721 722 723 724 725 726 727 728 729
    postEventHeader(&eventBuf, tag);

    switch (tag) {
    case EVENT_CAP_CREATE:   // (cap)
    case EVENT_CAP_DELETE:   // (cap)
    case EVENT_CAP_ENABLE:   // (cap)
    case EVENT_CAP_DISABLE:  // (cap)
    {
        postCapNo(&eventBuf,capno);
        break;
    }

    default:
        barf("postCapEvent: unknown event tag %d", tag);
    }

    RELEASE_LOCK(&eventBufMutex);
}

730 731 732
void postCapsetEvent (EventTypeNum tag,
                      EventCapsetID capset,
                      StgWord info)
733 734
{
    ACQUIRE_LOCK(&eventBufMutex);
735
    ensureRoomForEvent(&eventBuf, tag);
736 737 738 739 740 741 742

    postEventHeader(&eventBuf, tag);
    postCapsetID(&eventBuf, capset);

    switch (tag) {
    case EVENT_CAPSET_CREATE:   // (capset, capset_type)
    {
743
        postCapsetType(&eventBuf, info /* capset_type */);
744 745 746 747 748 749 750 751 752 753 754
        break;
    }

    case EVENT_CAPSET_DELETE:   // (capset)
    {
        break;
    }

    case EVENT_CAPSET_ASSIGN_CAP:  // (capset, capno)
    case EVENT_CAPSET_REMOVE_CAP:  // (capset, capno)
    {
755
        postCapNo(&eventBuf, info /* capno */);
756 757
        break;
    }
758 759 760
    case EVENT_OSPROCESS_PID:   // (capset, pid)
    case EVENT_OSPROCESS_PPID:  // (capset, parent_pid)
    {
761
        postOSProcessId(&eventBuf, info);
762 763
        break;
    }
764
    default:
765
        barf("postCapsetEvent: unknown event tag %d", tag);
766 767 768 769 770
    }

    RELEASE_LOCK(&eventBufMutex);
}

771 772 773 774 775
void postCapsetStrEvent (EventTypeNum tag,
                         EventCapsetID capset,
                         char *msg)
{
    int strsize = strlen(msg);
776
    int size = strsize + sizeof(EventCapsetID);
Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
777 778 779 780
    if (size > EVENT_PAYLOAD_SIZE_MAX) {
        errorBelch("Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out");
        return;
    }
781 782 783 784 785 786 787

    ACQUIRE_LOCK(&eventBufMutex);

    if (!hasRoomForVariableEvent(&eventBuf, size)){
        printAndClearEventBuf(&eventBuf);

        if (!hasRoomForVariableEvent(&eventBuf, size)){
Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
788
            errorBelch("Event size exceeds buffer size, bail out");
789 790 791 792 793 794 795 796 797 798 799 800 801 802 803 804 805 806 807
            RELEASE_LOCK(&eventBufMutex);
            return;
        }
    }

    postEventHeader(&eventBuf, tag);
    postPayloadSize(&eventBuf, size);
    postCapsetID(&eventBuf, capset);

    postBuf(&eventBuf, (StgWord8*) msg, strsize);

    RELEASE_LOCK(&eventBufMutex);
}

void postCapsetVecEvent (EventTypeNum tag,
                         EventCapsetID capset,
                         int argc,
                         char *argv[])
{
808
    int size = sizeof(EventCapsetID);
809

810
    for (int i = 0; i < argc; i++) {
811 812 813 814 815 816 817 818 819 820
        // 1 + strlen to account for the trailing \0, used as separator
        size += 1 + strlen(argv[i]);
    }

    ACQUIRE_LOCK(&eventBufMutex);

    if (!hasRoomForVariableEvent(&eventBuf, size)){
        printAndClearEventBuf(&eventBuf);

        if(!hasRoomForVariableEvent(&eventBuf, size)){
Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
821
            errorBelch("Event size exceeds buffer size, bail out");
822 823 824 825 826 827 828 829 830
            RELEASE_LOCK(&eventBufMutex);
            return;
        }
    }

    postEventHeader(&eventBuf, tag);
    postPayloadSize(&eventBuf, size);
    postCapsetID(&eventBuf, capset);

831
    for (int i = 0; i < argc; i++) {
832 833 834 835 836 837 838
        // again, 1 + to account for \0
        postBuf(&eventBuf, (StgWord8*) argv[i], 1 + strlen(argv[i]));
    }

    RELEASE_LOCK(&eventBufMutex);
}

839 840 841 842 843 844 845
void postWallClockTime (EventCapsetID capset)
{
    StgWord64 ts;
    StgWord64 sec;
    StgWord32 nsec;

    ACQUIRE_LOCK(&eventBufMutex);
846

847 848 849 850 851 852 853 854 855 856 857 858 859 860 861
    /* The EVENT_WALL_CLOCK_TIME event is intended to allow programs
       reading the eventlog to match up the event timestamps with wall
       clock time. The normal event timestamps measure time since the
       start of the program. To align eventlogs from concurrent
       processes we need to be able to match up the timestamps. One way
       to do this is if we know how the timestamps and wall clock time
       match up (and of course if both processes have sufficiently
       synchronised clocks).

       So we want to make sure that the timestamp that we generate for
       this event matches up very closely with the wall clock time.
       Unfortunately we currently have to use two different APIs to get
       the elapsed time vs the wall clock time. So to minimise the
       difference we just call them very close together.
     */
862

863 864
    getUnixEpochTime(&sec, &nsec);  /* Get the wall clock time */
    ts = time_ns();                 /* Get the eventlog timestamp */
865
    ensureRoomForEvent(&eventBuf, EVENT_WALL_CLOCK_TIME);
866 867 868 869 870 871

    /* Normally we'd call postEventHeader(), but that generates its own
       timestamp, so we go one level lower so we can write out the
       timestamp we already generated above. */
    postEventTypeNum(&eventBuf, EVENT_WALL_CLOCK_TIME);
    postWord64(&eventBuf, ts);
872

873 874 875 876 877 878 879 880
    /* EVENT_WALL_CLOCK_TIME (capset, unix_epoch_seconds, nanoseconds) */
    postCapsetID(&eventBuf, capset);
    postWord64(&eventBuf, sec);
    postWord32(&eventBuf, nsec);

    RELEASE_LOCK(&eventBufMutex);
}

881 882 883 884 885 886
/*
 * Various GC and heap events
 */
void postHeapEvent (Capability    *cap,
                    EventTypeNum   tag,
                    EventCapsetID  heap_capset,
887
                    W_           info1)
888
{
889
    EventsBuf *eb = &capEventBuf[cap->no];
890
    ensureRoomForEvent(eb, tag);
891

892 893 894 895 896 897 898 899
    postEventHeader(eb, tag);

    switch (tag) {
    case EVENT_HEAP_ALLOCATED:     // (heap_capset, alloc_bytes)
    case EVENT_HEAP_SIZE:          // (heap_capset, size_bytes)
    case EVENT_HEAP_LIVE:          // (heap_capset, live_bytes)
    {
        postCapsetID(eb, heap_capset);
900
        postWord64(eb, info1 /* alloc/size/live_bytes */);
901 902 903 904 905 906 907 908 909
        break;
    }

    default:
        barf("postHeapEvent: unknown event tag %d", tag);
    }
}

void postEventHeapInfo (EventCapsetID heap_capset,
910
                        uint32_t    gens,
911 912 913 914
                        W_          maxHeapSize,
                        W_          allocAreaSize,
                        W_          mblockSize,
                        W_          blockSize)
915 916
{
    ACQUIRE_LOCK(&eventBufMutex);
917
    ensureRoomForEvent(&eventBuf, EVENT_HEAP_INFO_GHC);
918 919 920 921 922 923 924 925 926 927 928 929 930 931 932 933 934

    postEventHeader(&eventBuf, EVENT_HEAP_INFO_GHC);
    /* EVENT_HEAP_INFO_GHC (heap_capset, n_generations,
                            max_heap_size, alloc_area_size,
                            mblock_size, block_size) */
    postCapsetID(&eventBuf, heap_capset);
    postWord16(&eventBuf, gens);
    postWord64(&eventBuf, maxHeapSize);
    postWord64(&eventBuf, allocAreaSize);
    postWord64(&eventBuf, mblockSize);
    postWord64(&eventBuf, blockSize);

    RELEASE_LOCK(&eventBufMutex);
}

void postEventGcStats  (Capability    *cap,
                        EventCapsetID  heap_capset,
935
                        uint32_t     gen,
936 937 938
                        W_           copied,
                        W_           slop,
                        W_           fragmentation,
939
                        uint32_t     par_n_threads,
940
                        W_           par_max_copied,
941 942
                        W_           par_tot_copied,
                        W_           par_balanced_copied)
943
{
944
    EventsBuf *eb = &capEventBuf[cap->no];
945
    ensureRoomForEvent(eb, EVENT_GC_STATS_GHC);
946

947 948 949
    postEventHeader(eb, EVENT_GC_STATS_GHC);
    /* EVENT_GC_STATS_GHC (heap_capset, generation,
                           copied_bytes, slop_bytes, frag_bytes,
950 951
                           par_n_threads, par_max_copied,
                           par_tot_copied, par_balanced_copied) */
952 953 954 955 956 957 958 959
    postCapsetID(eb, heap_capset);
    postWord16(eb, gen);
    postWord64(eb, copied);
    postWord64(eb, slop);
    postWord64(eb, fragmentation);
    postWord32(eb, par_n_threads);
    postWord64(eb, par_max_copied);
    postWord64(eb, par_tot_copied);
960
    postWord64(eb, par_balanced_copied);
961 962
}

963 964 965 966 967
void postTaskCreateEvent (EventTaskId taskId,
                          EventCapNo capno,
                          EventKernelThreadId tid)
{
    ACQUIRE_LOCK(&eventBufMutex);
968
    ensureRoomForEvent(&eventBuf, EVENT_TASK_CREATE);
969 970 971 972 973 974 975 976 977 978 979 980 981 982 983

    postEventHeader(&eventBuf, EVENT_TASK_CREATE);
    /* EVENT_TASK_CREATE (taskID, cap, tid) */
    postTaskId(&eventBuf, taskId);
    postCapNo(&eventBuf, capno);
    postKernelThreadId(&eventBuf, tid);

    RELEASE_LOCK(&eventBufMutex);
}

void postTaskMigrateEvent (EventTaskId taskId,
                           EventCapNo capno,
                           EventCapNo new_capno)
{
    ACQUIRE_LOCK(&eventBufMutex);
984
    ensureRoomForEvent(&eventBuf, EVENT_TASK_MIGRATE);
985 986 987 988 989 990 991 992 993 994 995 996 997

    postEventHeader(&eventBuf, EVENT_TASK_MIGRATE);
    /* EVENT_TASK_MIGRATE (taskID, cap, new_cap) */
    postTaskId(&eventBuf, taskId);
    postCapNo(&eventBuf, capno);
    postCapNo(&eventBuf, new_capno);

    RELEASE_LOCK(&eventBufMutex);
}

void postTaskDeleteEvent (EventTaskId taskId)
{
    ACQUIRE_LOCK(&eventBufMutex);
998
    ensureRoomForEvent(&eventBuf, EVENT_TASK_DELETE);
999 1000 1001 1002 1003 1004 1005 1006

    postEventHeader(&eventBuf, EVENT_TASK_DELETE);
    /* EVENT_TASK_DELETE (taskID) */
    postTaskId(&eventBuf, taskId);

    RELEASE_LOCK(&eventBufMutex);
}

1007 1008 1009
void
postEvent (Capability *cap, EventTypeNum tag)
{
1010
    EventsBuf *eb = &capEventBuf[cap->no];
1011
    ensureRoomForEvent(eb, tag);
1012 1013 1014
    postEventHeader(eb, tag);
}

1015 1016 1017
void
postEventAtTimestamp (Capability *cap, EventTimestamp ts, EventTypeNum tag)
{
1018
    EventsBuf *eb = &capEventBuf[cap->no];
1019
    ensureRoomForEvent(eb, tag);
1020 1021 1022 1023 1024 1025 1026 1027

    /* Normally we'd call postEventHeader(), but that generates its own
       timestamp, so we go one level lower so we can write out
       the timestamp we received as an argument. */
    postEventTypeNum(eb, tag);
    postWord64(eb, ts);
}

1028 1029
#define BUF 512

1030
void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
1031 1032
{
    char buf[BUF];
1033
    uint32_t size = vsnprintf(buf, BUF, msg,ap);
1034 1035 1036 1037 1038
    if (size > BUF) {
        buf[BUF-1] = '\0';
        size = BUF;
    }

1039
    ensureRoomForVariableEvent(eb, size);
1040

1041
    postEventHeader(eb, type);
1042 1043
    postPayloadSize(eb, size);
    postBuf(eb,(StgWord8*)buf,size);
1044
}
1045

1046 1047 1048
void postMsg(char *msg, va_list ap)
{
    ACQUIRE_LOCK(&eventBufMutex);
1049
    postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
1050 1051 1052 1053 1054
    RELEASE_LOCK(&eventBufMutex);
}

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

1058
void postUserEvent(Capability *cap, EventTypeNum type, char *msg)
1059
{
Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
1060 1061 1062 1063 1064 1065
    const size_t size = strlen(msg);
    if (size > EVENT_PAYLOAD_SIZE_MAX) {
        errorBelch("Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out");
        return;
    }

1066
    EventsBuf *eb = &capEventBuf[cap->no];
Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
1067 1068 1069 1070 1071 1072 1073 1074
    if (!hasRoomForVariableEvent(eb, size)){
        printAndClearEventBuf(eb);

        if (!hasRoomForVariableEvent(eb, size)){
            errorBelch("Event size exceeds buffer size, bail out");
            return;
        }
    }
1075

Mitsutoshi Aoe's avatar
Mitsutoshi Aoe committed
1076 1077 1078 1079 1080 1081 1082 1083 1084 1085 1086 1087 1088 1089 1090 1091
    postEventHeader(eb, type);
    postPayloadSize(eb, size);
    postBuf(eb, (StgWord8*) msg, size);
}

void postUserBinaryEvent(Capability   *cap,
                         EventTypeNum  type,
                         uint8_t      *msg,
                         size_t        size)
{
    if (size > EVENT_PAYLOAD_SIZE_MAX) {
        errorBelch("Event size exceeds EVENT_PAYLOAD_SIZE_MAX, bail out");
        return;
    }

    EventsBuf *eb = &capEventBuf[cap->no];