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