X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=rts%2Feventlog%2FEventLog.c;h=fec34b9647ece0f4b7122a84a6d039182bcf1c24;hb=a201afd3d2c4bef07e4e7682b129f60dbdde0e8a;hp=820e95cef1b022c62c26c3797c29cd26223eec90;hpb=c14119ce2639d4e4c868f3d1c9bb59bd3a2dd281;p=ghc-hetmet.git diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 820e95c..fec34b9 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -6,16 +6,28 @@ * * ---------------------------------------------------------------------------*/ -#ifdef EVENTLOG - +#include "PosixSource.h" #include "Rts.h" -#include "EventLog.h" -#include "Capability.h" + +#ifdef TRACING + #include "Trace.h" +#include "Capability.h" #include "RtsUtils.h" #include "Stats.h" -#include +#include "EventLog.h" + +#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; @@ -30,25 +42,40 @@ 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 *eventsBuf; +EventsBuf *capEventBuf; // one EventsBuf for each Capability + +EventsBuf eventBuf; // an EventsBuf not associated with any Capability +#ifdef THREADED_RTS +Mutex eventBufMutex; // protected by this mutex +#endif char *EventDesc[] = { - "Create thread", - "Run thread", - "Stop thread", - "Thread runnable", - "Migrate thread", - "Run spark", - "Steal spark", - "Shutdown", - "Wakeup thread", - "Request sequential GC", - "Request parallel GC", - "Starting GC", - "Finished GC" + [EVENT_CREATE_THREAD] = "Create thread", + [EVENT_RUN_THREAD] = "Run thread", + [EVENT_STOP_THREAD] = "Stop thread", + [EVENT_THREAD_RUNNABLE] = "Thread runnable", + [EVENT_MIGRATE_THREAD] = "Migrate thread", + [EVENT_RUN_SPARK] = "Run spark", + [EVENT_STEAL_SPARK] = "Steal spark", + [EVENT_SHUTDOWN] = "Shutdown", + [EVENT_THREAD_WAKEUP] = "Wakeup thread", + [EVENT_GC_START] = "Starting GC", + [EVENT_GC_END] = "Finished GC", + [EVENT_REQUEST_SEQ_GC] = "Request sequential GC", + [EVENT_REQUEST_PAR_GC] = "Request parallel GC", + [EVENT_CREATE_SPARK_THREAD] = "Create spark thread", + [EVENT_LOG_MSG] = "Log message", + [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. @@ -61,22 +88,19 @@ 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); static inline void postWord8(EventsBuf *eb, StgWord8 i) { @@ -101,14 +125,35 @@ static inline void postWord64(EventsBuf *eb, StgWord64 i) postWord32(eb, (StgWord32)i); } +static inline void postBuf(EventsBuf *eb, StgWord8 *buf, nat size) +{ + memcpy(eb->pos, buf, 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 postEventTypeID(EventsBuf *eb, StgWord16 etID) -{ postWord16(eb, etID); } +static inline void postTimestamp(EventsBuf *eb) +{ postWord64(eb, time_ns()); } + +static inline void postThreadID(EventsBuf *eb, EventThreadID id) +{ postWord32(eb,id); } -static inline void postTimestamp(EventsBuf *eb, Timestamp t) -{ postWord64(eb,t); } +static inline void postCapNo(EventsBuf *eb, EventCapNo no) +{ postWord16(eb,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); } @@ -127,21 +172,31 @@ void initEventLogging(void) { StgWord8 t, c; + nat n_caps; - debugTrace(DEBUG_eventlog, "intiEventLog: start"); - - event_log_filename = stgMallocBytes(strlen(prog_name) + 9, + 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); } @@ -155,18 +210,25 @@ initEventLogging(void) * Use a single buffer to store the header with event types, then flush * the buffer so all buffers are empty for writing events. */ - eventsBuf = stgMallocBytes(n_capabilities * sizeof(EventsBuf),"initEventLogging"); - - for (c = 0; c < n_capabilities; ++c) { +#ifdef THREADED_RTS + // XXX n_capabilities hasn't been initislised yet + n_caps = RtsFlags.ParFlags.nNodes; +#else + n_caps = 1; +#endif + capEventBuf = stgMallocBytes(n_caps * sizeof(EventsBuf),"initEventLogging"); + + for (c = 0; c < n_caps; ++c) { // Init buffer for events. - initEventsBuf(&eventsBuf[c], EVENT_LOG_SIZE); + initEventsBuf(&capEventBuf[c], EVENT_LOG_SIZE, c); } + initEventsBuf(&eventBuf, EVENT_LOG_SIZE, (EventCapNo)(-1)); // Write in buffer: the header begin marker. - beginHeader(&eventsBuf[0]); + postInt32(&eventBuf, EVENT_HEADER_BEGIN); // Mark beginning of event types in the header. - beginEventTypes(&eventsBuf[0]); + postInt32(&eventBuf, EVENT_HET_BEGIN); for (t = 0; t < NUM_EVENT_TAGS; ++t) { eventTypes[t].etNum = t; @@ -177,20 +239,24 @@ initEventLogging(void) case EVENT_RUN_THREAD: // (cap, thread) case EVENT_THREAD_RUNNABLE: // (cap, thread) case EVENT_RUN_SPARK: // (cap, thread) - eventTypes[t].size = sizeof(CapabilityNum) + sizeof(ThreadID); + case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread) + 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(CapabilityNum) + sizeof(ThreadID) + - sizeof(CapabilityNum); + sizeof(EventThreadID) + sizeof(EventCapNo); break; case EVENT_STOP_THREAD: // (cap, thread, status) eventTypes[t].size = - sizeof(CapabilityNum) + sizeof(ThreadID) + sizeof(StgWord16); + sizeof(EventThreadID) + sizeof(StgWord16); + break; + + case EVENT_STARTUP: // (cap count) + eventTypes[t].size = sizeof(EventCapNo); break; case EVENT_SHUTDOWN: // (cap) @@ -198,31 +264,57 @@ initEventLogging(void) case EVENT_REQUEST_PAR_GC: // (cap) case EVENT_GC_START: // (cap) case EVENT_GC_END: // (cap) - eventTypes[t].size = sizeof(CapabilityNum); + case EVENT_GC_IDLE: + case EVENT_GC_WORK: + case EVENT_GC_DONE: + eventTypes[t].size = 0; + break; + + case EVENT_LOG_MSG: // (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 */ } // Write in buffer: the start event type. - postEventType(&eventsBuf[0], &eventTypes[t]); + postEventType(&eventBuf, &eventTypes[t]); } // Mark end of event types in the header. - endEventTypes(&eventsBuf[0]); + postInt32(&eventBuf, EVENT_HET_END); // Write in buffer: the header end marker. - endHeader(&eventsBuf[0]); + postInt32(&eventBuf, EVENT_HEADER_END); // Prepare event buffer for events (data). - beginData(&eventsBuf[0]); + postInt32(&eventBuf, EVENT_DATA_BEGIN); - // Flush eventsBuf with header. + // 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(&eventsBuf[0]); + printAndClearEventBuf(&eventBuf); - debugTrace(DEBUG_eventlog, "initEventLog: finish"); + for (c = 0; c < n_caps; ++c) { + postBlockMarker(&capEventBuf[c]); + } + +#ifdef THREADED_RTS + initMutex(&eventBufMutex); +#endif } void @@ -230,69 +322,78 @@ endEventLogging(void) { nat c; - debugTrace(DEBUG_eventlog,"endEventLog: start"); - // Flush all events remaining in the buffers. for (c = 0; c < n_capabilities; ++c) { - printAndClearEventBuf(&eventsBuf[c]); + printAndClearEventBuf(&capEventBuf[c]); } + printAndClearEventBuf(&eventBuf); + resetEventsBuf(&eventBuf); // we don't want the block marker // Mark end of events (data). - endData(&eventsBuf[0]); + postEventTypeNum(&eventBuf, EVENT_DATA_END); // Flush the end of data marker. - printAndClearEventBuf(&eventsBuf[0]); + printAndClearEventBuf(&eventBuf); if (event_log_file != NULL) { fclose(event_log_file); } - - debugTrace(DEBUG_eventlog,"endEventLog: finish"); } void freeEventLogging(void) { StgWord8 c; - - debugTrace(DEBUG_eventlog,"freeEventLog: start"); // Free events buffer. for (c = 0; c < n_capabilities; ++c) { - if (eventsBuf[c].begin != NULL) - stgFree(eventsBuf[c].begin); + if (capEventBuf[c].begin != NULL) + stgFree(capEventBuf[c].begin); } - if (eventsBuf != NULL) { - stgFree(eventsBuf); + if (capEventBuf != NULL) { + stgFree(capEventBuf); } if (event_log_filename != NULL) { stgFree(event_log_filename); } - - debugTrace(DEBUG_eventlog,"freeEventLog: finish"); } +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. */ void -postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap) +postSchedEvent (Capability *cap, + EventTypeNum tag, + StgThreadID thread, + StgWord64 other) { EventsBuf *eb; - debugTrace(DEBUG_eventlog,"postEvent: start"); - - eb = &eventsBuf[cap->no]; + eb = &capEventBuf[cap->no]; if (!hasRoomForEvent(eb, tag)) { // Flush event buffer to make room for new event. printAndClearEventBuf(eb); } - postEventTypeNum(eb, tag); - postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND)); - postWord16(eb, cap->no); + postEventHeader(eb, tag); switch (tag) { case EVENT_CREATE_THREAD: // (cap, thread) @@ -300,7 +401,13 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap) case EVENT_THREAD_RUNNABLE: // (cap, thread) case EVENT_RUN_SPARK: // (cap, thread) { - postWord64(eb,thread); + postThreadID(eb,thread); + break; + } + + case EVENT_CREATE_SPARK_THREAD: // (cap, spark_thread) + { + postThreadID(eb,other /* spark_thread */); break; } @@ -308,15 +415,15 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap) case EVENT_STEAL_SPARK: // (cap, thread, victim_cap) case EVENT_THREAD_WAKEUP: // (cap, thread, other_cap) { - postWord64(eb,thread); - postWord16(eb,other_cap); + postThreadID(eb,thread); + postCapNo(eb,other /* new_cap | victim_cap | other_cap */); break; - } + } case EVENT_STOP_THREAD: // (cap, thread, status) { - postWord64(eb,thread); - postWord16(eb,other_cap); + postThreadID(eb,thread); + postWord16(eb,other /* status */); break; } @@ -332,102 +439,141 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap) default: barf("postEvent: unknown event tag %d", tag); } - - debugTrace(DEBUG_eventlog,"postEvent: finish"); } -static void printAndClearEventBuf (EventsBuf *eventsBuf) +void +postEvent (Capability *cap, EventTypeNum tag) { - StgWord64 numBytes = 0, written = 0; + EventsBuf *eb; - if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin) - { - numBytes = eventsBuf->pos - eventsBuf->begin; - - debugTrace(DEBUG_eventlog, - "printAndEventLog: numbytes %" FMT_Word64 - " bytes to fwrite()", - numBytes); - - written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file); - if (written != numBytes) { - debugBelch( - "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64 - " doesn't match numBytes=%" FMT_Word64, written, numBytes); - return; - } - - debugTrace(DEBUG_eventlog, - "printAndClearEventLog: fwrite(): %" FMT_Word64 - " bytes written", written); - - resetEventsBuf(eventsBuf); - flushCount++; + eb = &capEventBuf[cap->no]; + + if (!hasRoomForEvent(eb, tag)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); } -} -void -printAndClearEventLog(Capability *cap) -{ - debugTrace(DEBUG_eventlog,"printAndClearEventLog: start"); - - printAndClearEventBuf(&eventsBuf[cap->no]); - - debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish"); + postEventHeader(eb, tag); } -/* ----------------------------------------------------------------------------- - Actual event generation below here - -------------------------------------------------------------------------- */ +#define BUF 512 -void initEventsBuf(EventsBuf* eb, StgWord64 size) +void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap) { - eb->begin = eb->pos = malloc(size); - eb->size = size; + char buf[BUF]; + nat size; + + size = vsnprintf(buf,BUF,msg,ap); + if (size > BUF) { + buf[BUF-1] = '\0'; + size = BUF; + } + + if (!hasRoomForVariableEvent(eb, size)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } + + postEventHeader(eb, type); + postPayloadSize(eb, size); + postBuf(eb,(StgWord8*)buf,size); } -void resetEventsBuf(EventsBuf* eb) +void postMsg(char *msg, va_list ap) { - eb->pos = eb->begin; + ACQUIRE_LOCK(&eventBufMutex); + postLogMsg(&eventBuf, EVENT_LOG_MSG, msg, ap); + RELEASE_LOCK(&eventBufMutex); } -// N.B.: Assuming buffer contains enough space for the header begin marker. -void beginHeader(EventsBuf *eb) +void postCapMsg(Capability *cap, char *msg, va_list ap) { - postInt32(eb, EVENT_HEADER_BEGIN); + postLogMsg(&capEventBuf[cap->no], EVENT_LOG_MSG, msg, ap); } -// N.B.: Assuming buffer contains enough space for the header end marker. -void endHeader(EventsBuf *eb) +void postUserMsg(Capability *cap, char *msg, va_list ap) { - postInt32(eb, EVENT_HEADER_END); + 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; + } } -void beginData(EventsBuf *eb) + +void postBlockMarker (EventsBuf *eb) { - postInt32(eb, EVENT_DATA_BEGIN); + if (!hasRoomForEvent(eb, EVENT_BLOCK_MARKER)) { + printAndClearEventBuf(eb); + } + + 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); } -void endData(EventsBuf *eb) +void printAndClearEventBuf (EventsBuf *ebuf) { - postEventTypeNum(eb, EVENT_DATA_END); + StgWord64 numBytes = 0, written = 0; + + closeBlockMarker(ebuf); + + if (ebuf->begin != NULL && ebuf->pos != ebuf->begin) + { + numBytes = ebuf->pos - ebuf->begin; + + written = fwrite(ebuf->begin, 1, numBytes, event_log_file); + if (written != numBytes) { + debugBelch( + "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64 + " doesn't match numBytes=%" FMT_Word64, written, numBytes); + return; + } + + resetEventsBuf(ebuf); + flushCount++; + + postBlockMarker(ebuf); + } } -void beginEventTypes(EventsBuf *eb) +void initEventsBuf(EventsBuf* eb, StgWord64 size, EventCapNo capno) { - postInt32(eb, EVENT_HET_BEGIN); + eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf"); + eb->size = size; + eb->marker = NULL; + eb->capno = capno; } -void endEventTypes(EventsBuf *eb) +void resetEventsBuf(EventsBuf* eb) { - postInt32(eb, EVENT_HET_END); + eb->pos = eb->begin; + eb->marker = NULL; } StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum) { - nat size = 0; + nat size; - size += sizeof(EventTypeNum) + sizeof(Timestamp) + eventTypes[eNum].size; + size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size; if (eb->pos + size > eb->begin + eb->size) { return 0; // Not enough space. @@ -436,7 +582,21 @@ StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum) } } -static void postEventType(EventsBuf *eb, EventType *et) +StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes) +{ + nat size; + + size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + + sizeof(EventPayloadSize) + payload_bytes; + + if (eb->pos + size > eb->begin + eb->size) { + return 0; // Not enough space. + } else { + return 1; // Buf has enough space for the event. + } +} + +void postEventType(EventsBuf *eb, EventType *et) { StgWord8 d; nat desclen; @@ -453,4 +613,4 @@ static void postEventType(EventsBuf *eb, EventType *et) postInt32(eb, EVENT_ET_END); } -#endif /* EVENTLOG */ +#endif /* TRACING */