diff options
| -rw-r--r-- | rts/Schedule.c | 2 | ||||
| -rw-r--r-- | rts/Stats.c | 45 | ||||
| -rw-r--r-- | rts/Stats.h | 2 | ||||
| -rw-r--r-- | rts/Trace.c | 13 | ||||
| -rw-r--r-- | rts/Trace.h | 25 | ||||
| -rw-r--r-- | rts/eventlog/EventLog.c | 21 | ||||
| -rw-r--r-- | rts/eventlog/EventLog.h | 3 | ||||
| -rw-r--r-- | rts/sm/GC.c | 2 |
8 files changed, 94 insertions, 19 deletions
diff --git a/rts/Schedule.c b/rts/Schedule.c index f3ab30b4b4..fe346afe19 100644 --- a/rts/Schedule.c +++ b/rts/Schedule.c @@ -1631,7 +1631,6 @@ delete_threads_and_gc: heap_census = scheduleNeedHeapProfile(rtsTrue); - traceEventGcStart(cap); #if defined(THREADED_RTS) // reset pending_sync *before* GC, so that when the GC threads // emerge they don't immediately re-enter the GC. @@ -1640,7 +1639,6 @@ delete_threads_and_gc: #else GarbageCollect(force_major || heap_census, heap_census, 0, cap); #endif - traceEventGcEnd(cap); traceSparkCounters(cap); diff --git a/rts/Stats.c b/rts/Stats.c index 29cae21bf3..ddc9bb96ae 100644 --- a/rts/Stats.c +++ b/rts/Stats.c @@ -256,7 +256,7 @@ stat_endExit(void) static nat rub_bell = 0; void -stat_startGC (gc_thread *gct) +stat_startGC (Capability *cap, gc_thread *gct) { nat bell = RtsFlags.GcFlags.ringBell; @@ -278,7 +278,16 @@ stat_startGC (gc_thread *gct) #endif getProcessTimes(&gct->gc_start_cpu, &gct->gc_start_elapsed); - gct->gc_start_thread_cpu = getThreadCPUTime(); + + // Post EVENT_GC_START with the same timestamp as used for stats + // (though converted from Time=StgInt64 to EventTimestamp=StgWord64). + // Here, as opposed to other places, the event is emitted on the cap + // that initiates the GC and external tools expect it to have the same + // timestamp as used in +RTS -s calculcations. + traceEventGcStartAtT(cap, + TimeToNS(gct->gc_start_elapsed - start_init_elapsed)); + + gct->gc_start_thread_cpu = getThreadCPUTime(); if (RtsFlags.GcFlags.giveStats != NO_GC_STATS) { @@ -339,10 +348,29 @@ stat_endGC (Capability *cap, gc_thread *gct, // heap profiling needs GC_tot_time { Time cpu, elapsed, gc_cpu, gc_elapsed; + + traceEventGcStats(cap, + CAPSET_HEAP_DEFAULT, + gen, + copied * sizeof(W_), + slop * sizeof(W_), + /* current loss due to fragmentation */ + (mblocks_allocated * BLOCKS_PER_MBLOCK - n_alloc_blocks) + * BLOCK_SIZE_W * sizeof(W_), + par_n_threads, + par_max_copied * sizeof(W_), + par_tot_copied * sizeof(W_)); getProcessTimes(&cpu, &elapsed); - gc_elapsed = elapsed - gct->gc_start_elapsed; + // Post EVENT_GC_END with the same timestamp as used for stats + // (though converted from Time=StgInt64 to EventTimestamp=StgWord64). + // Here, as opposed to other places, the event is emitted on the cap + // that initiates the GC and external tools expect it to have the same + // timestamp as used in +RTS -s calculcations. + traceEventGcEndAtT(cap, TimeToNS(elapsed - start_init_elapsed)); + + gc_elapsed = elapsed - gct->gc_start_elapsed; gc_cpu = cpu - gct->gc_start_cpu; if (RtsFlags.GcFlags.giveStats == VERBOSE_GC_STATS) { @@ -397,17 +425,6 @@ stat_endGC (Capability *cap, gc_thread *gct, traceEventHeapSize(cap, CAPSET_HEAP_DEFAULT, mblocks_allocated * MBLOCK_SIZE_W * sizeof(W_)); - traceEventGcStats(cap, - CAPSET_HEAP_DEFAULT, - gen, - copied * sizeof(W_), - slop * sizeof(W_), - /* current loss due to fragmentation */ - (mblocks_allocated * BLOCKS_PER_MBLOCK - n_alloc_blocks) - * BLOCK_SIZE_W * sizeof(W_), - par_n_threads, - par_max_copied * sizeof(W_), - par_tot_copied * sizeof(W_)); if (gen == RtsFlags.GcFlags.generations-1) { /* major GC? */ if (live > max_residency) { diff --git a/rts/Stats.h b/rts/Stats.h index 63a1801236..baabd26553 100644 --- a/rts/Stats.h +++ b/rts/Stats.h @@ -18,7 +18,7 @@ struct gc_thread_; void stat_startInit(void); void stat_endInit(void); -void stat_startGC(struct gc_thread_ *gct); +void stat_startGC(Capability *cap, struct gc_thread_ *gct); void stat_endGC (Capability *cap, struct gc_thread_ *gct, lnat alloc, lnat live, lnat copied, lnat slop, nat gen, nat n_gc_threads, lnat par_max_copied, lnat par_tot_copied); diff --git a/rts/Trace.c b/rts/Trace.c index f597726f90..995f8a2200 100644 --- a/rts/Trace.c +++ b/rts/Trace.c @@ -304,6 +304,19 @@ void traceGcEvent_ (Capability *cap, EventTypeNum tag) } } +void traceGcEventAtT_ (Capability *cap, StgWord64 ts, EventTypeNum tag) +{ +#ifdef DEBUG + if (RtsFlags.TraceFlags.tracing == TRACE_STDERR) { + traceGcEvent_stderr(cap, tag); + } else +#endif + { + /* assuming nullary events and explicitly inserting a timestamp */ + postEventAtTimestamp(cap, ts, tag); + } +} + void traceHeapEvent_ (Capability *cap, EventTypeNum tag, CapsetID heap_capset, diff --git a/rts/Trace.h b/rts/Trace.h index 18856d9721..062666b503 100644 --- a/rts/Trace.h +++ b/rts/Trace.h @@ -114,6 +114,16 @@ void traceSchedEvent_ (Capability *cap, EventTypeNum tag, void traceGcEvent_ (Capability *cap, EventTypeNum tag); /* + * Record a GC event at the explicitly given timestamp + */ +#define traceGcEventAtT(cap, ts, tag) \ + if (RTS_UNLIKELY(TRACE_gc)) { \ + traceGcEventAtT_(cap, ts, tag); \ + } + +void traceGcEventAtT_ (Capability *cap, StgWord64 ts, EventTypeNum tag); + +/* * Record a heap event */ #define traceHeapEvent(cap, tag, heap_capset, info1) \ @@ -257,6 +267,7 @@ void traceSparkCounters_ (Capability *cap, #define traceSchedEvent(cap, tag, tso, other) /* nothing */ #define traceSchedEvent2(cap, tag, tso, other, info) /* nothing */ #define traceGcEvent(cap, tag) /* nothing */ +#define traceGcEventAtT(cap, ts, tag) /* nothing */ #define traceEventGcStats_(cap, heap_capset, gen, \ copied, slop, fragmentation, \ par_n_threads, par_max_copied, par_tot_copied) /* nothing */ @@ -549,12 +560,26 @@ INLINE_HEADER void traceEventGcStart(Capability *cap STG_UNUSED) dtraceGcStart((EventCapNo)cap->no); } +INLINE_HEADER void traceEventGcStartAtT(Capability *cap STG_UNUSED, + StgWord64 ts STG_UNUSED) +{ + traceGcEventAtT(cap, ts, EVENT_GC_START); + dtraceGcStart((EventCapNo)cap->no); +} + INLINE_HEADER void traceEventGcEnd(Capability *cap STG_UNUSED) { traceGcEvent(cap, EVENT_GC_END); dtraceGcEnd((EventCapNo)cap->no); } +INLINE_HEADER void traceEventGcEndAtT(Capability *cap STG_UNUSED, + StgWord64 ts STG_UNUSED) +{ + traceGcEventAtT(cap, ts, EVENT_GC_END); + dtraceGcEnd((EventCapNo)cap->no); +} + INLINE_HEADER void traceEventRequestSeqGc(Capability *cap STG_UNUSED) { traceGcEvent(cap, EVENT_REQUEST_SEQ_GC); diff --git a/rts/eventlog/EventLog.c b/rts/eventlog/EventLog.c index 8e7cf3784d..aab93bbd92 100644 --- a/rts/eventlog/EventLog.c +++ b/rts/eventlog/EventLog.c @@ -839,7 +839,7 @@ void postHeapEvent (Capability *cap, case EVENT_HEAP_LIVE: // (heap_capset, live_bytes) { postCapsetID(eb, heap_capset); - postWord64(eb,info1 /* alloc/size/live_bytes */); + postWord64(eb, info1 /* alloc/size/live_bytes */); break; } @@ -924,6 +924,25 @@ postEvent (Capability *cap, EventTypeNum tag) postEventHeader(eb, tag); } +void +postEventAtTimestamp (Capability *cap, EventTimestamp ts, EventTypeNum tag) +{ + EventsBuf *eb; + + eb = &capEventBuf[cap->no]; + + if (!hasRoomForEvent(eb, tag)) { + // Flush event buffer to make room for new event. + printAndClearEventBuf(eb); + } + + /* Normally we'd call postEventHeader(), but that generates its own + timestamp, so we go one level lower so we can write out + the timestamp we received as an argument. */ + postEventTypeNum(eb, tag); + postWord64(eb, ts); +} + #define BUF 512 void postLogMsg(EventsBuf *eb, EventTypeNum type, char *msg, va_list ap) diff --git a/rts/eventlog/EventLog.h b/rts/eventlog/EventLog.h index dadc6fa6d9..d1b0814114 100644 --- a/rts/eventlog/EventLog.h +++ b/rts/eventlog/EventLog.h @@ -40,6 +40,9 @@ void postSchedEvent(Capability *cap, EventTypeNum tag, */ void postEvent(Capability *cap, EventTypeNum tag); +void postEventAtTimestamp (Capability *cap, EventTimestamp ts, + EventTypeNum tag); + void postMsg(char *msg, va_list ap); void postUserMsg(Capability *cap, char *msg, va_list ap); diff --git a/rts/sm/GC.c b/rts/sm/GC.c index 0d83f2abae..a6b8c4af64 100644 --- a/rts/sm/GC.c +++ b/rts/sm/GC.c @@ -209,7 +209,7 @@ GarbageCollect (rtsBool force_major_gc, SET_GCT(gc_threads[cap->no]); // tell the stats department that we've started a GC - stat_startGC(gct); + stat_startGC(cap, gct); // lock the StablePtr table stablePtrPreGC(); |