X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=rts%2Feventlog%2FEventLog.c;h=b5c2ef63bbdb0521e2ec80372d15865dbf7823fa;hb=43c7d555c8d7eea6ba0d76bce33be8d25a01c6fd;hp=448611675a567208207dded6c3887064e4093921;hpb=a5288c551349a0adab0d931a429b10a096d9444d;p=ghc-hetmet.git diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 4486116..b5c2ef6 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,17 @@ 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_CAPSET_CREATE] = "Create capability set", + [EVENT_CAPSET_DELETE] = "Delete capability set", + [EVENT_CAPSET_ASSIGN_CAP] = "Add capability to capability set", + [EVENT_CAPSET_REMOVE_CAP] = "Remove capability from capability set" }; // Event type. @@ -74,20 +92,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 postEventType(EventsBuf *eb, EventType *et); -static void beginData(EventsBuf *eb); -static void endData(EventsBuf *eb); +static void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap); -static void beginEventTypes(EventsBuf *eb); -static void endEventTypes(EventsBuf *eb); - -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 +135,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); } @@ -133,9 +150,21 @@ static inline void postThreadID(EventsBuf *eb, EventThreadID id) static inline void postCapNo(EventsBuf *eb, EventCapNo no) { postWord16(eb,no); } +static inline void postCapsetID(EventsBuf *eb, EventCapsetID id) +{ postWord32(eb,id); } + +static inline void postCapsetType(EventsBuf *eb, EventCapsetType type) +{ postWord16(eb,type); } + 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 +184,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 +230,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 +250,38 @@ 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) + sizeof(EventThreadID); + break; + + case EVENT_STARTUP: // (cap count) + eventTypes[t].size = sizeof(EventCapNo); + break; + + case EVENT_CAPSET_CREATE: // (capset, capset_type) + eventTypes[t].size = + sizeof(EventCapsetID) + sizeof(EventCapsetType); + break; + + case EVENT_CAPSET_DELETE: // (capset) + eventTypes[t].size = sizeof(EventCapsetID); + break; + + case EVENT_CAPSET_ASSIGN_CAP: // (capset, cap) + case EVENT_CAPSET_REMOVE_CAP: + eventTypes[t].size = + sizeof(EventCapsetID) + sizeof(EventCapNo); break; case EVENT_SHUTDOWN: // (cap) @@ -230,14 +289,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 +314,28 @@ 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); + // 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 +348,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 +379,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. @@ -311,7 +403,8 @@ void postSchedEvent (Capability *cap, EventTypeNum tag, StgThreadID thread, - StgWord64 other) + StgWord info1, + StgWord info2) { EventsBuf *eb; @@ -322,9 +415,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) @@ -338,7 +429,7 @@ postSchedEvent (Capability *cap, case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread) { - postThreadID(eb,other /* spark_thread */); + postThreadID(eb,info1 /* spark_thread */); break; } @@ -347,14 +438,15 @@ postSchedEvent (Capability *cap, case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap) { postThreadID(eb,thread); - postCapNo(eb,other /* new_cap | victim_cap | other_cap */); + postCapNo(eb,info1 /* new_cap | victim_cap | other_cap */); break; } case EVENT_STOP_THREAD: // (cap, thread, status) { postThreadID(eb,thread); - postWord16(eb,other /* status */); + postWord16(eb,info1 /* status */); + postThreadID(eb,info2 /* blocked on thread */); break; } @@ -372,11 +464,64 @@ postSchedEvent (Capability *cap, } } -#define BUF 512 +void postCapsetModifyEvent (EventTypeNum tag, + EventCapsetID capset, + StgWord32 other) +{ + ACQUIRE_LOCK(&eventBufMutex); -void postMsg(char *msg, va_list ap) + if (!hasRoomForEvent(&eventBuf, tag)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(&eventBuf); + } + + postEventHeader(&eventBuf, tag); + postCapsetID(&eventBuf, capset); + + switch (tag) { + case EVENT_CAPSET_CREATE: // (capset, capset_type) + { + postCapsetType(&eventBuf, other /* capset_type */); + break; + } + + case EVENT_CAPSET_DELETE: // (capset) + { + break; + } + + case EVENT_CAPSET_ASSIGN_CAP: // (capset, capno) + case EVENT_CAPSET_REMOVE_CAP: // (capset, capno) + { + postCapNo(&eventBuf, other /* capno */); + break; + } + default: + barf("postCapsetModifyEvent: unknown event tag %d", tag); + } + + RELEASE_LOCK(&eventBufMutex); +} + +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 postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap) +{ char buf[BUF]; nat size; @@ -386,52 +531,89 @@ 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); +} - eb = &capEventBuf[cap->no]; +void postEventStartup(EventCapNo n_caps) +{ + ACQUIRE_LOCK(&eventBufMutex); - if (!hasRoomForVariableEvent(eb, size)) { + if (!hasRoomForEvent(&eventBuf, EVENT_STARTUP)) { // Flush event buffer to make room for new event. + printAndClearEventBuf(&eventBuf); + } + + // Post a STARTUP event with the number of capabilities + postEventHeader(&eventBuf, EVENT_STARTUP); + postCapNo(&eventBuf, n_caps); + + RELEASE_LOCK(&eventBufMutex); +} + +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; + } +} + + +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 +628,23 @@ static void printAndClearEventBuf (EventsBuf *ebuf) resetEventsBuf(ebuf); flushCount++; + + postBlockMarker(ebuf); } } -void -printAndClearEventLog(Capability *cap) -{ - printAndClearEventBuf(&capEventBuf[cap->no]); -} - -/* ----------------------------------------------------------------------------- - 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 +674,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;