From 598109eb0cc2271c33e23b4ddb12123991273f61 Mon Sep 17 00:00:00 2001 From: Mikolaj Date: Fri, 9 Mar 2012 14:22:06 +0100 Subject: Fix the timestamps in GC_START and GC_END events on the GC-initiating cap There was a discrepancy between GC times reported in +RTS -s and the timestamps of GC_START and GC_END events on the cap, on which +RTS -s stats for the given GC are based. This is fixed by posting the events with exactly the same timestamp as generated for the stat calculation. The calls posting the events are moved too, so that the events are emitted close to the time instant they claim to be emitted at. The GC_STATS_GHC was moved, too, ensuring it's emitted before the moved GC_END on all caps, which simplifies tools code. --- rts/Schedule.c | 2 -- rts/Stats.c | 45 +++++++++++++++++++++++++++++++-------------- rts/Stats.h | 2 +- rts/Trace.c | 13 +++++++++++++ rts/Trace.h | 25 +++++++++++++++++++++++++ rts/eventlog/EventLog.c | 21 ++++++++++++++++++++- rts/eventlog/EventLog.h | 3 +++ 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 @@ -113,6 +113,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 */ @@ -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(); -- cgit v1.2.1