1 /* -----------------------------------------------------------------------------
3 * (c) The GHC Team, 2008-2009
5 * Support for fast binary event logging.
7 * ---------------------------------------------------------------------------*/
9 #include "PosixSource.h"
15 #include "Capability.h"
22 #ifdef HAVE_SYS_TYPES_H
23 #include <sys/types.h>
29 // PID of the process that writes to event_log_filename (#4512)
30 static pid_t event_log_pid = -1;
32 static char *event_log_filename = NULL;
34 // File for logging events
35 FILE *event_log_file = NULL;
37 #define EVENT_LOG_SIZE 2 * (1024 * 1024) // 2MB
39 static int flushCount;
41 // Struct for record keeping of buffer to store event types and events.
42 typedef struct _EventsBuf {
47 EventCapNo capno; // which capability this buffer belongs to, or -1
50 EventsBuf *capEventBuf; // one EventsBuf for each Capability
52 EventsBuf eventBuf; // an EventsBuf not associated with any Capability
54 Mutex eventBufMutex; // protected by this mutex
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_RUN_SPARK] = "Run spark",
64 [EVENT_STEAL_SPARK] = "Steal spark",
65 [EVENT_SHUTDOWN] = "Shutdown",
66 [EVENT_THREAD_WAKEUP] = "Wakeup thread",
67 [EVENT_GC_START] = "Starting GC",
68 [EVENT_GC_END] = "Finished GC",
69 [EVENT_REQUEST_SEQ_GC] = "Request sequential GC",
70 [EVENT_REQUEST_PAR_GC] = "Request parallel GC",
71 [EVENT_CREATE_SPARK_THREAD] = "Create spark thread",
72 [EVENT_LOG_MSG] = "Log message",
73 [EVENT_USER_MSG] = "User message",
74 [EVENT_STARTUP] = "Startup",
75 [EVENT_GC_IDLE] = "GC idle",
76 [EVENT_GC_WORK] = "GC working",
77 [EVENT_GC_DONE] = "GC done",
78 [EVENT_BLOCK_MARKER] = "Block marker",
79 [EVENT_CAPSET_CREATE] = "Create capability set",
80 [EVENT_CAPSET_DELETE] = "Delete capability set",
81 [EVENT_CAPSET_ASSIGN_CAP] = "Add capability to capability set",
82 [EVENT_CAPSET_REMOVE_CAP] = "Remove capability from capability set",
83 [EVENT_RTS_IDENTIFIER] = "Identify the RTS version",
84 [EVENT_PROGRAM_ARGS] = "Identify the program arguments",
85 [EVENT_PROGRAM_ENV] = "Identify the environment variables",
86 [EVENT_OSPROCESS_PID] = "Identify the process ID of a capability set"
91 typedef struct _EventType {
92 EventTypeNum etNum; // Event Type number.
93 nat size; // size of the payload in bytes
94 char *desc; // Description
97 EventType eventTypes[NUM_EVENT_TAGS];
99 static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
100 static void resetEventsBuf(EventsBuf* eb);
101 static void printAndClearEventBuf (EventsBuf *eventsBuf);
103 static void postEventType(EventsBuf *eb, EventType *et);
105 static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap);
107 static void postBlockMarker(EventsBuf *eb);
108 static void closeBlockMarker(EventsBuf *ebuf);
110 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
111 static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);
113 static inline void postWord8(EventsBuf *eb, StgWord8 i)
118 static inline void postWord16(EventsBuf *eb, StgWord16 i)
120 postWord8(eb, (StgWord8)(i >> 8));
121 postWord8(eb, (StgWord8)i);
124 static inline void postWord32(EventsBuf *eb, StgWord32 i)
126 postWord16(eb, (StgWord16)(i >> 16));
127 postWord16(eb, (StgWord16)i);
130 static inline void postWord64(EventsBuf *eb, StgWord64 i)
132 postWord32(eb, (StgWord32)(i >> 32));
133 postWord32(eb, (StgWord32)i);
136 static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
138 memcpy(eb->pos, buf, size);
142 static inline StgWord64 time_ns(void)
143 { return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); }
145 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
146 { postWord16(eb, etNum); }
148 static inline void postTimestamp(EventsBuf *eb)
149 { postWord64(eb, time_ns()); }
151 static inline void postThreadID(EventsBuf *eb, EventThreadID id)
152 { postWord32(eb,id); }
154 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
155 { postWord16(eb,no); }
157 static inline void postCapsetID(EventsBuf *eb, EventCapsetID id)
158 { postWord32(eb,id); }
160 static inline void postCapsetType(EventsBuf *eb, EventCapsetType type)
161 { postWord16(eb,type); }
163 static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
164 { postWord16(eb,size); }
166 static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
168 postEventTypeNum(eb, type);
172 static inline void postInt8(EventsBuf *eb, StgInt8 i)
173 { postWord8(eb, (StgWord8)i); }
175 static inline void postInt16(EventsBuf *eb, StgInt16 i)
176 { postWord16(eb, (StgWord16)i); }
178 static inline void postInt32(EventsBuf *eb, StgInt32 i)
179 { postWord32(eb, (StgWord32)i); }
181 static inline void postInt64(EventsBuf *eb, StgInt64 i)
182 { postWord64(eb, (StgWord64)i); }
186 initEventLogging(void)
191 event_log_filename = stgMallocBytes(strlen(prog_name)
193 + 10 /* .eventlog */,
196 if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
197 barf("EventDesc array has the wrong number of elements");
200 if (event_log_pid == -1) { // #4512
202 sprintf(event_log_filename, "%s.eventlog", prog_name);
203 event_log_pid = getpid();
205 // Forked process, eventlog already started by the parent
207 event_log_pid = getpid();
208 sprintf(event_log_filename, "%s.%d.eventlog", prog_name, event_log_pid);
211 /* Open event log file for writing. */
212 if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
213 sysErrorBelch("initEventLogging: can't open %s", event_log_filename);
214 stg_exit(EXIT_FAILURE);
218 * Allocate buffer(s) to store events.
219 * Create buffer large enough for the header begin marker, all event
220 * types, and header end marker to prevent checking if buffer has room
221 * for each of these steps, and remove the need to flush the buffer to
222 * disk during initialization.
224 * Use a single buffer to store the header with event types, then flush
225 * the buffer so all buffers are empty for writing events.
228 // XXX n_capabilities hasn't been initislised yet
229 n_caps = RtsFlags.ParFlags.nNodes;
233 capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging");
235 for (c = 0; c < n_caps; ++c) {
236 // Init buffer for events.
237 initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
239 initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
241 // Write in buffer: the header begin marker.
242 postInt32(&eventBuf, EVENT_HEADER_BEGIN);
244 // Mark beginning of event types in the header.
245 postInt32(&eventBuf, EVENT_HET_BEGIN);
246 for (t = 0; t < NUM_EVENT_TAGS; ++t) {
248 eventTypes[t].etNum = t;
249 eventTypes[t].desc = EventDesc[t];
252 case EVENT_CREATE_THREAD: // (cap, thread)
253 case EVENT_RUN_THREAD: // (cap, thread)
254 case EVENT_THREAD_RUNNABLE: // (cap, thread)
255 case EVENT_RUN_SPARK: // (cap, thread)
256 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
257 eventTypes[t].size = sizeof(EventThreadID);
260 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
261 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
262 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
264 sizeof(EventThreadID) + sizeof(EventCapNo);
267 case EVENT_STOP_THREAD: // (cap, thread, status)
269 sizeof(EventThreadID) + sizeof(StgWord16) + sizeof(EventThreadID);
272 case EVENT_STARTUP: // (cap count)
273 eventTypes[t].size = sizeof(EventCapNo);
276 case EVENT_CAPSET_CREATE: // (capset, capset_type)
278 sizeof(EventCapsetID) + sizeof(EventCapsetType);
281 case EVENT_CAPSET_DELETE: // (capset)
282 eventTypes[t].size = sizeof(EventCapsetID);
285 case EVENT_CAPSET_ASSIGN_CAP: // (capset, cap)
286 case EVENT_CAPSET_REMOVE_CAP:
288 sizeof(EventCapsetID) + sizeof(EventCapNo);
291 case EVENT_OSPROCESS_PID: // (cap, pid, parent pid)
293 sizeof(EventCapsetID) + 2*sizeof(StgWord32);
296 case EVENT_SHUTDOWN: // (cap)
297 case EVENT_REQUEST_SEQ_GC: // (cap)
298 case EVENT_REQUEST_PAR_GC: // (cap)
299 case EVENT_GC_START: // (cap)
300 case EVENT_GC_END: // (cap)
304 eventTypes[t].size = 0;
307 case EVENT_LOG_MSG: // (msg)
308 case EVENT_USER_MSG: // (msg)
309 case EVENT_RTS_IDENTIFIER: // (capset, str)
310 case EVENT_PROGRAM_ARGS: // (capset, strvec)
311 case EVENT_PROGRAM_ENV: // (capset, strvec)
312 eventTypes[t].size = 0xffff;
315 case EVENT_BLOCK_MARKER:
316 eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) +
321 continue; /* ignore deprecated events */
324 // Write in buffer: the start event type.
325 postEventType(&eventBuf, &eventTypes[t]);
328 // Mark end of event types in the header.
329 postInt32(&eventBuf, EVENT_HET_END);
331 // Write in buffer: the header end marker.
332 postInt32(&eventBuf, EVENT_HEADER_END);
334 // Prepare event buffer for events (data).
335 postInt32(&eventBuf, EVENT_DATA_BEGIN);
337 // Post a STARTUP event with the number of capabilities
338 postEventHeader(&eventBuf, EVENT_STARTUP);
339 postCapNo(&eventBuf, n_caps);
341 // Flush capEventBuf with header.
343 * Flush header and data begin marker to the file, thus preparing the
344 * file to have events written to it.
346 printAndClearEventBuf(&eventBuf);
348 for (c = 0; c < n_caps; ++c) {
349 postBlockMarker(&capEventBuf[c]);
353 initMutex(&eventBufMutex);
358 endEventLogging(void)
362 // Flush all events remaining in the buffers.
363 for (c = 0; c < n_capabilities; ++c) {
364 printAndClearEventBuf(&capEventBuf[c]);
366 printAndClearEventBuf(&eventBuf);
367 resetEventsBuf(&eventBuf); // we don't want the block marker
369 // Mark end of events (data).
370 postEventTypeNum(&eventBuf, EVENT_DATA_END);
372 // Flush the end of data marker.
373 printAndClearEventBuf(&eventBuf);
375 if (event_log_file != NULL) {
376 fclose(event_log_file);
381 freeEventLogging(void)
385 // Free events buffer.
386 for (c = 0; c < n_capabilities; ++c) {
387 if (capEventBuf[c].begin != NULL)
388 stgFree(capEventBuf[c].begin);
390 if (capEventBuf != NULL) {
391 stgFree(capEventBuf);
393 if (event_log_filename != NULL) {
394 stgFree(event_log_filename);
401 if (event_log_file != NULL) {
402 fflush(event_log_file);
407 abortEventLogging(void)
410 if (event_log_file != NULL) {
411 fclose(event_log_file);
415 * Post an event message to the capability's eventlog buffer.
416 * If the buffer is full, prints out the buffer and clears it.
419 postSchedEvent (Capability *cap,
427 eb = &capEventBuf[cap->no];
429 if (!hasRoomForEvent(eb, tag)) {
430 // Flush event buffer to make room for new event.
431 printAndClearEventBuf(eb);
434 postEventHeader(eb, tag);
437 case EVENT_CREATE_THREAD: // (cap, thread)
438 case EVENT_RUN_THREAD: // (cap, thread)
439 case EVENT_THREAD_RUNNABLE: // (cap, thread)
440 case EVENT_RUN_SPARK: // (cap, thread)
442 postThreadID(eb,thread);
446 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
448 postThreadID(eb,info1 /* spark_thread */);
452 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
453 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
454 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
456 postThreadID(eb,thread);
457 postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */);
461 case EVENT_STOP_THREAD: // (cap, thread, status)
463 postThreadID(eb,thread);
464 postWord16(eb,info1 /* status */);
465 postThreadID(eb,info2 /* blocked on thread */);
469 case EVENT_SHUTDOWN: // (cap)
470 case EVENT_REQUEST_SEQ_GC: // (cap)
471 case EVENT_REQUEST_PAR_GC: // (cap)
472 case EVENT_GC_START: // (cap)
473 case EVENT_GC_END: // (cap)
479 barf("postEvent: unknown event tag %d", tag);
483 void postCapsetModifyEvent (EventTypeNum tag,
484 EventCapsetID capset,
488 ACQUIRE_LOCK(&eventBufMutex);
490 if (!hasRoomForEvent(&eventBuf, tag)) {
491 // Flush event buffer to make room for new event.
492 printAndClearEventBuf(&eventBuf);
495 postEventHeader(&eventBuf, tag);
496 postCapsetID(&eventBuf, capset);
499 case EVENT_CAPSET_CREATE: // (capset, capset_type)
501 postCapsetType(&eventBuf, other /* capset_type */);
505 case EVENT_CAPSET_DELETE: // (capset)
510 case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno)
511 case EVENT_CAPSET_REMOVE_CAP: // (capset, capno)
513 postCapNo(&eventBuf, other /* capno */);
516 case EVENT_OSPROCESS_PID:
518 postWord32(&eventBuf, other);
519 postWord32(&eventBuf, other2);
523 barf("postCapsetModifyEvent: unknown event tag %d", tag);
526 RELEASE_LOCK(&eventBufMutex);
529 void postCapsetStrEvent (EventTypeNum tag,
530 EventCapsetID capset,
533 int strsize = strlen(msg);
534 int size = strsize + sizeof(EventCapsetID)
536 ACQUIRE_LOCK(&eventBufMutex);
538 if (!hasRoomForVariableEvent(&eventBuf, size)){
539 printAndClearEventBuf(&eventBuf);
541 if (!hasRoomForVariableEvent(&eventBuf, size)){
542 // Event size exceeds buffer size, bail out:
543 RELEASE_LOCK(&eventBufMutex);
548 postEventHeader(&eventBuf, tag);
549 postPayloadSize(&eventBuf, size);
550 postCapsetID(&eventBuf, capset);
552 postBuf(&eventBuf, (StgWord8*) msg, strsize);
554 RELEASE_LOCK(&eventBufMutex);
557 void postCapsetVecEvent (EventTypeNum tag,
558 EventCapsetID capset,
562 int i, size = sizeof(EventCapsetID);
564 for (i = 0; i < argc; i++) {
565 // 1 + strlen to account for the trailing \0, used as separator
566 size += 1 + strlen(argv[i]);
569 ACQUIRE_LOCK(&eventBufMutex);
571 if (!hasRoomForVariableEvent(&eventBuf, size)){
572 printAndClearEventBuf(&eventBuf);
574 if(!hasRoomForVariableEvent(&eventBuf, size)){
575 // Event size exceeds buffer size, bail out:
576 RELEASE_LOCK(&eventBufMutex);
581 postEventHeader(&eventBuf, tag);
582 postPayloadSize(&eventBuf, size);
583 postCapsetID(&eventBuf, capset);
585 for( i = 0; i < argc; i++ ) {
586 // again, 1 + to account for \0
587 postBuf(&eventBuf, (StgWord8*) argv[i], 1 + strlen(argv[i]));
590 RELEASE_LOCK(&eventBufMutex);
594 postEvent (Capability *cap, EventTypeNum tag)
598 eb = &capEventBuf[cap->no];
600 if (!hasRoomForEvent(eb, tag)) {
601 // Flush event buffer to make room for new event.
602 printAndClearEventBuf(eb);
605 postEventHeader(eb, tag);
610 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
615 size = vsnprintf(buf,BUF,msg,ap);
621 if (!hasRoomForVariableEvent(eb, size)) {
622 // Flush event buffer to make room for new event.
623 printAndClearEventBuf(eb);
626 postEventHeader(eb, type);
627 postPayloadSize(eb, size);
628 postBuf(eb,(StgWord8*)buf,size);
631 void postMsg(char *msg, va_list ap)
633 ACQUIRE_LOCK(&eventBufMutex);
634 postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
635 RELEASE_LOCK(&eventBufMutex);
638 void postCapMsg(Capability *cap, char *msg, va_list ap)
640 postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap);
643 void postUserMsg(Capability *cap, char *msg, va_list ap)
645 postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, ap);
648 void closeBlockMarker (EventsBuf *ebuf)
654 // (type:16, time:64, size:32, end_time:64)
656 save_pos = ebuf->pos;
657 ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
658 sizeof(EventTimestamp);
659 postWord32(ebuf, save_pos - ebuf->marker);
661 ebuf->pos = save_pos;
667 void postBlockMarker (EventsBuf *eb)
669 if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
670 printAndClearEventBuf(eb);
673 closeBlockMarker(eb);
675 eb->marker = eb->pos;
676 postEventHeader(eb, EVENT_BLOCK_MARKER);
677 postWord32(eb,0); // these get filled in later by closeBlockMarker();
679 postCapNo(eb, eb->capno);
682 void printAndClearEventBuf (EventsBuf *ebuf)
684 StgWord64 numBytes = 0, written = 0;
686 closeBlockMarker(ebuf);
688 if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
690 numBytes = ebuf->pos - ebuf->begin;
692 written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
693 if (written != numBytes) {
695 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
696 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
700 resetEventsBuf(ebuf);
703 postBlockMarker(ebuf);
707 void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
709 eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
715 void resetEventsBuf(EventsBuf* eb)
721 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
725 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
727 if (eb->pos + size > eb->begin + eb->size) {
728 return 0; // Not enough space.
730 return 1; // Buf has enough space for the event.
734 StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
738 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
739 sizeof(EventPayloadSize) + payload_bytes;
741 if (eb->pos + size > eb->begin + eb->size) {
742 return 0; // Not enough space.
744 return 1; // Buf has enough space for the event.
748 void postEventType(EventsBuf *eb, EventType *et)
753 postInt32(eb, EVENT_ET_BEGIN);
754 postEventTypeNum(eb, et->etNum);
755 postWord16(eb, (StgWord16)et->size);
756 desclen = strlen(et->desc);
757 postWord32(eb, desclen);
758 for (d = 0; d < desclen; ++d) {
759 postInt8(eb, (StgInt8)et->desc[d]);
761 postWord32(eb, 0); // no extensions yet
762 postInt32(eb, EVENT_ET_END);