X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=rts%2Feventlog%2FEventLog.c;h=178dfb3fd7653bc0d3d52787ccf4e61fdf477870;hb=d71615757d0462b1721ee3664c5fa9f79325d666;hp=98ccaa578b1a62d357194140a18ffa0aa495951c;hpb=0292156b69dbbf7ee2b494ba26ca1b7f28182ab6;p=ghc-hetmet.git diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 98ccaa5..178dfb3 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -6,14 +6,18 @@ * * ---------------------------------------------------------------------------*/ -#ifdef EVENTLOG - +#include "PosixSource.h" #include "Rts.h" -#include "EventLog.h" + +#ifdef TRACING + +#include "Trace.h" #include "Capability.h" #include "Trace.h" #include "RtsUtils.h" #include "Stats.h" +#include "EventLog.h" + #include #include @@ -30,26 +34,36 @@ static int flushCount; typedef struct _EventsBuf { StgInt8 *begin; StgInt8 *pos; + StgInt8 *marker; StgWord64 size; } 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", - "Starting GC", - "Finished GC", - "Request sequential GC", - "Request parallel GC", - "Create spark" + [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_CAP_MSG] = "Log Capability message", + [EVENT_LOG_MSG] = "Log message", + [EVENT_STARTUP] = "Startup", + [EVENT_BLOCK_MARKER] = "Block marker" }; // Event type. @@ -62,22 +76,17 @@ typedef struct _EventType { EventType eventTypes[NUM_EVENT_TAGS]; -static void printAndClearEventBuf (EventsBuf *eventsBuf); static void initEventsBuf(EventsBuf* eb, StgWord64 size); static void resetEventsBuf(EventsBuf* eb); - -static void beginHeader(EventsBuf *eb); -static void endHeader(EventsBuf *eb); - -static void beginData(EventsBuf *eb); -static void endData(EventsBuf *eb); - -static void beginEventTypes(EventsBuf *eb); -static void endEventTypes(EventsBuf *eb); +static void printAndClearEventBuf (EventsBuf *eventsBuf); 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) { @@ -102,14 +111,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); } @@ -128,10 +158,9 @@ 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, "initEventLogging"); if (sizeof(EventDesc) / sizeof(char*) != NUM_EVENT_TAGS) { @@ -156,18 +185,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); } + initEventsBuf(&eventBuf, EVENT_LOG_SIZE); // 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,22 +213,21 @@ initEventLogging(void) case EVENT_CREATE_THREAD: // (cap, thread) case EVENT_RUN_THREAD: // (cap, thread) case EVENT_THREAD_RUNNABLE: // (cap, thread) - case EVENT_CREATE_SPARK: // (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(EventCapNo) + 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(EventCapNo) + sizeof(EventThreadID) + sizeof(EventCapNo); break; case EVENT_STOP_THREAD: // (cap, thread, status) eventTypes[t].size = - sizeof(CapabilityNum) + sizeof(ThreadID) + sizeof(StgWord16); + sizeof(EventCapNo) + sizeof(EventThreadID) + sizeof(StgWord16); break; case EVENT_SHUTDOWN: // (cap) @@ -200,31 +235,49 @@ initEventLogging(void) case EVENT_REQUEST_PAR_GC: // (cap) case EVENT_GC_START: // (cap) case EVENT_GC_END: // (cap) - eventTypes[t].size = sizeof(CapabilityNum); + eventTypes[t].size = sizeof(EventCapNo); + break; + + case EVENT_LOG_MSG: // (msg) + case EVENT_LOG_CAP_MSG: // (cap,msg) + eventTypes[t].size = 0xffff; + break; + + case EVENT_STARTUP: + eventTypes[t].size = sizeof(EventCapNo); break; + + case EVENT_BLOCK_MARKER: + eventTypes[t].size = sizeof(StgWord32) + sizeof(EventTimestamp); + 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. + // 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]); + } } void @@ -232,46 +285,39 @@ 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); // 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"); } /* @@ -279,31 +325,36 @@ freeEventLogging(void) * 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); + postCapNo(eb, cap->no); switch (tag) { case EVENT_CREATE_THREAD: // (cap, thread) case EVENT_RUN_THREAD: // (cap, thread) case EVENT_THREAD_RUNNABLE: // (cap, thread) - case EVENT_CREATE_SPARK: // (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; } @@ -311,15 +362,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; } @@ -335,24 +386,99 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap) default: barf("postEvent: unknown event tag %d", tag); } +} + +#define BUF 512 + +void postMsg(char *msg, va_list ap) +{ + EventsBuf *eb; + char buf[BUF]; + nat size; + + size = vsnprintf(buf,BUF,msg,ap); + if (size > BUF) { + buf[BUF-1] = '\0'; + size = BUF; + } + + ACQUIRE_LOCK(&eventBufMutex); + eb = &eventBuf; + + if (!hasRoomForVariableEvent(eb, size)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } + + postEventHeader(eb, EVENT_LOG_MSG); + postPayloadSize(eb, size); + postBuf(eb,(StgWord8*)buf,size); + + RELEASE_LOCK(&eventBufMutex); +} + +void postCapMsg(Capability *cap, char *msg, va_list ap) +{ + EventsBuf *eb; + char buf[BUF]; + nat size; + + size = vsnprintf(buf,BUF,msg,ap); + if (size > BUF) { + buf[BUF-1] = '\0'; + size = BUF; + } - debugTrace(DEBUG_eventlog,"postEvent: finish"); + eb = &capEventBuf[cap->no]; + + if (!hasRoomForVariableEvent(eb, size)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } + + postEventHeader(eb, EVENT_LOG_MSG); + postPayloadSize(eb, size + sizeof(EventCapNo)); + postCapNo(eb, cap->no); + postBuf(eb,(StgWord8*)buf,size); } -static void printAndClearEventBuf (EventsBuf *eventsBuf) +void closeBlockMarker (EventsBuf *ebuf) +{ + if (ebuf->marker) + { + // (type:16, time:64, size:32, end_time:64) + *(StgWord32 *)(ebuf->marker + 10) = ebuf->pos - ebuf->marker; + *(StgWord64 *)(ebuf->marker + 14) = time_ns(); + ebuf->marker = NULL; + } +} + + +void postBlockMarker (EventsBuf *eb) +{ + 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); +} + +void printAndClearEventBuf (EventsBuf *ebuf) { StgWord64 numBytes = 0, written = 0; - if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin) + closeBlockMarker(ebuf); + + if (ebuf->begin != NULL && ebuf->pos != ebuf->begin) { - numBytes = eventsBuf->pos - eventsBuf->begin; - - debugTrace(DEBUG_eventlog, - "printAndEventLog: numbytes %" FMT_Word64 - " bytes to fwrite()", - numBytes); + numBytes = ebuf->pos - ebuf->begin; - written = fwrite(eventsBuf->begin, 1, numBytes, event_log_file); + written = fwrite(ebuf->begin, 1, numBytes, event_log_file); if (written != numBytes) { debugBelch( "printAndClearEventLog: fwrite() failed, written=%" FMT_Word64 @@ -360,33 +486,18 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf) return; } - debugTrace(DEBUG_eventlog, - "printAndClearEventLog: fwrite(): %" FMT_Word64 - " bytes written", written); - - resetEventsBuf(eventsBuf); + resetEventsBuf(ebuf); flushCount++; - } -} -void -printAndClearEventLog(Capability *cap) -{ - debugTrace(DEBUG_eventlog,"printAndClearEventLog: start"); - - printAndClearEventBuf(&eventsBuf[cap->no]); - - debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish"); + postBlockMarker(ebuf); + } } -/* ----------------------------------------------------------------------------- - Actual event generation below here - -------------------------------------------------------------------------- */ - void initEventsBuf(EventsBuf* eb, StgWord64 size) { - eb->begin = eb->pos = malloc(size); + eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf"); eb->size = size; + eb->marker = NULL; } void resetEventsBuf(EventsBuf* eb) @@ -394,52 +505,34 @@ 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) +StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum) { - postEventTypeNum(eb, EVENT_DATA_END); -} + nat size; -void beginEventTypes(EventsBuf *eb) -{ - postInt32(eb, EVENT_HET_BEGIN); -} + size = sizeof(EventTypeNum) + sizeof(EventTimestamp) + eventTypes[eNum].size; -void endEventTypes(EventsBuf *eb) -{ - postInt32(eb, EVENT_HET_END); + if (eb->pos + size > eb->begin + eb->size) { + return 0; // Not enough space. + } else { + return 1; // Buf has enough space for the event. + } } -StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum) +StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes) { - nat size = 0; + nat size; - size += sizeof(EventTypeNum) + sizeof(Timestamp) + eventTypes[eNum].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. } -} +} -static void postEventType(EventsBuf *eb, EventType *et) +void postEventType(EventsBuf *eb, EventType *et) { StgWord8 d; nat desclen; @@ -456,4 +549,4 @@ static void postEventType(EventsBuf *eb, EventType *et) postInt32(eb, EVENT_ET_END); } -#endif /* EVENTLOG */ +#endif /* TRACING */