ef96f3c8801247f9f1325b18bb49c2004d0466ce
[ghc.git] / 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_THREAD_WAKEUP] = "Wakeup thread",
64 [EVENT_THREAD_LABEL] = "Thread label",
65 [EVENT_STARTUP] = "Create capabilities",
66 [EVENT_CAP_CREATE] = "Create capability",
67 [EVENT_CAP_DELETE] = "Delete capability",
68 [EVENT_CAP_DISABLE] = "Disable capability",
69 [EVENT_CAP_ENABLE] = "Enable capability",
70 [EVENT_GC_START] = "Starting GC",
71 [EVENT_GC_END] = "Finished GC",
72 [EVENT_REQUEST_SEQ_GC] = "Request sequential GC",
73 [EVENT_REQUEST_PAR_GC] = "Request parallel GC",
74 [EVENT_GC_GLOBAL_SYNC] = "Synchronise stop-the-world GC",
75 [EVENT_GC_STATS_GHC] = "GC statistics",
76 [EVENT_HEAP_INFO_GHC] = "Heap static parameters",
77 [EVENT_HEAP_ALLOCATED] = "Total heap mem ever allocated",
78 [EVENT_HEAP_SIZE] = "Current heap size",
79 [EVENT_HEAP_LIVE] = "Current heap live data",
80 [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
81 [EVENT_LOG_MSG] = "Log message",
82 [EVENT_USER_MSG] = "User message",
83 [EVENT_USER_MARKER] = "User marker",
84 [EVENT_GC_IDLE] = "GC idle",
85 [EVENT_GC_WORK] = "GC working",
86 [EVENT_GC_DONE] = "GC done",
87 [EVENT_BLOCK_MARKER] = "Block marker",
88 [EVENT_CAPSET_CREATE] = "Create capability set",
89 [EVENT_CAPSET_DELETE] = "Delete capability set",
90 [EVENT_CAPSET_ASSIGN_CAP] = "Add capability to capability set",
91 [EVENT_CAPSET_REMOVE_CAP] = "Remove capability from capability set",
92 [EVENT_RTS_IDENTIFIER] = "RTS name and version",
93 [EVENT_PROGRAM_ARGS] = "Program arguments",
94 [EVENT_PROGRAM_ENV] = "Program environment variables",
95 [EVENT_OSPROCESS_PID] = "Process ID",
96 [EVENT_OSPROCESS_PPID] = "Parent process ID",
97 [EVENT_WALL_CLOCK_TIME] = "Wall clock time",
98 [EVENT_SPARK_COUNTERS] = "Spark counters",
99 [EVENT_SPARK_CREATE] = "Spark create",
100 [EVENT_SPARK_DUD] = "Spark dud",
101 [EVENT_SPARK_OVERFLOW] = "Spark overflow",
102 [EVENT_SPARK_RUN] = "Spark run",
103 [EVENT_SPARK_STEAL] = "Spark steal",
104 [EVENT_SPARK_FIZZLE] = "Spark fizzle",
105 [EVENT_SPARK_GC] = "Spark GC",
106 [EVENT_TASK_CREATE] = "Task create",
107 [EVENT_TASK_MIGRATE] = "Task migrate",
108 [EVENT_TASK_DELETE] = "Task delete",
109 [EVENT_HACK_BUG_T9003] = "Empty event for bug #9003",
110 };
111
112 // Event type.
113
114 typedef struct _EventType {
115 EventTypeNum etNum; // Event Type number.
116 nat size; // size of the payload in bytes
117 char *desc; // Description
118 } EventType;
119
120 EventType eventTypes[NUM_GHC_EVENT_TAGS];
121
122 static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
123 static void resetEventsBuf(EventsBuf* eb);
124 static void printAndClearEventBuf (EventsBuf *eventsBuf);
125
126 static void postEventType(EventsBuf *eb, EventType *et);
127
128 static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap);
129
130 static void postBlockMarker(EventsBuf *eb);
131 static void closeBlockMarker(EventsBuf *ebuf);
132
133 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
134 static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);
135
136 static inline void postWord8(EventsBuf *eb, StgWord8 i)
137 {
138 *(eb->pos++) = i;
139 }
140
141 static inline void postWord16(EventsBuf *eb, StgWord16 i)
142 {
143 postWord8(eb, (StgWord8)(i >> 8));
144 postWord8(eb, (StgWord8)i);
145 }
146
147 static inline void postWord32(EventsBuf *eb, StgWord32 i)
148 {
149 postWord16(eb, (StgWord16)(i >> 16));
150 postWord16(eb, (StgWord16)i);
151 }
152
153 static inline void postWord64(EventsBuf *eb, StgWord64 i)
154 {
155 postWord32(eb, (StgWord32)(i >> 32));
156 postWord32(eb, (StgWord32)i);
157 }
158
159 static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
160 {
161 memcpy(eb->pos, buf, size);
162 eb->pos += size;
163 }
164
165 static inline StgWord64 time_ns(void)
166 { return TimeToNS(stat_getElapsedTime()); }
167
168 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
169 { postWord16(eb, etNum); }
170
171 static inline void postTimestamp(EventsBuf *eb)
172 { postWord64(eb, time_ns()); }
173
174 static inline void postThreadID(EventsBuf *eb, EventThreadID id)
175 { postWord32(eb,id); }
176
177 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
178 { postWord16(eb,no); }
179
180 static inline void postCapsetID(EventsBuf *eb, EventCapsetID id)
181 { postWord32(eb,id); }
182
183 static inline void postCapsetType(EventsBuf *eb, EventCapsetType type)
184 { postWord16(eb,type); }
185
186 static inline void postOSProcessId(EventsBuf *eb, pid_t pid)
187 { postWord32(eb, pid); }
188
189 static inline void postKernelThreadId(EventsBuf *eb, EventKernelThreadId tid)
190 { postWord64(eb, tid); }
191
192 static inline void postTaskId(EventsBuf *eb, EventTaskId tUniq)
193 { postWord64(eb, tUniq); }
194
195 static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
196 { postWord16(eb,size); }
197
198 static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
199 {
200 postEventTypeNum(eb, type);
201 postTimestamp(eb);
202 }
203
204 static inline void postInt8(EventsBuf *eb, StgInt8 i)
205 { postWord8(eb, (StgWord8)i); }
206
207 static inline void postInt32(EventsBuf *eb, StgInt32 i)
208 { postWord32(eb, (StgWord32)i); }
209
210
211 void
212 initEventLogging(void)
213 {
214 StgWord8 t, c;
215 nat n_caps;
216 char *prog;
217
218 prog = stgMallocBytes(strlen(prog_name) + 1, "initEventLogging");
219 strcpy(prog, prog_name);
220 #ifdef mingw32_HOST_OS
221 // on Windows, drop the .exe suffix if there is one
222 {
223 char *suff;
224 suff = strrchr(prog,'.');
225 if (suff != NULL && !strcmp(suff,".exe")) {
226 *suff = '\0';
227 }
228 }
229 #endif
230
231 event_log_filename = stgMallocBytes(strlen(prog)
232 + 10 /* .%d */
233 + 10 /* .eventlog */,
234 "initEventLogging");
235
236 if (sizeof(EventDesc) / sizeof(char*) != NUM_GHC_EVENT_TAGS) {
237 barf("EventDesc array has the wrong number of elements");
238 }
239
240 if (event_log_pid == -1) { // #4512
241 // Single process
242 sprintf(event_log_filename, "%s.eventlog", prog);
243 event_log_pid = getpid();
244 } else {
245 // Forked process, eventlog already started by the parent
246 // before fork
247 event_log_pid = getpid();
248 // We don't have a FMT* symbol for pid_t, so we go via Word64
249 // to be sure of not losing range. It would be nicer to have a
250 // FMT* symbol or similar, though.
251 sprintf(event_log_filename, "%s.%" FMT_Word64 ".eventlog",
252 prog, (StgWord64)event_log_pid);
253 }
254 stgFree(prog);
255
256 /* Open event log file for writing. */
257 if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
258 sysErrorBelch("initEventLogging: can't open %s", event_log_filename);
259 stg_exit(EXIT_FAILURE);
260 }
261
262 /*
263 * Allocate buffer(s) to store events.
264 * Create buffer large enough for the header begin marker, all event
265 * types, and header end marker to prevent checking if buffer has room
266 * for each of these steps, and remove the need to flush the buffer to
267 * disk during initialization.
268 *
269 * Use a single buffer to store the header with event types, then flush
270 * the buffer so all buffers are empty for writing events.
271 */
272 #ifdef THREADED_RTS
273 // XXX n_capabilities hasn't been initislised yet
274 n_caps = RtsFlags.ParFlags.nNodes;
275 #else
276 n_caps = 1;
277 #endif
278 moreCapEventBufs(0,n_caps);
279
280 initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
281
282 // Write in buffer: the header begin marker.
283 postInt32(&eventBuf, EVENT_HEADER_BEGIN);
284
285 // Mark beginning of event types in the header.
286 postInt32(&eventBuf, EVENT_HET_BEGIN);
287 for (t = 0; t < NUM_GHC_EVENT_TAGS; ++t) {
288
289 eventTypes[t].etNum = t;
290 eventTypes[t].desc = EventDesc[t];
291
292 switch (t) {
293 case EVENT_CREATE_THREAD: // (cap, thread)
294 case EVENT_RUN_THREAD: // (cap, thread)
295 case EVENT_THREAD_RUNNABLE: // (cap, thread)
296 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
297 eventTypes[t].size = sizeof(EventThreadID);
298 break;
299
300 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
301 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
302 eventTypes[t].size =
303 sizeof(EventThreadID) + sizeof(EventCapNo);
304 break;
305
306 case EVENT_STOP_THREAD: // (cap, thread, status)
307 eventTypes[t].size = sizeof(EventThreadID)
308 + sizeof(StgWord16)
309 + sizeof(EventThreadID);
310 break;
311
312 case EVENT_STARTUP: // (cap_count)
313 case EVENT_CAP_CREATE: // (cap)
314 case EVENT_CAP_DELETE: // (cap)
315 case EVENT_CAP_ENABLE: // (cap)
316 case EVENT_CAP_DISABLE: // (cap)
317 eventTypes[t].size = sizeof(EventCapNo);
318 break;
319
320 case EVENT_CAPSET_CREATE: // (capset, capset_type)
321 eventTypes[t].size =
322 sizeof(EventCapsetID) + sizeof(EventCapsetType);
323 break;
324
325 case EVENT_CAPSET_DELETE: // (capset)
326 eventTypes[t].size = sizeof(EventCapsetID);
327 break;
328
329 case EVENT_CAPSET_ASSIGN_CAP: // (capset, cap)
330 case EVENT_CAPSET_REMOVE_CAP:
331 eventTypes[t].size =
332 sizeof(EventCapsetID) + sizeof(EventCapNo);
333 break;
334
335 case EVENT_OSPROCESS_PID: // (cap, pid)
336 case EVENT_OSPROCESS_PPID:
337 eventTypes[t].size =
338 sizeof(EventCapsetID) + sizeof(StgWord32);
339 break;
340
341 case EVENT_WALL_CLOCK_TIME: // (capset, unix_epoch_seconds, nanoseconds)
342 eventTypes[t].size =
343 sizeof(EventCapsetID) + sizeof(StgWord64) + sizeof(StgWord32);
344 break;
345
346 case EVENT_SPARK_STEAL: // (cap, victim_cap)
347 eventTypes[t].size =
348 sizeof(EventCapNo);
349 break;
350
351 case EVENT_REQUEST_SEQ_GC: // (cap)
352 case EVENT_REQUEST_PAR_GC: // (cap)
353 case EVENT_GC_START: // (cap)
354 case EVENT_GC_END: // (cap)
355 case EVENT_GC_IDLE:
356 case EVENT_GC_WORK:
357 case EVENT_GC_DONE:
358 case EVENT_GC_GLOBAL_SYNC: // (cap)
359 case EVENT_SPARK_CREATE: // (cap)
360 case EVENT_SPARK_DUD: // (cap)
361 case EVENT_SPARK_OVERFLOW: // (cap)
362 case EVENT_SPARK_RUN: // (cap)
363 case EVENT_SPARK_FIZZLE: // (cap)
364 case EVENT_SPARK_GC: // (cap)
365 eventTypes[t].size = 0;
366 break;
367
368 case EVENT_LOG_MSG: // (msg)
369 case EVENT_USER_MSG: // (msg)
370 case EVENT_USER_MARKER: // (markername)
371 case EVENT_RTS_IDENTIFIER: // (capset, str)
372 case EVENT_PROGRAM_ARGS: // (capset, strvec)
373 case EVENT_PROGRAM_ENV: // (capset, strvec)
374 case EVENT_THREAD_LABEL: // (thread, str)
375 eventTypes[t].size = 0xffff;
376 break;
377
378 case EVENT_SPARK_COUNTERS: // (cap, 7*counter)
379 eventTypes[t].size = 7 * sizeof(StgWord64);
380 break;
381
382 case EVENT_HEAP_ALLOCATED: // (heap_capset, alloc_bytes)
383 case EVENT_HEAP_SIZE: // (heap_capset, size_bytes)
384 case EVENT_HEAP_LIVE: // (heap_capset, live_bytes)
385 eventTypes[t].size = sizeof(EventCapsetID) + sizeof(StgWord64);
386 break;
387
388 case EVENT_HEAP_INFO_GHC: // (heap_capset, n_generations,
389 // max_heap_size, alloc_area_size,
390 // mblock_size, block_size)
391 eventTypes[t].size = sizeof(EventCapsetID)
392 + sizeof(StgWord16)
393 + sizeof(StgWord64) * 4;
394 break;
395
396 case EVENT_GC_STATS_GHC: // (heap_capset, generation,
397 // copied_bytes, slop_bytes, frag_bytes,
398 // par_n_threads,
399 // par_max_copied, par_tot_copied)
400 eventTypes[t].size = sizeof(EventCapsetID)
401 + sizeof(StgWord16)
402 + sizeof(StgWord64) * 3
403 + sizeof(StgWord32)
404 + sizeof(StgWord64) * 2;
405 break;
406
407 case EVENT_TASK_CREATE: // (taskId, cap, tid)
408 eventTypes[t].size = sizeof(EventTaskId)
409 + sizeof(EventCapNo)
410 + sizeof(EventKernelThreadId);
411 break;
412
413 case EVENT_TASK_MIGRATE: // (taskId, cap, new_cap)
414 eventTypes[t].size =
415 sizeof(EventTaskId) + sizeof(EventCapNo) + sizeof(EventCapNo);
416 break;
417
418 case EVENT_TASK_DELETE: // (taskId)
419 eventTypes[t].size = sizeof(EventTaskId);
420 break;
421
422 case EVENT_BLOCK_MARKER:
423 eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) +
424 sizeof(EventCapNo);
425 break;
426
427 case EVENT_HACK_BUG_T9003:
428 eventTypes[t].size = 0;
429 break;
430
431 default:
432 continue; /* ignore deprecated events */
433 }
434
435 // Write in buffer: the start event type.
436 postEventType(&eventBuf, &eventTypes[t]);
437 }
438
439 // Mark end of event types in the header.
440 postInt32(&eventBuf, EVENT_HET_END);
441
442 // Write in buffer: the header end marker.
443 postInt32(&eventBuf, EVENT_HEADER_END);
444
445 // Prepare event buffer for events (data).
446 postInt32(&eventBuf, EVENT_DATA_BEGIN);
447
448 // Flush capEventBuf with header.
449 /*
450 * Flush header and data begin marker to the file, thus preparing the
451 * file to have events written to it.
452 */
453 printAndClearEventBuf(&eventBuf);
454
455 for (c = 0; c < n_caps; ++c) {
456 postBlockMarker(&capEventBuf[c]);
457 }
458
459 #ifdef THREADED_RTS
460 initMutex(&eventBufMutex);
461 #endif
462 }
463
464 void
465 endEventLogging(void)
466 {
467 nat c;
468
469 // Flush all events remaining in the buffers.
470 for (c = 0; c < n_capabilities; ++c) {
471 printAndClearEventBuf(&capEventBuf[c]);
472 }
473 printAndClearEventBuf(&eventBuf);
474 resetEventsBuf(&eventBuf); // we don't want the block marker
475
476 // Mark end of events (data).
477 postEventTypeNum(&eventBuf, EVENT_DATA_END);
478
479 // Flush the end of data marker.
480 printAndClearEventBuf(&eventBuf);
481
482 if (event_log_file != NULL) {
483 fclose(event_log_file);
484 }
485 }
486
487 void
488 moreCapEventBufs (nat from, nat to)
489 {
490 nat c;
491
492 if (from > 0) {
493 capEventBuf = stgReallocBytes(capEventBuf, to * sizeof(EventsBuf),
494 "moreCapEventBufs");
495 } else {
496 capEventBuf = stgMallocBytes(to * sizeof(EventsBuf),
497 "moreCapEventBufs");
498 }
499
500 for (c = from; c < to; ++c) {
501 initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
502 }
503 }
504
505
506 void
507 freeEventLogging(void)
508 {
509 StgWord8 c;
510
511 // Free events buffer.
512 for (c = 0; c < n_capabilities; ++c) {
513 if (capEventBuf[c].begin != NULL)
514 stgFree(capEventBuf[c].begin);
515 }
516 if (capEventBuf != NULL) {
517 stgFree(capEventBuf);
518 }
519 if (event_log_filename != NULL) {
520 stgFree(event_log_filename);
521 }
522 }
523
524 void
525 flushEventLog(void)
526 {
527 if (event_log_file != NULL) {
528 fflush(event_log_file);
529 }
530 }
531
532 void
533 abortEventLogging(void)
534 {
535 freeEventLogging();
536 if (event_log_file != NULL) {
537 fclose(event_log_file);
538 }
539 }
540 /*
541 * Post an event message to the capability's eventlog buffer.
542 * If the buffer is full, prints out the buffer and clears it.
543 */
544 void
545 postSchedEvent (Capability *cap,
546 EventTypeNum tag,
547 StgThreadID thread,
548 StgWord info1,
549 StgWord info2)
550 {
551 EventsBuf *eb;
552
553 eb = &capEventBuf[cap->no];
554
555 if (!hasRoomForEvent(eb, tag)) {
556 // Flush event buffer to make room for new event.
557 printAndClearEventBuf(eb);
558 }
559
560 postEventHeader(eb, tag);
561
562 switch (tag) {
563 case EVENT_CREATE_THREAD: // (cap, thread)
564 case EVENT_RUN_THREAD: // (cap, thread)
565 case EVENT_THREAD_RUNNABLE: // (cap, thread)
566 {
567 postThreadID(eb,thread);
568 break;
569 }
570
571 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
572 {
573 postThreadID(eb,info1 /* spark_thread */);
574 break;
575 }
576
577 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
578 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
579 {
580 postThreadID(eb,thread);
581 postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */);
582 break;
583 }
584
585 case EVENT_STOP_THREAD: // (cap, thread, status)
586 {
587 postThreadID(eb,thread);
588 postWord16(eb,info1 /* status */);
589 postThreadID(eb,info2 /* blocked on thread */);
590 break;
591 }
592
593 default:
594 barf("postSchedEvent: unknown event tag %d", tag);
595 }
596 }
597
598 void
599 postSparkEvent (Capability *cap,
600 EventTypeNum tag,
601 StgWord info1)
602 {
603 EventsBuf *eb;
604
605 eb = &capEventBuf[cap->no];
606
607 if (!hasRoomForEvent(eb, tag)) {
608 // Flush event buffer to make room for new event.
609 printAndClearEventBuf(eb);
610 }
611
612 postEventHeader(eb, tag);
613
614 switch (tag) {
615 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
616 {
617 postThreadID(eb,info1 /* spark_thread */);
618 break;
619 }
620
621 case EVENT_SPARK_STEAL: // (cap, victim_cap)
622 {
623 postCapNo(eb,info1 /* victim_cap */);
624 break;
625 }
626
627 case EVENT_SPARK_CREATE: // (cap)
628 case EVENT_SPARK_DUD: // (cap)
629 case EVENT_SPARK_OVERFLOW: // (cap)
630 case EVENT_SPARK_RUN: // (cap)
631 case EVENT_SPARK_FIZZLE: // (cap)
632 case EVENT_SPARK_GC: // (cap)
633 {
634 break;
635 }
636
637 default:
638 barf("postSparkEvent: unknown event tag %d", tag);
639 }
640 }
641
642 void
643 postSparkCountersEvent (Capability *cap,
644 SparkCounters counters,
645 StgWord remaining)
646 {
647 EventsBuf *eb;
648
649 eb = &capEventBuf[cap->no];
650
651 if (!hasRoomForEvent(eb, EVENT_SPARK_COUNTERS)) {
652 // Flush event buffer to make room for new event.
653 printAndClearEventBuf(eb);
654 }
655
656 postEventHeader(eb, EVENT_SPARK_COUNTERS);
657 /* EVENT_SPARK_COUNTERS (crt,dud,ovf,cnv,gcd,fiz,rem) */
658 postWord64(eb,counters.created);
659 postWord64(eb,counters.dud);
660 postWord64(eb,counters.overflowed);
661 postWord64(eb,counters.converted);
662 postWord64(eb,counters.gcd);
663 postWord64(eb,counters.fizzled);
664 postWord64(eb,remaining);
665 }
666
667 void
668 postCapEvent (EventTypeNum tag,
669 EventCapNo capno)
670 {
671 ACQUIRE_LOCK(&eventBufMutex);
672
673 if (!hasRoomForEvent(&eventBuf, tag)) {
674 // Flush event buffer to make room for new event.
675 printAndClearEventBuf(&eventBuf);
676 }
677
678 postEventHeader(&eventBuf, tag);
679
680 switch (tag) {
681 case EVENT_CAP_CREATE: // (cap)
682 case EVENT_CAP_DELETE: // (cap)
683 case EVENT_CAP_ENABLE: // (cap)
684 case EVENT_CAP_DISABLE: // (cap)
685 {
686 postCapNo(&eventBuf,capno);
687 break;
688 }
689
690 default:
691 barf("postCapEvent: unknown event tag %d", tag);
692 }
693
694 RELEASE_LOCK(&eventBufMutex);
695 }
696
697 void postCapsetEvent (EventTypeNum tag,
698 EventCapsetID capset,
699 StgWord info)
700 {
701 ACQUIRE_LOCK(&eventBufMutex);
702
703 if (!hasRoomForEvent(&eventBuf, tag)) {
704 // Flush event buffer to make room for new event.
705 printAndClearEventBuf(&eventBuf);
706 }
707
708 postEventHeader(&eventBuf, tag);
709 postCapsetID(&eventBuf, capset);
710
711 switch (tag) {
712 case EVENT_CAPSET_CREATE: // (capset, capset_type)
713 {
714 postCapsetType(&eventBuf, info /* capset_type */);
715 break;
716 }
717
718 case EVENT_CAPSET_DELETE: // (capset)
719 {
720 break;
721 }
722
723 case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno)
724 case EVENT_CAPSET_REMOVE_CAP: // (capset, capno)
725 {
726 postCapNo(&eventBuf, info /* capno */);
727 break;
728 }
729 case EVENT_OSPROCESS_PID: // (capset, pid)
730 case EVENT_OSPROCESS_PPID: // (capset, parent_pid)
731 {
732 postOSProcessId(&eventBuf, info);
733 break;
734 }
735 default:
736 barf("postCapsetEvent: unknown event tag %d", tag);
737 }
738
739 RELEASE_LOCK(&eventBufMutex);
740 }
741
742 void postCapsetStrEvent (EventTypeNum tag,
743 EventCapsetID capset,
744 char *msg)
745 {
746 int strsize = strlen(msg);
747 int size = strsize + sizeof(EventCapsetID);
748
749 ACQUIRE_LOCK(&eventBufMutex);
750
751 if (!hasRoomForVariableEvent(&eventBuf, size)){
752 printAndClearEventBuf(&eventBuf);
753
754 if (!hasRoomForVariableEvent(&eventBuf, size)){
755 // Event size exceeds buffer size, bail out:
756 RELEASE_LOCK(&eventBufMutex);
757 return;
758 }
759 }
760
761 postEventHeader(&eventBuf, tag);
762 postPayloadSize(&eventBuf, size);
763 postCapsetID(&eventBuf, capset);
764
765 postBuf(&eventBuf, (StgWord8*) msg, strsize);
766
767 RELEASE_LOCK(&eventBufMutex);
768 }
769
770 void postCapsetVecEvent (EventTypeNum tag,
771 EventCapsetID capset,
772 int argc,
773 char *argv[])
774 {
775 int i, size = sizeof(EventCapsetID);
776
777 for (i = 0; i < argc; i++) {
778 // 1 + strlen to account for the trailing \0, used as separator
779 size += 1 + strlen(argv[i]);
780 }
781
782 ACQUIRE_LOCK(&eventBufMutex);
783
784 if (!hasRoomForVariableEvent(&eventBuf, size)){
785 printAndClearEventBuf(&eventBuf);
786
787 if(!hasRoomForVariableEvent(&eventBuf, size)){
788 // Event size exceeds buffer size, bail out:
789 RELEASE_LOCK(&eventBufMutex);
790 return;
791 }
792 }
793
794 postEventHeader(&eventBuf, tag);
795 postPayloadSize(&eventBuf, size);
796 postCapsetID(&eventBuf, capset);
797
798 for( i = 0; i < argc; i++ ) {
799 // again, 1 + to account for \0
800 postBuf(&eventBuf, (StgWord8*) argv[i], 1 + strlen(argv[i]));
801 }
802
803 RELEASE_LOCK(&eventBufMutex);
804 }
805
806 void postWallClockTime (EventCapsetID capset)
807 {
808 StgWord64 ts;
809 StgWord64 sec;
810 StgWord32 nsec;
811
812 ACQUIRE_LOCK(&eventBufMutex);
813
814 /* The EVENT_WALL_CLOCK_TIME event is intended to allow programs
815 reading the eventlog to match up the event timestamps with wall
816 clock time. The normal event timestamps measure time since the
817 start of the program. To align eventlogs from concurrent
818 processes we need to be able to match up the timestamps. One way
819 to do this is if we know how the timestamps and wall clock time
820 match up (and of course if both processes have sufficiently
821 synchronised clocks).
822
823 So we want to make sure that the timestamp that we generate for
824 this event matches up very closely with the wall clock time.
825 Unfortunately we currently have to use two different APIs to get
826 the elapsed time vs the wall clock time. So to minimise the
827 difference we just call them very close together.
828 */
829
830 getUnixEpochTime(&sec, &nsec); /* Get the wall clock time */
831 ts = time_ns(); /* Get the eventlog timestamp */
832
833 if (!hasRoomForEvent(&eventBuf, EVENT_WALL_CLOCK_TIME)) {
834 // Flush event buffer to make room for new event.
835 printAndClearEventBuf(&eventBuf);
836 }
837
838 /* Normally we'd call postEventHeader(), but that generates its own
839 timestamp, so we go one level lower so we can write out the
840 timestamp we already generated above. */
841 postEventTypeNum(&eventBuf, EVENT_WALL_CLOCK_TIME);
842 postWord64(&eventBuf, ts);
843
844 /* EVENT_WALL_CLOCK_TIME (capset, unix_epoch_seconds, nanoseconds) */
845 postCapsetID(&eventBuf, capset);
846 postWord64(&eventBuf, sec);
847 postWord32(&eventBuf, nsec);
848
849 RELEASE_LOCK(&eventBufMutex);
850 }
851
852 /*
853 * Various GC and heap events
854 */
855 void postHeapEvent (Capability *cap,
856 EventTypeNum tag,
857 EventCapsetID heap_capset,
858 W_ info1)
859 {
860 EventsBuf *eb;
861
862 eb = &capEventBuf[cap->no];
863
864 if (!hasRoomForEvent(eb, tag)) {
865 // Flush event buffer to make room for new event.
866 printAndClearEventBuf(eb);
867 }
868
869 postEventHeader(eb, tag);
870
871 switch (tag) {
872 case EVENT_HEAP_ALLOCATED: // (heap_capset, alloc_bytes)
873 case EVENT_HEAP_SIZE: // (heap_capset, size_bytes)
874 case EVENT_HEAP_LIVE: // (heap_capset, live_bytes)
875 {
876 postCapsetID(eb, heap_capset);
877 postWord64(eb, info1 /* alloc/size/live_bytes */);
878 break;
879 }
880
881 default:
882 barf("postHeapEvent: unknown event tag %d", tag);
883 }
884 }
885
886 void postEventHeapInfo (EventCapsetID heap_capset,
887 nat gens,
888 W_ maxHeapSize,
889 W_ allocAreaSize,
890 W_ mblockSize,
891 W_ blockSize)
892 {
893 ACQUIRE_LOCK(&eventBufMutex);
894
895 if (!hasRoomForEvent(&eventBuf, EVENT_HEAP_INFO_GHC)) {
896 // Flush event buffer to make room for new event.
897 printAndClearEventBuf(&eventBuf);
898 }
899
900 postEventHeader(&eventBuf, EVENT_HEAP_INFO_GHC);
901 /* EVENT_HEAP_INFO_GHC (heap_capset, n_generations,
902 max_heap_size, alloc_area_size,
903 mblock_size, block_size) */
904 postCapsetID(&eventBuf, heap_capset);
905 postWord16(&eventBuf, gens);
906 postWord64(&eventBuf, maxHeapSize);
907 postWord64(&eventBuf, allocAreaSize);
908 postWord64(&eventBuf, mblockSize);
909 postWord64(&eventBuf, blockSize);
910
911 RELEASE_LOCK(&eventBufMutex);
912 }
913
914 void postEventGcStats (Capability *cap,
915 EventCapsetID heap_capset,
916 nat gen,
917 W_ copied,
918 W_ slop,
919 W_ fragmentation,
920 nat par_n_threads,
921 W_ par_max_copied,
922 W_ par_tot_copied)
923 {
924 EventsBuf *eb;
925
926 eb = &capEventBuf[cap->no];
927
928 if (!hasRoomForEvent(eb, EVENT_GC_STATS_GHC)) {
929 // Flush event buffer to make room for new event.
930 printAndClearEventBuf(eb);
931 }
932
933 postEventHeader(eb, EVENT_GC_STATS_GHC);
934 /* EVENT_GC_STATS_GHC (heap_capset, generation,
935 copied_bytes, slop_bytes, frag_bytes,
936 par_n_threads, par_max_copied, par_tot_copied) */
937 postCapsetID(eb, heap_capset);
938 postWord16(eb, gen);
939 postWord64(eb, copied);
940 postWord64(eb, slop);
941 postWord64(eb, fragmentation);
942 postWord32(eb, par_n_threads);
943 postWord64(eb, par_max_copied);
944 postWord64(eb, par_tot_copied);
945 }
946
947 void postTaskCreateEvent (EventTaskId taskId,
948 EventCapNo capno,
949 EventKernelThreadId tid)
950 {
951 ACQUIRE_LOCK(&eventBufMutex);
952
953 if (!hasRoomForEvent(&eventBuf, EVENT_TASK_CREATE)) {
954 // Flush event buffer to make room for new event.
955 printAndClearEventBuf(&eventBuf);
956 }
957
958 postEventHeader(&eventBuf, EVENT_TASK_CREATE);
959 /* EVENT_TASK_CREATE (taskID, cap, tid) */
960 postTaskId(&eventBuf, taskId);
961 postCapNo(&eventBuf, capno);
962 postKernelThreadId(&eventBuf, tid);
963
964 RELEASE_LOCK(&eventBufMutex);
965 }
966
967 void postTaskMigrateEvent (EventTaskId taskId,
968 EventCapNo capno,
969 EventCapNo new_capno)
970 {
971 ACQUIRE_LOCK(&eventBufMutex);
972
973 if (!hasRoomForEvent(&eventBuf, EVENT_TASK_MIGRATE)) {
974 // Flush event buffer to make room for new event.
975 printAndClearEventBuf(&eventBuf);
976 }
977
978 postEventHeader(&eventBuf, EVENT_TASK_MIGRATE);
979 /* EVENT_TASK_MIGRATE (taskID, cap, new_cap) */
980 postTaskId(&eventBuf, taskId);
981 postCapNo(&eventBuf, capno);
982 postCapNo(&eventBuf, new_capno);
983
984 RELEASE_LOCK(&eventBufMutex);
985 }
986
987 void postTaskDeleteEvent (EventTaskId taskId)
988 {
989 ACQUIRE_LOCK(&eventBufMutex);
990
991 if (!hasRoomForEvent(&eventBuf, EVENT_TASK_DELETE)) {
992 // Flush event buffer to make room for new event.
993 printAndClearEventBuf(&eventBuf);
994 }
995
996 postEventHeader(&eventBuf, EVENT_TASK_DELETE);
997 /* EVENT_TASK_DELETE (taskID) */
998 postTaskId(&eventBuf, taskId);
999
1000 RELEASE_LOCK(&eventBufMutex);
1001 }
1002
1003 void
1004 postEvent (Capability *cap, EventTypeNum tag)
1005 {
1006 EventsBuf *eb;
1007
1008 eb = &capEventBuf[cap->no];
1009
1010 if (!hasRoomForEvent(eb, tag)) {
1011 // Flush event buffer to make room for new event.
1012 printAndClearEventBuf(eb);
1013 }
1014
1015 postEventHeader(eb, tag);
1016 }
1017
1018 void
1019 postEventAtTimestamp (Capability *cap, EventTimestamp ts, EventTypeNum tag)
1020 {
1021 EventsBuf *eb;
1022
1023 eb = &capEventBuf[cap->no];
1024
1025 if (!hasRoomForEvent(eb, tag)) {
1026 // Flush event buffer to make room for new event.
1027 printAndClearEventBuf(eb);
1028 }
1029
1030 /* Normally we'd call postEventHeader(), but that generates its own
1031 timestamp, so we go one level lower so we can write out
1032 the timestamp we received as an argument. */
1033 postEventTypeNum(eb, tag);
1034 postWord64(eb, ts);
1035 }
1036
1037 #define BUF 512
1038
1039 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
1040 {
1041 char buf[BUF];
1042 nat size;
1043
1044 size = vsnprintf(buf,BUF,msg,ap);
1045 if (size > BUF) {
1046 buf[BUF-1] = '\0';
1047 size = BUF;
1048 }
1049
1050 if (!hasRoomForVariableEvent(eb, size)) {
1051 // Flush event buffer to make room for new event.
1052 printAndClearEventBuf(eb);
1053 }
1054
1055 postEventHeader(eb, type);
1056 postPayloadSize(eb, size);
1057 postBuf(eb,(StgWord8*)buf,size);
1058 }
1059
1060 void postMsg(char *msg, va_list ap)
1061 {
1062 ACQUIRE_LOCK(&eventBufMutex);
1063 postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
1064 RELEASE_LOCK(&eventBufMutex);
1065 }
1066
1067 void postCapMsg(Capability *cap, char *msg, va_list ap)
1068 {
1069 postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap);
1070 }
1071
1072 void postUserMsg(Capability *cap, char *msg, va_list ap)
1073 {
1074 postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, ap);
1075 }
1076
1077 void postEventStartup(EventCapNo n_caps)
1078 {
1079 ACQUIRE_LOCK(&eventBufMutex);
1080
1081 if (!hasRoomForEvent(&eventBuf, EVENT_STARTUP)) {
1082 // Flush event buffer to make room for new event.
1083 printAndClearEventBuf(&eventBuf);
1084 }
1085
1086 // Post a STARTUP event with the number of capabilities
1087 postEventHeader(&eventBuf, EVENT_STARTUP);
1088 postCapNo(&eventBuf, n_caps);
1089
1090 RELEASE_LOCK(&eventBufMutex);
1091 }
1092
1093 void postUserMarker(Capability *cap, char *markername)
1094 {
1095 EventsBuf *eb;
1096 int size = strlen(markername);
1097
1098 eb = &capEventBuf[cap->no];
1099
1100 if (!hasRoomForVariableEvent(eb, size)){
1101 printAndClearEventBuf(eb);
1102
1103 if (!hasRoomForVariableEvent(eb, size)){
1104 // Event size exceeds buffer size, bail out:
1105 return;
1106 }
1107 }
1108
1109 postEventHeader(eb, EVENT_USER_MARKER);
1110 postPayloadSize(eb, size);
1111 postBuf(eb, (StgWord8*) markername, size);
1112 }
1113
1114 void postThreadLabel(Capability *cap,
1115 EventThreadID id,
1116 char *label)
1117 {
1118 EventsBuf *eb;
1119 int strsize = strlen(label);
1120 int size = strsize + sizeof(EventThreadID);
1121
1122 eb = &capEventBuf[cap->no];
1123
1124 if (!hasRoomForVariableEvent(eb, size)){
1125 printAndClearEventBuf(eb);
1126
1127 if (!hasRoomForVariableEvent(eb, size)){
1128 // Event size exceeds buffer size, bail out:
1129 return;
1130 }
1131 }
1132
1133 postEventHeader(eb, EVENT_THREAD_LABEL);
1134 postPayloadSize(eb, size);
1135 postThreadID(eb, id);
1136 postBuf(eb, (StgWord8*) label, strsize);
1137 }
1138
1139 void closeBlockMarker (EventsBuf *ebuf)
1140 {
1141 StgInt8* save_pos;
1142
1143 if (ebuf->marker)
1144 {
1145 // (type:16, time:64, size:32, end_time:64)
1146
1147 save_pos = ebuf->pos;
1148 ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
1149 sizeof(EventTimestamp);
1150 postWord32(ebuf, save_pos - ebuf->marker);
1151 postTimestamp(ebuf);
1152 ebuf->pos = save_pos;
1153 ebuf->marker = NULL;
1154 }
1155 }
1156
1157
1158 void postBlockMarker (EventsBuf *eb)
1159 {
1160 if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
1161 printAndClearEventBuf(eb);
1162 }
1163
1164 closeBlockMarker(eb);
1165
1166 eb->marker = eb->pos;
1167 postEventHeader(eb, EVENT_BLOCK_MARKER);
1168 postWord32(eb,0); // these get filled in later by closeBlockMarker();
1169 postWord64(eb,0);
1170 postCapNo(eb, eb->capno);
1171 }
1172
1173 void printAndClearEventBuf (EventsBuf *ebuf)
1174 {
1175 StgWord64 numBytes = 0, written = 0;
1176
1177 closeBlockMarker(ebuf);
1178
1179 if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
1180 {
1181 numBytes = ebuf->pos - ebuf->begin;
1182
1183 written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
1184 if (written != numBytes) {
1185 debugBelch(
1186 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
1187 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
1188 return;
1189 }
1190
1191 resetEventsBuf(ebuf);
1192 flushCount++;
1193
1194 postBlockMarker(ebuf);
1195 }
1196 }
1197
1198 void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
1199 {
1200 eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
1201 eb->size = size;
1202 eb->marker = NULL;
1203 eb->capno = capno;
1204 }
1205
1206 void resetEventsBuf(EventsBuf* eb)
1207 {
1208 eb->pos = eb->begin;
1209 eb->marker = NULL;
1210 }
1211
1212 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
1213 {
1214 nat size;
1215
1216 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
1217
1218 if (eb->pos + size > eb->begin + eb->size) {
1219 return 0; // Not enough space.
1220 } else {
1221 return 1; // Buf has enough space for the event.
1222 }
1223 }
1224
1225 StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
1226 {
1227 nat size;
1228
1229 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
1230 sizeof(EventPayloadSize) + payload_bytes;
1231
1232 if (eb->pos + size > eb->begin + eb->size) {
1233 return 0; // Not enough space.
1234 } else {
1235 return 1; // Buf has enough space for the event.
1236 }
1237 }
1238
1239 void postEventType(EventsBuf *eb, EventType *et)
1240 {
1241 StgWord8 d;
1242 nat desclen;
1243
1244 postInt32(eb, EVENT_ET_BEGIN);
1245 postEventTypeNum(eb, et->etNum);
1246 postWord16(eb, (StgWord16)et->size);
1247 desclen = strlen(et->desc);
1248 postWord32(eb, desclen);
1249 for (d = 0; d < desclen; ++d) {
1250 postInt8(eb, (StgInt8)et->desc[d]);
1251 }
1252 postWord32(eb, 0); // no extensions yet
1253 postInt32(eb, EVENT_ET_END);
1254 }
1255
1256 #endif /* TRACING */