X-Git-Url: http://git.megacz.com/?a=blobdiff_plain;f=rts%2Feventlog%2FEventLog.c;h=448611675a567208207dded6c3887064e4093921;hb=53628e913632cac29d54da914040e39add334784;hp=98ccaa578b1a62d357194140a18ffa0aa495951c;hpb=0292156b69dbbf7ee2b494ba26ca1b7f28182ab6;p=ghc-hetmet.git diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 98ccaa5..4486116 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 @@ -33,23 +37,31 @@ typedef struct _EventsBuf { 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 type. @@ -78,6 +90,7 @@ static void endEventTypes(EventsBuf *eb); static void postEventType(EventsBuf *eb, EventType *et); static StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum); +static StgBool hasRoomForVariableEvent(EventsBuf *eb, nat payload_bytes); static inline void postWord8(EventsBuf *eb, StgWord8 i) { @@ -102,15 +115,27 @@ 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 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, Timestamp t) +static inline void postTimestamp(EventsBuf *eb, EventTimestamp t) { postWord64(eb,t); } +static inline void postThreadID(EventsBuf *eb, EventThreadID id) +{ postWord32(eb,id); } + +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 postInt8(EventsBuf *eb, StgInt8 i) { postWord8(eb, (StgWord8)i); } @@ -128,10 +153,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 +180,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]); + beginHeader(&eventBuf); // Mark beginning of event types in the header. - beginEventTypes(&eventsBuf[0]); + beginEventTypes(&eventBuf); for (t = 0; t < NUM_EVENT_TAGS; ++t) { eventTypes[t].etNum = t; @@ -177,22 +208,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 +230,37 @@ 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; + + 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]); + endEventTypes(&eventBuf); // Write in buffer: the header end marker. - endHeader(&eventsBuf[0]); + endHeader(&eventBuf); // Prepare event buffer for events (data). - beginData(&eventsBuf[0]); + beginData(&eventBuf); - // 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]); - - debugTrace(DEBUG_eventlog, "initEventLog: finish"); + printAndClearEventBuf(&eventBuf); } void @@ -232,46 +268,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]); + endData(&eventBuf); // 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,13 +308,14 @@ 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. @@ -294,16 +324,21 @@ postEvent_(Capability *cap, EventTypeNum tag, StgThreadID thread, nat other_cap) postEventTypeNum(eb, tag); postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND)); - postWord16(eb, cap->no); + 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 +346,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 +370,73 @@ 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); + } + + postEventTypeNum(eb, EVENT_LOG_MSG); + postTimestamp(eb, stat_getElapsedTime() * (1000000000LL/TICKS_PER_SECOND)); + 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; + } + + eb = &capEventBuf[cap->no]; + + if (!hasRoomForVariableEvent(eb, size)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } - debugTrace(DEBUG_eventlog,"postEvent: finish"); + 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); } -static void printAndClearEventBuf (EventsBuf *eventsBuf) +static void printAndClearEventBuf (EventsBuf *ebuf) { StgWord64 numBytes = 0, written = 0; - if (eventsBuf->begin != NULL && eventsBuf->pos != eventsBuf->begin) + if (ebuf->begin != NULL && ebuf->pos != ebuf->begin) { - numBytes = eventsBuf->pos - eventsBuf->begin; + numBytes = ebuf->pos - ebuf->begin; - debugTrace(DEBUG_eventlog, - "printAndEventLog: numbytes %" FMT_Word64 - " bytes to fwrite()", - numBytes); - - 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,11 +444,7 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf) return; } - debugTrace(DEBUG_eventlog, - "printAndClearEventLog: fwrite(): %" FMT_Word64 - " bytes written", written); - - resetEventsBuf(eventsBuf); + resetEventsBuf(ebuf); flushCount++; } } @@ -372,11 +452,7 @@ static void printAndClearEventBuf (EventsBuf *eventsBuf) void printAndClearEventLog(Capability *cap) { - debugTrace(DEBUG_eventlog,"printAndClearEventLog: start"); - - printAndClearEventBuf(&eventsBuf[cap->no]); - - debugTrace(DEBUG_eventlog,"printAndClearEventLog: finish"); + printAndClearEventBuf(&capEventBuf[cap->no]); } /* ----------------------------------------------------------------------------- @@ -385,7 +461,7 @@ printAndClearEventLog(Capability *cap) void initEventsBuf(EventsBuf* eb, StgWord64 size) { - eb->begin = eb->pos = malloc(size); + eb->begin = eb->pos = stgMallocBytes(size, "initEventsBuf"); eb->size = size; } @@ -428,9 +504,9 @@ void endEventTypes(EventsBuf *eb) 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. @@ -439,6 +515,20 @@ StgBool hasRoomForEvent(EventsBuf *eb, EventTypeNum eNum) } } +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. + } +} + static void postEventType(EventsBuf *eb, EventType *et) { StgWord8 d; @@ -456,4 +546,4 @@ static void postEventType(EventsBuf *eb, EventType *et) postInt32(eb, EVENT_ET_END); } -#endif /* EVENTLOG */ +#endif /* TRACING */