X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=rts%2Feventlog%2FEventLog.c;h=fec34b9647ece0f4b7122a84a6d039182bcf1c24;hb=a201afd3d2c4bef07e4e7682b129f60dbdde0e8a;hp=448611675a567208207dded6c3887064e4093921;hpb=a5288c551349a0adab0d931a429b10a096d9444d;p=ghc-hetmet.git diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 4486116..fec34b9 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -13,13 +13,21 @@ #include "Trace.h" #include "Capability.h" -#include "Trace.h" #include "RtsUtils.h" #include "Stats.h" #include "EventLog.h" -#include +#include #include +#ifdef HAVE_SYS_TYPES_H +#include +#endif +#ifdef HAVE_UNISTD_H +#include +#endif + +// PID of the process that writes to event_log_filename (#4512) +static pid_t event_log_pid = -1; static char *event_log_filename = NULL; @@ -34,7 +42,9 @@ static int flushCount; typedef struct _EventsBuf { StgInt8 *begin; StgInt8 *pos; + StgInt8 *marker; StgWord64 size; + EventCapNo capno; // which capability this buffer belongs to, or -1 } EventsBuf; EventsBuf *capEventBuf; // one EventsBuf for each Capability @@ -59,9 +69,13 @@ char *EventDesc[] = { [EVENT_REQUEST_SEQ_GC] = "Request sequential GC", [EVENT_REQUEST_PAR_GC] = "Request parallel GC", [EVENT_CREATE_SPARK_THREAD] = "Create spark thread", - [EVENT_LOG_CAP_MSG] = "Log Capability message", [EVENT_LOG_MSG] = "Log message", - [EVENT_STARTUP] = "Startup" + [EVENT_USER_MSG] = "User message", + [EVENT_STARTUP] = "Startup", + [EVENT_GC_IDLE] = "GC idle", + [EVENT_GC_WORK] = "GC working", + [EVENT_GC_DONE] = "GC done", + [EVENT_BLOCK_MARKER] = "Block marker" }; // Event type. @@ -74,20 +88,16 @@ typedef struct _EventType { EventType eventTypes[NUM_EVENT_TAGS]; -static void printAndClearEventBuf (EventsBuf *eventsBuf); -static void initEventsBuf(EventsBuf* eb, StgWord64 size); +static void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno); static void resetEventsBuf(EventsBuf* eb); +static void printAndClearEventBuf (EventsBuf *eventsBuf); -static void beginHeader(EventsBuf *eb); -static void endHeader(EventsBuf *eb); - -static void beginData(EventsBuf *eb); -static void endData(EventsBuf *eb); +static void postEventType(EventsBuf *eb, EventType *et); -static void beginEventTypes(EventsBuf *eb); -static void endEventTypes(EventsBuf *eb); +static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap); -static void postEventType(EventsBuf *eb, EventType *et); +static void postBlockMarker(EventsBuf *eb); +static void closeBlockMarker(EventsBuf *ebuf); static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum); static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes); @@ -121,11 +131,14 @@ static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size) eb->pos += size; } +static inline StgWord64 time_ns(void) +{ return stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND); } + static inline void postEventTypeNum(EventsBuf *eb, EventTypeNum etNum) { postWord16(eb, etNum); } -static inline void postTimestamp(EventsBuf *eb, EventTimestamp t) -{ postWord64(eb,t); } +static inline void postTimestamp(EventsBuf *eb) +{ postWord64(eb, time_ns()); } static inline void postThreadID(EventsBuf *eb, EventThreadID id) { postWord32(eb,id); } @@ -136,6 +149,12 @@ static inline void postCapNo(EventsBuf *eb, EventCapNo no) static inline void postPayloadSize(EventsBuf *eb, EventPayloadSize size) { postWord16(eb,size); } +static inline void postEventHeader(EventsBuf *eb, EventTypeNum type) +{ + postEventTypeNum(eb, type); + postTimestamp(eb); +} + static inline void postInt8(EventsBuf *eb, StgInt8 i) { postWord8(eb, (StgWord8)i); } @@ -155,18 +174,29 @@ initEventLogging(void) StgWord8 t, c; nat n_caps; - event_log_filename = stgMallocBytes(strlen(prog_name) + 10, + event_log_filename = stgMallocBytes(strlen(prog_name) + + 10 /* .%d */ + + 10 /* .eventlog */, "initEventLogging"); if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) { barf("EventDesc array has the wrong number of elements"); } - - sprintf(event_log_filename, "%s.eventlog", prog_name); - + + if (event_log_pid == -1) { // #4512 + // Single process + sprintf(event_log_filename, "%s.eventlog", prog_name); + event_log_pid = getpid(); + } else { + // Forked process, eventlog already started by the parent + // before fork + event_log_pid = getpid(); + sprintf(event_log_filename, "%s.%d.eventlog", prog_name, event_log_pid); + } + /* Open event log file for writing. */ if ((event_log_file = fopen(event_log_filename, "wb")) == NULL) { - sysErrorBelch("initEventLoggin: can't open %s", event_log_filename); + sysErrorBelch("initEventLogging: can't open %s", event_log_filename); stg_exit(EXIT_FAILURE); } @@ -190,15 +220,15 @@ initEventLogging(void) for (c = 0; c < n_caps; ++c) { // Init buffer for events. - initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE); + initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c); } - initEventsBuf(&eventBuf, EVENT_LOG_SIZE); + initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1)); // Write in buffer: the header begin marker. - beginHeader(&eventBuf); + postInt32(&eventBuf, EVENT_HEADER_BEGIN); // Mark beginning of event types in the header. - beginEventTypes(&eventBuf); + postInt32(&eventBuf, EVENT_HET_BEGIN); for (t = 0; t < NUM_EVENT_TAGS; ++t) { eventTypes[t].etNum = t; @@ -210,19 +240,23 @@ initEventLogging(void) case EVENT_THREAD_RUNNABLE: // (cap, thread) case EVENT_RUN_SPARK: // (cap, thread) case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread) - eventTypes[t].size = sizeof(EventCapNo) + sizeof(EventThreadID); + eventTypes[t].size = sizeof(EventThreadID); break; case EVENT_MIGRATE_THREAD: // (cap, thread, new_cap) case EVENT_STEAL_SPARK: // (cap, thread, victim_cap) case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap) eventTypes[t].size = - sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(EventCapNo); + sizeof(EventThreadID) + sizeof(EventCapNo); break; case EVENT_STOP_THREAD: // (cap, thread, status) eventTypes[t].size = - sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(StgWord16); + sizeof(EventThreadID) + sizeof(StgWord16); + break; + + case EVENT_STARTUP: // (cap count) + eventTypes[t].size = sizeof(EventCapNo); break; case EVENT_SHUTDOWN: // (cap) @@ -230,14 +264,22 @@ initEventLogging(void) case EVENT_REQUEST_PAR_GC: // (cap) case EVENT_GC_START: // (cap) case EVENT_GC_END: // (cap) - eventTypes[t].size = sizeof(EventCapNo); + case EVENT_GC_IDLE: + case EVENT_GC_WORK: + case EVENT_GC_DONE: + eventTypes[t].size = 0; break; case EVENT_LOG_MSG: // (msg) - case EVENT_LOG_CAP_MSG: // (cap,msg) + case EVENT_USER_MSG: // (msg) eventTypes[t].size = 0xffff; break; + case EVENT_BLOCK_MARKER: + eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp) + + sizeof(EventCapNo); + break; + default: continue; /* ignore deprecated events */ } @@ -247,20 +289,32 @@ initEventLogging(void) } // Mark end of event types in the header. - endEventTypes(&eventBuf); + postInt32(&eventBuf, EVENT_HET_END); // Write in buffer: the header end marker. - endHeader(&eventBuf); + postInt32(&eventBuf, EVENT_HEADER_END); // Prepare event buffer for events (data). - beginData(&eventBuf); + postInt32(&eventBuf, EVENT_DATA_BEGIN); + // Post a STARTUP event with the number of capabilities + postEventHeader(&eventBuf, EVENT_STARTUP); + postCapNo(&eventBuf, n_caps); + // Flush capEventBuf with header. /* * Flush header and data begin marker to the file, thus preparing the * file to have events written to it. */ printAndClearEventBuf(&eventBuf); + + for (c = 0; c < n_caps; ++c) { + postBlockMarker(&capEventBuf[c]); + } + +#ifdef THREADED_RTS + initMutex(&eventBufMutex); +#endif } void @@ -273,9 +327,10 @@ endEventLogging(void) printAndClearEventBuf(&capEventBuf[c]); } printAndClearEventBuf(&eventBuf); + resetEventsBuf(&eventBuf); // we don't want the block marker // Mark end of events (data). - endData(&eventBuf); + postEventTypeNum(&eventBuf, EVENT_DATA_END); // Flush the end of data marker. printAndClearEventBuf(&eventBuf); @@ -303,6 +358,22 @@ freeEventLogging(void) } } +void +flushEventLog(void) +{ + if (event_log_file != NULL) { + fflush(event_log_file); + } +} + +void +abortEventLogging(void) +{ + freeEventLogging(); + if (event_log_file != NULL) { + fclose(event_log_file); + } +} /* * Post an event message to the capability's eventlog buffer. * If the buffer is full, prints out the buffer and clears it. @@ -322,9 +393,7 @@ postSchedEvent (Capability *cap, printAndClearEventBuf(eb); } - postEventTypeNum(eb, tag); - postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND)); - postCapNo(eb, cap->no); + postEventHeader(eb, tag); switch (tag) { case EVENT_CREATE_THREAD: // (cap, thread) @@ -372,11 +441,25 @@ postSchedEvent (Capability *cap, } } +void +postEvent (Capability *cap, EventTypeNum tag) +{ + EventsBuf *eb; + + eb = &capEventBuf[cap->no]; + + if (!hasRoomForEvent(eb, tag)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } + + postEventHeader(eb, tag); +} + #define BUF 512 -void postMsg(char *msg, va_list ap) +void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap) { - EventsBuf *eb; char buf[BUF]; nat size; @@ -386,52 +469,73 @@ void postMsg(char *msg, va_list ap) size = BUF; } - ACQUIRE_LOCK(&eventBufMutex); - eb = &eventBuf; - if (!hasRoomForVariableEvent(eb, size)) { // Flush event buffer to make room for new event. printAndClearEventBuf(eb); } - postEventTypeNum(eb, EVENT_LOG_MSG); - postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND)); + postEventHeader(eb, type); postPayloadSize(eb, size); postBuf(eb,(StgWord8*)buf,size); +} +void postMsg(char *msg, va_list ap) +{ + ACQUIRE_LOCK(&eventBufMutex); + postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap); RELEASE_LOCK(&eventBufMutex); } void postCapMsg(Capability *cap, char *msg, va_list ap) { - EventsBuf *eb; - char buf[BUF]; - nat size; + postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap); +} - size = vsnprintf(buf,BUF,msg,ap); - if (size > BUF) { - buf[BUF-1] = '\0'; - size = BUF; +void postUserMsg(Capability *cap, char *msg, va_list ap) +{ + postLogMsg(&capEventBuf[cap->no], EVENT_USER_MSG, msg, ap); +} + +void closeBlockMarker (EventsBuf *ebuf) +{ + StgInt8* save_pos; + + if (ebuf->marker) + { + // (type:16, time:64, size:32, end_time:64) + + save_pos = ebuf->pos; + ebuf->pos = ebuf->marker + sizeof(EventTypeNum) + + sizeof(EventTimestamp); + postWord32(ebuf, save_pos - ebuf->marker); + postTimestamp(ebuf); + ebuf->pos = save_pos; + ebuf->marker = NULL; } +} - eb = &capEventBuf[cap->no]; - if (!hasRoomForVariableEvent(eb, size)) { - // Flush event buffer to make room for new event. +void postBlockMarker (EventsBuf *eb) +{ + if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) { printAndClearEventBuf(eb); } - postEventTypeNum(eb, EVENT_LOG_MSG); - postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND)); - postPayloadSize(eb, size + sizeof(EventCapNo)); - postCapNo(eb, cap->no); - postBuf(eb,(StgWord8*)buf,size); + closeBlockMarker(eb); + + eb->marker = eb->pos; + postEventHeader(eb, EVENT_BLOCK_MARKER); + postWord32(eb,0); // these get filled in later by closeBlockMarker(); + postWord64(eb,0); + postCapNo(eb, eb->capno); } -static void printAndClearEventBuf (EventsBuf *ebuf) +void printAndClearEventBuf (EventsBuf *ebuf) { StgWord64 numBytes = 0, written = 0; + closeBlockMarker(ebuf); + if (ebuf->begin != NULL && ebuf->pos != ebuf->begin) { numBytes = ebuf->pos - ebuf->begin; @@ -446,60 +550,23 @@ static void printAndClearEventBuf (EventsBuf *ebuf) resetEventsBuf(ebuf); flushCount++; - } -} -void -printAndClearEventLog(Capability *cap) -{ - printAndClearEventBuf(&capEventBuf[cap->no]); + postBlockMarker(ebuf); + } } -/* ----------------------------------------------------------------------------- - Actual event generation below here - -------------------------------------------------------------------------- */ - -void initEventsBuf(EventsBuf* eb, StgWord64 size) +void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno) { eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf"); eb->size = size; + eb->marker = NULL; + eb->capno = capno; } void resetEventsBuf(EventsBuf* eb) { eb->pos = eb->begin; -} - -// N.B.: Assuming buffer contains enough space for the header begin marker. -void beginHeader(EventsBuf *eb) -{ - postInt32(eb, EVENT_HEADER_BEGIN); -} - -// N.B.: Assuming buffer contains enough space for the header end marker. -void endHeader(EventsBuf *eb) -{ - postInt32(eb, EVENT_HEADER_END); -} - -void beginData(EventsBuf *eb) -{ - postInt32(eb, EVENT_DATA_BEGIN); -} - -void endData(EventsBuf *eb) -{ - postEventTypeNum(eb, EVENT_DATA_END); -} - -void beginEventTypes(EventsBuf *eb) -{ - postInt32(eb, EVENT_HET_BEGIN); -} - -void endEventTypes(EventsBuf *eb) -{ - postInt32(eb, EVENT_HET_END); + eb->marker = NULL; } StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum) @@ -529,7 +596,7 @@ StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes) } } -static void postEventType(EventsBuf *eb, EventType *et) +void postEventType(EventsBuf *eb, EventType *et) { StgWord8 d; nat desclen;