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"
83 typedef struct _EventType {
84 EventTypeNum etNum; // Event Type number.
85 nat size; // size of the payload in bytes
86 char *desc; // Description
89 EventType eventTypes[NUM_EVENT_TAGS];
91 static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno);
92 static void resetEventsBuf(EventsBuf* eb);
93 static void printAndClearEventBuf (EventsBuf *eventsBuf);
95 static void postEventType(EventsBuf *eb, EventType *et);
97 static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap);
99 static void postBlockMarker(EventsBuf *eb);
100 static void closeBlockMarker(EventsBuf *ebuf);
102 static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum);
103 static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes);
105 static inline void postWord8(EventsBuf *eb, StgWord8 i)
110 static inline void postWord16(EventsBuf *eb, StgWord16 i)
112 postWord8(eb, (StgWord8)(i >> 8));
113 postWord8(eb, (StgWord8)i);
116 static inline void postWord32(EventsBuf *eb, StgWord32 i)
118 postWord16(eb, (StgWord16)(i >> 16));
119 postWord16(eb, (StgWord16)i);
122 static inline void postWord64(EventsBuf *eb, StgWord64 i)
124 postWord32(eb, (StgWord32)(i >> 32));
125 postWord32(eb, (StgWord32)i);
128 static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size)
130 memcpy(eb->pos, buf, size);
134 static inline StgWord64 time_ns(void)
135 { return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); }
137 static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum)
138 { postWord16(eb, etNum); }
140 static inline void postTimestamp(EventsBuf *eb)
141 { postWord64(eb, time_ns()); }
143 static inline void postThreadID(EventsBuf *eb, EventThreadID id)
144 { postWord32(eb,id); }
146 static inline void postCapNo(EventsBuf *eb, EventCapNo no)
147 { postWord16(eb,no); }
149 static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size)
150 { postWord16(eb,size); }
152 static inline void postEventHeader(EventsBuf *eb, EventTypeNum type)
154 postEventTypeNum(eb, type);
158 static inline void postInt8(EventsBuf *eb, StgInt8 i)
159 { postWord8(eb, (StgWord8)i); }
161 static inline void postInt16(EventsBuf *eb, StgInt16 i)
162 { postWord16(eb, (StgWord16)i); }
164 static inline void postInt32(EventsBuf *eb, StgInt32 i)
165 { postWord32(eb, (StgWord32)i); }
167 static inline void postInt64(EventsBuf *eb, StgInt64 i)
168 { postWord64(eb, (StgWord64)i); }
172 initEventLogging(void)
177 event_log_filename = stgMallocBytes(strlen(prog_name)
179 + 10 /* .eventlog */,
182 if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) {
183 barf("EventDesc array has the wrong number of elements");
186 if (event_log_pid == -1) { // #4512
188 sprintf(event_log_filename, "%s.eventlog", prog_name);
189 event_log_pid = getpid();
191 // Forked process, eventlog already started by the parent
193 event_log_pid = getpid();
194 sprintf(event_log_filename, "%s.%d.eventlog", prog_name, event_log_pid);
197 /* Open event log file for writing. */
198 if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) {
199 sysErrorBelch("initEventLogging: can't open %s", event_log_filename);
200 stg_exit(EXIT_FAILURE);
204 * Allocate buffer(s) to store events.
205 * Create buffer large enough for the header begin marker, all event
206 * types, and header end marker to prevent checking if buffer has room
207 * for each of these steps, and remove the need to flush the buffer to
208 * disk during initialization.
210 * Use a single buffer to store the header with event types, then flush
211 * the buffer so all buffers are empty for writing events.
214 // XXX n_capabilities hasn't been initislised yet
215 n_caps = RtsFlags.ParFlags.nNodes;
219 capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging");
221 for (c = 0; c < n_caps; ++c) {
222 // Init buffer for events.
223 initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c);
225 initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1));
227 // Write in buffer: the header begin marker.
228 postInt32(&eventBuf, EVENT_HEADER_BEGIN);
230 // Mark beginning of event types in the header.
231 postInt32(&eventBuf, EVENT_HET_BEGIN);
232 for (t = 0; t < NUM_EVENT_TAGS; ++t) {
234 eventTypes[t].etNum = t;
235 eventTypes[t].desc = EventDesc[t];
238 case EVENT_CREATE_THREAD: // (cap, thread)
239 case EVENT_RUN_THREAD: // (cap, thread)
240 case EVENT_THREAD_RUNNABLE: // (cap, thread)
241 case EVENT_RUN_SPARK: // (cap, thread)
242 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
243 eventTypes[t].size = sizeof(EventThreadID);
246 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
247 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
248 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
250 sizeof(EventThreadID) + sizeof(EventCapNo);
253 case EVENT_STOP_THREAD: // (cap, thread, status)
255 sizeof(EventThreadID) + sizeof(StgWord16) + sizeof(EventThreadID);
258 case EVENT_STARTUP: // (cap count)
259 eventTypes[t].size = sizeof(EventCapNo);
262 case EVENT_SHUTDOWN: // (cap)
263 case EVENT_REQUEST_SEQ_GC: // (cap)
264 case EVENT_REQUEST_PAR_GC: // (cap)
265 case EVENT_GC_START: // (cap)
266 case EVENT_GC_END: // (cap)
270 eventTypes[t].size = 0;
273 case EVENT_LOG_MSG: // (msg)
274 case EVENT_USER_MSG: // (msg)
275 eventTypes[t].size = 0xffff;
278 case EVENT_BLOCK_MARKER:
279 eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) +
284 continue; /* ignore deprecated events */
287 // Write in buffer: the start event type.
288 postEventType(&eventBuf, &eventTypes[t]);
291 // Mark end of event types in the header.
292 postInt32(&eventBuf, EVENT_HET_END);
294 // Write in buffer: the header end marker.
295 postInt32(&eventBuf, EVENT_HEADER_END);
297 // Prepare event buffer for events (data).
298 postInt32(&eventBuf, EVENT_DATA_BEGIN);
300 // Post a STARTUP event with the number of capabilities
301 postEventHeader(&eventBuf, EVENT_STARTUP);
302 postCapNo(&eventBuf, n_caps);
304 // Flush capEventBuf with header.
306 * Flush header and data begin marker to the file, thus preparing the
307 * file to have events written to it.
309 printAndClearEventBuf(&eventBuf);
311 for (c = 0; c < n_caps; ++c) {
312 postBlockMarker(&capEventBuf[c]);
316 initMutex(&eventBufMutex);
321 endEventLogging(void)
325 // Flush all events remaining in the buffers.
326 for (c = 0; c < n_capabilities; ++c) {
327 printAndClearEventBuf(&capEventBuf[c]);
329 printAndClearEventBuf(&eventBuf);
330 resetEventsBuf(&eventBuf); // we don't want the block marker
332 // Mark end of events (data).
333 postEventTypeNum(&eventBuf, EVENT_DATA_END);
335 // Flush the end of data marker.
336 printAndClearEventBuf(&eventBuf);
338 if (event_log_file != NULL) {
339 fclose(event_log_file);
344 freeEventLogging(void)
348 // Free events buffer.
349 for (c = 0; c < n_capabilities; ++c) {
350 if (capEventBuf[c].begin != NULL)
351 stgFree(capEventBuf[c].begin);
353 if (capEventBuf != NULL) {
354 stgFree(capEventBuf);
356 if (event_log_filename != NULL) {
357 stgFree(event_log_filename);
364 if (event_log_file != NULL) {
365 fflush(event_log_file);
370 abortEventLogging(void)
373 if (event_log_file != NULL) {
374 fclose(event_log_file);
378 * Post an event message to the capability's eventlog buffer.
379 * If the buffer is full, prints out the buffer and clears it.
382 postSchedEvent (Capability *cap,
390 eb = &capEventBuf[cap->no];
392 if (!hasRoomForEvent(eb, tag)) {
393 // Flush event buffer to make room for new event.
394 printAndClearEventBuf(eb);
397 postEventHeader(eb, tag);
400 case EVENT_CREATE_THREAD: // (cap, thread)
401 case EVENT_RUN_THREAD: // (cap, thread)
402 case EVENT_THREAD_RUNNABLE: // (cap, thread)
403 case EVENT_RUN_SPARK: // (cap, thread)
405 postThreadID(eb,thread);
409 case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread)
411 postThreadID(eb,info1 /* spark_thread */);
415 case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap)
416 case EVENT_STEAL_SPARK: // (cap, thread, victim_cap)
417 case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap)
419 postThreadID(eb,thread);
420 postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */);
424 case EVENT_STOP_THREAD: // (cap, thread, status)
426 postThreadID(eb,thread);
427 postWord16(eb,info1 /* status */);
428 postThreadID(eb,info2 /* blocked on thread */);
432 case EVENT_SHUTDOWN: // (cap)
433 case EVENT_REQUEST_SEQ_GC: // (cap)
434 case EVENT_REQUEST_PAR_GC: // (cap)
435 case EVENT_GC_START: // (cap)
436 case EVENT_GC_END: // (cap)
442 barf("postEvent: unknown event tag %d", tag);
447 postEvent (Capability *cap, EventTypeNum tag)
451 eb = &capEventBuf[cap->no];
453 if (!hasRoomForEvent(eb, tag)) {
454 // Flush event buffer to make room for new event.
455 printAndClearEventBuf(eb);
458 postEventHeader(eb, tag);
463 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap)
468 size = vsnprintf(buf,BUF,msg,ap);
474 if (!hasRoomForVariableEvent(eb, size)) {
475 // Flush event buffer to make room for new event.
476 printAndClearEventBuf(eb);
479 postEventHeader(eb, type);
480 postPayloadSize(eb, size);
481 postBuf(eb,(StgWord8*)buf,size);
484 void postMsg(char *msg, va_list ap)
486 ACQUIRE_LOCK(&eventBufMutex);
487 postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap);
488 RELEASE_LOCK(&eventBufMutex);
491 void postCapMsg(Capability *cap, char *msg, va_list ap)
493 postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap);
496 void postUserMsg(Capability *cap, char *msg, va_list ap)
498 postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, ap);
501 void closeBlockMarker (EventsBuf *ebuf)
507 // (type:16, time:64, size:32, end_time:64)
509 save_pos = ebuf->pos;
510 ebuf->pos = ebuf->marker + sizeof(EventTypeNum) +
511 sizeof(EventTimestamp);
512 postWord32(ebuf, save_pos - ebuf->marker);
514 ebuf->pos = save_pos;
520 void postBlockMarker (EventsBuf *eb)
522 if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) {
523 printAndClearEventBuf(eb);
526 closeBlockMarker(eb);
528 eb->marker = eb->pos;
529 postEventHeader(eb, EVENT_BLOCK_MARKER);
530 postWord32(eb,0); // these get filled in later by closeBlockMarker();
532 postCapNo(eb, eb->capno);
535 void printAndClearEventBuf (EventsBuf *ebuf)
537 StgWord64 numBytes = 0, written = 0;
539 closeBlockMarker(ebuf);
541 if (ebuf->begin != NULL && ebuf->pos != ebuf->begin)
543 numBytes = ebuf->pos - ebuf->begin;
545 written = fwrite(ebuf->begin, 1, numBytes, event_log_file);
546 if (written != numBytes) {
548 "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64
549 " doesn't match numBytes=%" FMT_Word64, written, numBytes);
553 resetEventsBuf(ebuf);
556 postBlockMarker(ebuf);
560 void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno)
562 eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf");
568 void resetEventsBuf(EventsBuf* eb)
574 StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum)
578 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size;
580 if (eb->pos + size > eb->begin + eb->size) {
581 return 0; // Not enough space.
583 return 1; // Buf has enough space for the event.
587 StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes)
591 size = sizeof(EventTypeNum) + sizeof(EventTimestamp) +
592 sizeof(EventPayloadSize) + payload_bytes;
594 if (eb->pos + size > eb->begin + eb->size) {
595 return 0; // Not enough space.
597 return 1; // Buf has enough space for the event.
601 void postEventType(EventsBuf *eb, EventType *et)
606 postInt32(eb, EVENT_ET_BEGIN);
607 postEventTypeNum(eb, et->etNum);
608 postWord16(eb, (StgWord16)et->size);
609 desclen = strlen(et->desc);
610 postWord32(eb, desclen);
611 for (d = 0; d < desclen; ++d) {
612 postInt8(eb, (StgInt8)et->desc[d]);
614 postWord32(eb, 0); // no extensions yet
615 postInt32(eb, EVENT_ET_END);