Trac #9384: fix increasing capabilites number for eventlog.
[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 // The from == 0 already covered in initEventLogging, so we are interested
505 // only in case when we are increasing capabilities number
506 if (from > 0) {
507 for (c = from; c < to; ++c) {
508 postBlockMarker(&capEventBuf[c]);
509 }
510 }
511
512 }
513
514
515 void
516 freeEventLogging(void)
517 {
518 StgWord8 c;
519
520 // Free events buffer.
521 for (c = 0; c < n_capabilities; ++c) {
522 if (capEventBuf[c].begin != NULL)
523 stgFree(capEventBuf[c].begin);
524 }
525 if (capEventBuf != NULL) {
526 stgFree(capEventBuf);
527 }
528 if (event_log_filename != NULL) {
529 stgFree(event_log_filename);
530 }
531 }
532
533 void
534 flushEventLog(void)
535 {
536 if (event_log_file != NULL) {
537 fflush(event_log_file);
538 }
539 }
540
541 void
542 abortEventLogging(void)
543 {
544 freeEventLogging();
545 if (event_log_file != NULL) {
546 fclose(event_log_file);
547 }
548 }
549 /*
550 * Post an event message to the capability's eventlog buffer.
551 * If the buffer is full, prints out the buffer and clears it.
552 */
553 void
554 postSchedEvent (Capability *cap,
555 EventTypeNum tag,
556 StgThreadID thread,
557 StgWord info1,
558 StgWord info2)
559 {
560 EventsBuf *eb;
561
562 eb = &capEventBuf[cap->no];
563
564 if (!hasRoomForEvent(eb, tag)) {
565 // Flush event buffer to make room for new event.
566 printAndClearEventBuf(eb);
567 }
568
569 postEventHeader(eb, tag);
570
571 switch (tag) {
572 case EVENT_CREATE_THREAD: // (cap, thread)
573 case EVENT_RUN_THREAD: // (cap, thread)
574 case EVENT_THREAD_RUNNABLE: // (cap, thread)
575 {
576 postThreadID(eb,thread);
577 break;
578 }
579
580 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
581 {
582 postThreadID(eb,info1 /* spark_thread */);
583 break;
584 }
585
586 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
587 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
588 {
589 postThreadID(eb,thread);
590 postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */);
591 break;
592 }
593
594 case EVENT_STOP_THREAD: // (cap, thread, status)
595 {
596 postThreadID(eb,thread);
597 postWord16(eb,info1 /* status */);
598 postThreadID(eb,info2 /* blocked on thread */);
599 break;
600 }
601
602 default:
603 barf("postSchedEvent: unknown event tag %d", tag);
604 }
605 }
606
607 void
608 postSparkEvent (Capability *cap,
609 EventTypeNum tag,
610 StgWord info1)
611 {
612 EventsBuf *eb;
613
614 eb = &capEventBuf[cap->no];
615
616 if (!hasRoomForEvent(eb, tag)) {
617 // Flush event buffer to make room for new event.
618 printAndClearEventBuf(eb);
619 }
620
621 postEventHeader(eb, tag);
622
623 switch (tag) {
624 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
625 {
626 postThreadID(eb,info1 /* spark_thread */);
627 break;
628 }
629
630 case EVENT_SPARK_STEAL: // (cap, victim_cap)
631 {
632 postCapNo(eb,info1 /* victim_cap */);
633 break;
634 }
635
636 case EVENT_SPARK_CREATE: // (cap)
637 case EVENT_SPARK_DUD: // (cap)
638 case EVENT_SPARK_OVERFLOW: // (cap)
639 case EVENT_SPARK_RUN: // (cap)
640 case EVENT_SPARK_FIZZLE: // (cap)
641 case EVENT_SPARK_GC: // (cap)
642 {
643 break;
644 }
645
646 default:
647 barf("postSparkEvent: unknown event tag %d", tag);
648 }
649 }
650
651 void
652 postSparkCountersEvent (Capability *cap,
653 SparkCounters counters,
654 StgWord remaining)
655 {
656 EventsBuf *eb;
657
658 eb = &capEventBuf[cap->no];
659
660 if (!hasRoomForEvent(eb, EVENT_SPARK_COUNTERS)) {
661 // Flush event buffer to make room for new event.
662 printAndClearEventBuf(eb);
663 }
664
665 postEventHeader(eb, EVENT_SPARK_COUNTERS);
666 /* EVENT_SPARK_COUNTERS (crt,dud,ovf,cnv,gcd,fiz,rem) */
667 postWord64(eb,counters.created);
668 postWord64(eb,counters.dud);
669 postWord64(eb,counters.overflowed);
670 postWord64(eb,counters.converted);
671 postWord64(eb,counters.gcd);
672 postWord64(eb,counters.fizzled);
673 postWord64(eb,remaining);
674 }
675
676 void
677 postCapEvent (EventTypeNum tag,
678 EventCapNo capno)
679 {
680 ACQUIRE_LOCK(&eventBufMutex);
681
682 if (!hasRoomForEvent(&eventBuf, tag)) {
683 // Flush event buffer to make room for new event.
684 printAndClearEventBuf(&eventBuf);
685 }
686
687 postEventHeader(&eventBuf, tag);
688
689 switch (tag) {
690 case EVENT_CAP_CREATE: // (cap)
691 case EVENT_CAP_DELETE: // (cap)
692 case EVENT_CAP_ENABLE: // (cap)
693 case EVENT_CAP_DISABLE: // (cap)
694 {
695 postCapNo(&eventBuf,capno);
696 break;
697 }
698
699 default:
700 barf("postCapEvent: unknown event tag %d", tag);
701 }
702
703 RELEASE_LOCK(&eventBufMutex);
704 }
705
706 void postCapsetEvent (EventTypeNum tag,
707 EventCapsetID capset,
708 StgWord info)
709 {
710 ACQUIRE_LOCK(&eventBufMutex);
711
712 if (!hasRoomForEvent(&eventBuf, tag)) {
713 // Flush event buffer to make room for new event.
714 printAndClearEventBuf(&eventBuf);
715 }
716
717 postEventHeader(&eventBuf, tag);
718 postCapsetID(&eventBuf, capset);
719
720 switch (tag) {
721 case EVENT_CAPSET_CREATE: // (capset, capset_type)
722 {
723 postCapsetType(&eventBuf, info /* capset_type */);
724 break;
725 }
726
727 case EVENT_CAPSET_DELETE: // (capset)
728 {
729 break;
730 }
731
732 case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno)
733 case EVENT_CAPSET_REMOVE_CAP: // (capset, capno)
734 {
735 postCapNo(&eventBuf, info /* capno */);
736 break;
737 }
738 case EVENT_OSPROCESS_PID: // (capset, pid)
739 case EVENT_OSPROCESS_PPID: // (capset, parent_pid)
740 {
741 postOSProcessId(&eventBuf, info);
742 break;
743 }
744 default:
745 barf("postCapsetEvent: unknown event tag %d", tag);
746 }
747
748 RELEASE_LOCK(&eventBufMutex);
749 }
750
751 void postCapsetStrEvent (EventTypeNum tag,
752 EventCapsetID capset,
753 char *msg)
754 {
755 int strsize = strlen(msg);
756 int size = strsize + sizeof(EventCapsetID);
757
758 ACQUIRE_LOCK(&eventBufMutex);
759
760 if (!hasRoomForVariableEvent(&eventBuf, size)){
761 printAndClearEventBuf(&eventBuf);
762
763 if (!hasRoomForVariableEvent(&eventBuf, size)){
764 // Event size exceeds buffer size, bail out:
765 RELEASE_LOCK(&eventBufMutex);
766 return;
767 }
768 }
769
770 postEventHeader(&eventBuf, tag);
771 postPayloadSize(&eventBuf, size);
772 postCapsetID(&eventBuf, capset);
773
774 postBuf(&eventBuf, (StgWord8*) msg, strsize);
775
776 RELEASE_LOCK(&eventBufMutex);
777 }
778
779 void postCapsetVecEvent (EventTypeNum tag,
780 EventCapsetID capset,
781 int argc,
782 char *argv[])
783 {
784 int i, size = sizeof(EventCapsetID);
785
786 for (i = 0; i < argc; i++) {
787 // 1 + strlen to account for the trailing \0, used as separator
788 size += 1 + strlen(argv[i]);
789 }
790
791 ACQUIRE_LOCK(&eventBufMutex);
792
793 if (!hasRoomForVariableEvent(&eventBuf, size)){
794 printAndClearEventBuf(&eventBuf);
795
796 if(!hasRoomForVariableEvent(&eventBuf, size)){
797 // Event size exceeds buffer size, bail out:
798 RELEASE_LOCK(&eventBufMutex);
799 return;
800 }
801 }
802
803 postEventHeader(&eventBuf, tag);
804 postPayloadSize(&eventBuf, size);
805 postCapsetID(&eventBuf, capset);
806
807 for( i = 0; i < argc; i++ ) {
808 // again, 1 + to account for \0
809 postBuf(&eventBuf, (StgWord8*) argv[i], 1 + strlen(argv[i]));
810 }
811
812 RELEASE_LOCK(&eventBufMutex);
813 }
814
815 void postWallClockTime (EventCapsetID capset)
816 {
817 StgWord64 ts;
818 StgWord64 sec;
819 StgWord32 nsec;
820
821 ACQUIRE_LOCK(&eventBufMutex);
822
823 /* The EVENT_WALL_CLOCK_TIME event is intended to allow programs
824 reading the eventlog to match up the event timestamps with wall
825 clock time. The normal event timestamps measure time since the
826 start of the program. To align eventlogs from concurrent
827 processes we need to be able to match up the timestamps. One way
828 to do this is if we know how the timestamps and wall clock time
829 match up (and of course if both processes have sufficiently
830 synchronised clocks).
831
832 So we want to make sure that the timestamp that we generate for
833 this event matches up very closely with the wall clock time.
834 Unfortunately we currently have to use two different APIs to get
835 the elapsed time vs the wall clock time. So to minimise the
836 difference we just call them very close together.
837 */
838
839 getUnixEpochTime(&sec, &nsec); /* Get the wall clock time */
840 ts = time_ns(); /* Get the eventlog timestamp */
841
842 if (!hasRoomForEvent(&eventBuf, EVENT_WALL_CLOCK_TIME)) {
843 // Flush event buffer to make room for new event.
844 printAndClearEventBuf(&eventBuf);
845 }
846
847 /* Normally we'd call postEventHeader(), but that generates its own
848 timestamp, so we go one level lower so we can write out the
849 timestamp we already generated above. */
850 postEventTypeNum(&eventBuf, EVENT_WALL_CLOCK_TIME);
851 postWord64(&eventBuf, ts);
852
853 /* EVENT_WALL_CLOCK_TIME (capset, unix_epoch_seconds, nanoseconds) */
854 postCapsetID(&eventBuf, capset);
855 postWord64(&eventBuf, sec);
856 postWord32(&eventBuf, nsec);
857
858 RELEASE_LOCK(&eventBufMutex);
859 }
860
861 /*
862 * Various GC and heap events
863 */
864 void postHeapEvent (Capability *cap,
865 EventTypeNum tag,
866 EventCapsetID heap_capset,
867 W_ info1)
868 {
869 EventsBuf *eb;
870
871 eb = &capEventBuf[cap->no];
872
873 if (!hasRoomForEvent(eb, tag)) {
874 // Flush event buffer to make room for new event.
875 printAndClearEventBuf(eb);
876 }
877
878 postEventHeader(eb, tag);
879
880 switch (tag) {
881 case EVENT_HEAP_ALLOCATED: // (heap_capset, alloc_bytes)
882 case EVENT_HEAP_SIZE: // (heap_capset, size_bytes)
883 case EVENT_HEAP_LIVE: // (heap_capset, live_bytes)
884 {
885 postCapsetID(eb, heap_capset);
886 postWord64(eb, info1 /* alloc/size/live_bytes */);
887 break;
888 }
889
890 default:
891 barf("postHeapEvent: unknown event tag %d", tag);
892 }
893 }
894
895 void postEventHeapInfo (EventCapsetID heap_capset,
896 nat gens,
897 W_ maxHeapSize,
898 W_ allocAreaSize,
899 W_ mblockSize,
900 W_ blockSize)
901 {
902 ACQUIRE_LOCK(&eventBufMutex);
903
904 if (!hasRoomForEvent(&eventBuf, EVENT_HEAP_INFO_GHC)) {
905 // Flush event buffer to make room for new event.
906 printAndClearEventBuf(&eventBuf);
907 }
908
909 postEventHeader(&eventBuf, EVENT_HEAP_INFO_GHC);
910 /* EVENT_HEAP_INFO_GHC (heap_capset, n_generations,
911 max_heap_size, alloc_area_size,
912 mblock_size, block_size) */
913 postCapsetID(&eventBuf, heap_capset);
914 postWord16(&eventBuf, gens);
915 postWord64(&eventBuf, maxHeapSize);
916 postWord64(&eventBuf, allocAreaSize);
917 postWord64(&eventBuf, mblockSize);
918 postWord64(&eventBuf, blockSize);
919
920 RELEASE_LOCK(&eventBufMutex);
921 }
922
923 void postEventGcStats (Capability *cap,
924 EventCapsetID heap_capset,
925 nat gen,
926 W_ copied,
927 W_ slop,
928 W_ fragmentation,
929 nat par_n_threads,
930 W_ par_max_copied,
931 W_ par_tot_copied)
932 {
933 EventsBuf *eb;
934
935 eb = &capEventBuf[cap->no];
936
937 if (!hasRoomForEvent(eb, EVENT_GC_STATS_GHC)) {
938 // Flush event buffer to make room for new event.
939 printAndClearEventBuf(eb);
940 }
941
942 postEventHeader(eb, EVENT_GC_STATS_GHC);
943 /* EVENT_GC_STATS_GHC (heap_capset, generation,
944 copied_bytes, slop_bytes, frag_bytes,
945 par_n_threads, par_max_copied, par_tot_copied) */
946 postCapsetID(eb, heap_capset);
947 postWord16(eb, gen);
948 postWord64(eb, copied);
949 postWord64(eb, slop);
950 postWord64(eb, fragmentation);
951 postWord32(eb, par_n_threads);
952 postWord64(eb, par_max_copied);
953 postWord64(eb, par_tot_copied);
954 }
955
956 void postTaskCreateEvent (EventTaskId taskId,
957 EventCapNo capno,
958 EventKernelThreadId tid)
959 {
960 ACQUIRE_LOCK(&eventBufMutex);
961
962 if (!hasRoomForEvent(&eventBuf, EVENT_TASK_CREATE)) {
963 // Flush event buffer to make room for new event.
964 printAndClearEventBuf(&eventBuf);
965 }
966
967 postEventHeader(&eventBuf, EVENT_TASK_CREATE);
968 /* EVENT_TASK_CREATE (taskID, cap, tid) */
969 postTaskId(&eventBuf, taskId);
970 postCapNo(&eventBuf, capno);
971 postKernelThreadId(&eventBuf, tid);
972
973 RELEASE_LOCK(&eventBufMutex);
974 }
975
976 void postTaskMigrateEvent (EventTaskId taskId,
977 EventCapNo capno,
978 EventCapNo new_capno)
979 {
980 ACQUIRE_LOCK(&eventBufMutex);
981
982 if (!hasRoomForEvent(&eventBuf, EVENT_TASK_MIGRATE)) {
983 // Flush event buffer to make room for new event.
984 printAndClearEventBuf(&eventBuf);
985 }
986
987 postEventHeader(&eventBuf, EVENT_TASK_MIGRATE);
988 /* EVENT_TASK_MIGRATE (taskID, cap, new_cap) */
989 postTaskId(&eventBuf, taskId);
990 postCapNo(&eventBuf, capno);
991 postCapNo(&eventBuf, new_capno);
992
993 RELEASE_LOCK(&eventBufMutex);
994 }
995
996 void postTaskDeleteEvent (EventTaskId taskId)
997 {
998 ACQUIRE_LOCK(&eventBufMutex);
999
1000 if (!hasRoomForEvent(&eventBuf, EVENT_TASK_DELETE)) {
1001 // Flush event buffer to make room for new event.
1002 printAndClearEventBuf(&eventBuf);
1003 }
1004
1005 postEventHeader(&eventBuf, EVENT_TASK_DELETE);
1006 /* EVENT_TASK_DELETE (taskID) */
1007 postTaskId(&eventBuf, taskId);
1008
1009 RELEASE_LOCK(&eventBufMutex);
1010 }
1011
1012 void
1013 postEvent (Capability *cap, EventTypeNum tag)
1014 {
1015 EventsBuf *eb;
1016
1017 eb = &capEventBuf[cap->no];
1018
1019 if (!hasRoomForEvent(eb, tag)) {
1020 // Flush event buffer to make room for new event.
1021 printAndClearEventBuf(eb);
1022 }
1023
1024 postEventHeader(eb, tag);
1025 }
1026
1027 void
1028 postEventAtTimestamp (Capability *cap, EventTimestamp ts, EventTypeNum tag)
1029 {
1030 EventsBuf *eb;
1031
1032 eb = &capEventBuf[cap->no];
1033
1034 if (!hasRoomForEvent(eb, tag)) {
1035 // Flush event buffer to make room for new event.
1036 printAndClearEventBuf(eb);
1037 }
1038
1039 /* Normally we'd call postEventHeader(), but that generates its own
1040 timestamp, so we go one level lower so we can write out
1041 the timestamp we received as an argument. */
1042 postEventTypeNum(eb, tag);
1043 postWord64(eb, ts);
1044 }
1045
1046 #define BUF 512
1047
1048 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
1049 {
1050 char buf[BUF];
1051 nat size;
1052
1053 size = vsnprintf(buf,BUF,msg,ap);
1054 if (size > BUF) {
1055 buf[BUF-1] = '\0';
1056 size = BUF;
1057 }
1058
1059 if (!hasRoomForVariableEvent(eb, size)) {
1060 // Flush event buffer to make room for new event.
1061 printAndClearEventBuf(eb);
1062 }
1063
1064 postEventHeader(eb, type);
1065 postPayloadSize(eb, size);
1066 postBuf(eb,(StgWord8*)buf,size);
1067 }
1068
1069 void postMsg(char *msg, va_list ap)
1070 {
1071 ACQUIRE_LOCK(&eventBufMutex);
1072 postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
1073 RELEASE_LOCK(&eventBufMutex);
1074 }
1075
1076 void postCapMsg(Capability *cap, char *msg, va_list ap)
1077 {
1078 postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap);
1079 }
1080
1081 void postUserMsg(Capability *cap, char *msg, va_list ap)
1082 {
1083 postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, ap);
1084 }
1085
1086 void postEventStartup(EventCapNo n_caps)
1087 {
1088 ACQUIRE_LOCK(&eventBufMutex);
1089
1090 if (!hasRoomForEvent(&eventBuf, EVENT_STARTUP)) {
1091 // Flush event buffer to make room for new event.
1092 printAndClearEventBuf(&eventBuf);
1093 }
1094
1095 // Post a STARTUP event with the number of capabilities
1096 postEventHeader(&eventBuf, EVENT_STARTUP);
1097 postCapNo(&eventBuf, n_caps);
1098
1099 RELEASE_LOCK(&eventBufMutex);
1100 }
1101
1102 void postUserMarker(Capability *cap, char *markername)
1103 {
1104 EventsBuf *eb;
1105 int size = strlen(markername);
1106
1107 eb = &capEventBuf[cap->no];
1108
1109 if (!hasRoomForVariableEvent(eb, size)){
1110 printAndClearEventBuf(eb);
1111
1112 if (!hasRoomForVariableEvent(eb, size)){
1113 // Event size exceeds buffer size, bail out:
1114 return;
1115 }
1116 }
1117
1118 postEventHeader(eb, EVENT_USER_MARKER);
1119 postPayloadSize(eb, size);
1120 postBuf(eb, (StgWord8*) markername, size);
1121 }
1122
1123 void postThreadLabel(Capability *cap,
1124 EventThreadID id,
1125 char *label)
1126 {
1127 EventsBuf *eb;
1128 int strsize = strlen(label);
1129 int size = strsize + sizeof(EventThreadID);
1130
1131 eb = &capEventBuf[cap->no];
1132
1133 if (!hasRoomForVariableEvent(eb, size)){
1134 printAndClearEventBuf(eb);
1135
1136 if (!hasRoomForVariableEvent(eb, size)){
1137 // Event size exceeds buffer size, bail out:
1138 return;
1139 }
1140 }
1141
1142 postEventHeader(eb, EVENT_THREAD_LABEL);
1143 postPayloadSize(eb, size);
1144 postThreadID(eb, id);
1145 postBuf(eb, (StgWord8*) label, strsize);
1146 }
1147
1148 void closeBlockMarker (EventsBuf *ebuf)
1149 {
1150 StgInt8* save_pos;
1151
1152 if (ebuf->marker)
1153 {
1154 // (type:16, time:64, size:32, end_time:64)
1155
1156 save_pos = ebuf->pos;
1157 ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
1158 sizeof(EventTimestamp);
1159 postWord32(ebuf, save_pos - ebuf->marker);
1160 postTimestamp(ebuf);
1161 ebuf->pos = save_pos;
1162 ebuf->marker = NULL;
1163 }
1164 }
1165
1166
1167 void postBlockMarker (EventsBuf *eb)
1168 {
1169 if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
1170 printAndClearEventBuf(eb);
1171 }
1172
1173 closeBlockMarker(eb);
1174
1175 eb->marker = eb->pos;
1176 postEventHeader(eb, EVENT_BLOCK_MARKER);
1177 postWord32(eb,0); // these get filled in later by closeBlockMarker();
1178 postWord64(eb,0);
1179 postCapNo(eb, eb->capno);
1180 }
1181
1182 void printAndClearEventBuf (EventsBuf *ebuf)
1183 {
1184 StgWord64 numBytes = 0, written = 0;
1185
1186 closeBlockMarker(ebuf);
1187
1188 if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
1189 {
1190 numBytes = ebuf->pos - ebuf->begin;
1191
1192 written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
1193 if (written != numBytes) {
1194 debugBelch(
1195 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
1196 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
1197 return;
1198 }
1199
1200 resetEventsBuf(ebuf);
1201 flushCount++;
1202
1203 postBlockMarker(ebuf);
1204 }
1205 }
1206
1207 void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
1208 {
1209 eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
1210 eb->size = size;
1211 eb->marker = NULL;
1212 eb->capno = capno;
1213 }
1214
1215 void resetEventsBuf(EventsBuf* eb)
1216 {
1217 eb->pos = eb->begin;
1218 eb->marker = NULL;
1219 }
1220
1221 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
1222 {
1223 nat size;
1224
1225 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
1226
1227 if (eb->pos + size > eb->begin + eb->size) {
1228 return 0; // Not enough space.
1229 } else {
1230 return 1; // Buf has enough space for the event.
1231 }
1232 }
1233
1234 StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
1235 {
1236 nat size;
1237
1238 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
1239 sizeof(EventPayloadSize) + payload_bytes;
1240
1241 if (eb->pos + size > eb->begin + eb->size) {
1242 return 0; // Not enough space.
1243 } else {
1244 return 1; // Buf has enough space for the event.
1245 }
1246 }
1247
1248 void postEventType(EventsBuf *eb, EventType *et)
1249 {
1250 StgWord8 d;
1251 nat desclen;
1252
1253 postInt32(eb, EVENT_ET_BEGIN);
1254 postEventTypeNum(eb, et->etNum);
1255 postWord16(eb, (StgWord16)et->size);
1256 desclen = strlen(et->desc);
1257 postWord32(eb, desclen);
1258 for (d = 0; d < desclen; ++d) {
1259 postInt8(eb, (StgInt8)et->desc[d]);
1260 }
1261 postWord32(eb, 0); // no extensions yet
1262 postInt32(eb, EVENT_ET_END);
1263 }
1264
1265 #endif /* TRACING */