diff --git a/js/src/gc/Nursery.cpp b/js/src/gc/Nursery.cpp index ef219bb9d825..28f6a84df8ca 100644 --- a/js/src/gc/Nursery.cpp +++ b/js/src/gc/Nursery.cpp @@ -9,10 +9,13 @@ #include "gc/Nursery-inl.h" +#include + #include "jscompartment.h" #include "jsgc.h" #include "jsinfer.h" #include "jsutil.h" +#include "prmjtime.h" #include "gc/GCInternals.h" #include "gc/Memory.h" @@ -32,6 +35,15 @@ using namespace js; using namespace gc; using namespace mozilla; +//#define PROFILE_NURSERY + +#ifdef PROFILE_NURSERY +/* + * Print timing information for minor GCs that take longer than this time in microseconds. + */ +static int64_t GCReportThreshold = INT64_MAX; +#endif + bool js::Nursery::init() { @@ -68,6 +80,12 @@ js::Nursery::init() for (int i = 0; i < NumNurseryChunks; ++i) chunk(i).trailer.runtime = rt; +#ifdef PROFILE_NURSERY + char *env = getenv("JS_MINORGC_TIME"); + if (env) + GCReportThreshold = atoi(env); +#endif + JS_ASSERT(isEnabled()); return true; } @@ -626,6 +644,16 @@ CheckHashTablesAfterMovingGC(JSRuntime *rt) #endif } +#ifdef PROFILE_NURSERY +#define TIME_START(name) int64_t timstampStart_##name = PRMJ_Now() +#define TIME_END(name) int64_t timstampEnd_##name = PRMJ_Now() +#define TIME_TOTAL(name) (timstampEnd_##name - timstampStart_##name) +#else +#define TIME_START(name) +#define TIME_END(name) +#define TIME_TOTAL(name) +#endif + void js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList *pretenureTypes) { @@ -640,17 +668,36 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList if (isEmpty()) return; + TIME_START(total); + AutoStopVerifyingBarriers av(rt, false); + TIME_START(waitBgSweep); rt->gcHelperThread.waitBackgroundSweepEnd(); + TIME_END(waitBgSweep); /* Move objects pointed to by roots from the nursery to the major heap. */ MinorCollectionTracer trc(rt, this); + + TIME_START(markStoreBuffer); rt->gcStoreBuffer.mark(&trc); // This must happen first. + TIME_END(markStoreBuffer); + + TIME_START(checkHashTables); CheckHashTablesAfterMovingGC(rt); + TIME_END(checkHashTables); + + TIME_START(markRuntime); MarkRuntime(&trc); + TIME_END(markRuntime); + + TIME_START(markDebugger); Debugger::markAll(&trc); + TIME_END(markDebugger); + + TIME_START(clearNewObjectCache); rt->newObjectCache.clearNurseryObjects(rt); + TIME_END(clearNewObjectCache); /* * Most of the work is done here. This loop iterates over objects that have @@ -658,21 +705,28 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList * to the nursery, then those nursery objects get moved as well, until no * objects are left to move. That is, we iterate to a fixed point. */ + TIME_START(collectToFP); TenureCountCache tenureCounts; collectToFixedPoint(&trc, tenureCounts); + TIME_END(collectToFP); + TIME_START(updateJitActivations); #ifdef JS_ION /* Update any slot or element pointers whose destination has been tenured. */ js::jit::UpdateJitActivationsForMinorGC(rt, &trc); #endif + TIME_END(updateJitActivations); /* Resize the nursery. */ + TIME_START(resize); double promotionRate = trc.tenuredSize / double(allocationEnd() - start()); if (promotionRate > 0.05) growAllocableSpace(); else if (promotionRate < 0.01) shrinkAllocableSpace(); + TIME_END(resize); + TIME_START(pretenure); // If we are promoting the nursery, or exhausted the store buffer with // pointers to nursery things, which will force a collection well before // the nursery is full, look for object types that are getting promoted @@ -684,10 +738,13 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList pretenureTypes->append(entry.type); // ignore alloc failure } } + TIME_END(pretenure); /* Sweep. */ + TIME_START(sweep); sweep(rt); rt->gcStoreBuffer.clear(); + TIME_END(sweep); /* * We ignore gcMaxBytes when allocating for minor collection. However, if we @@ -696,6 +753,37 @@ js::Nursery::collect(JSRuntime *rt, JS::gcreason::Reason reason, TypeObjectList */ if (rt->gcBytes >= rt->gcMaxBytes) disable(); + + TIME_END(total); + +#ifdef PROFILE_NURSERY + uint64_t totalTime = TIME_TOTAL(total); + + if (totalTime >= GCReportThreshold) { + static bool printedHeader = false; + if (!printedHeader) { + fprintf(stderr, + "MinorGC time: Total WaitBg mkStrBf ckHshTb mkRuntm mkDbggr clrNOC collect updtIon resize pretnur sweep\n"); + printedHeader = true; + } + +#define FMT " %7" PRIu64 + fprintf(stderr, "MinorGC time:" FMT FMT FMT FMT FMT FMT FMT FMT FMT FMT FMT FMT "\n", + totalTime, + TIME_TOTAL(waitBgSweep), + TIME_TOTAL(markStoreBuffer), + TIME_TOTAL(checkHashTables), + TIME_TOTAL(markRuntime), + TIME_TOTAL(markDebugger), + TIME_TOTAL(clearNewObjectCache), + TIME_TOTAL(collectToFP), + TIME_TOTAL(updateJitActivations), + TIME_TOTAL(resize), + TIME_TOTAL(pretenure), + TIME_TOTAL(sweep)); +#undef FMT + } +#endif } void