Commit 598109eb authored by Mikolaj Konarski's avatar Mikolaj Konarski Committed by Duncan Coutts

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.
parent 1f809ce6
......@@ -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);
......
......@@ -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) {
......
......@@ -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);
......
......@@ -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,
......
......@@ -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);
......
......@@ -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)
......
......@@ -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);
......
......@@ -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();
......
Markdown is supported
0% or .
You are about to add 0 people to the discussion. Proceed with caution.
Finish editing this message first!
Please register or to comment