Bug 1088831 - Track mutator vs GC time in specified intervals, r=jonco

--HG--
extra : rebase_source : 9a33a646c120df0fb22399c6ea83c0a041bad9f0
This commit is contained in:
Steve Fink 2014-11-13 12:23:26 -08:00
parent 456449f25a
commit df33ea76fe
5 changed files with 115 additions and 11 deletions

View File

@ -27,6 +27,7 @@ using namespace js::gc;
using namespace js::gcstats;
using mozilla::PodArrayZero;
using mozilla::PodZero;
/* Except for the first and last, slices of less than 10ms are not reported. */
static const int64_t SLICE_MIN_REPORT_TIME = 10 * PRMJ_USEC_PER_MSEC;
@ -283,6 +284,7 @@ struct PhaseInfo
static const Phase PHASE_NO_PARENT = PHASE_LIMIT;
static const PhaseInfo phases[] = {
{ PHASE_MUTATOR, "Mutator Running", PHASE_NO_PARENT },
{ PHASE_GC_BEGIN, "Begin Callback", PHASE_NO_PARENT },
{ PHASE_WAIT_BACKGROUND_THREAD, "Wait Background Thread", PHASE_NO_PARENT },
{ PHASE_MARK_DISCARD_CODE, "Mark Discard Code", PHASE_NO_PARENT },
@ -642,6 +644,8 @@ Statistics::Statistics(JSRuntime *rt)
fullFormat(false),
gcDepth(0),
nonincrementalReason(nullptr),
timingMutator(false),
timedGCStart(0),
preBytes(0),
maxPauseInInterval(0),
phaseNestingDepth(0),
@ -778,8 +782,8 @@ Statistics::endGC()
// Clear the timers at the end of a GC because we accumulate time for some
// phases (eg storebuffer compaction) during the mutator's run.
PodArrayZero(phaseStartTimes);
PodArrayZero(phaseTimes);
PodZero(&phaseStartTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN);
PodZero(&phaseTimes[PHASE_GC_BEGIN], PHASE_LIMIT - PHASE_GC_BEGIN);
}
void
@ -836,12 +840,50 @@ Statistics::endSlice()
PodArrayZero(counts);
}
void
Statistics::startTimingMutator()
{
MOZ_ASSERT(!timingMutator);
// Should only be called from outside of GC
MOZ_ASSERT(phaseNestingDepth == 0);
timingMutator = true;
timedGCTime = 0;
phaseStartTimes[PHASE_MUTATOR] = 0;
phaseTimes[PHASE_MUTATOR] = 0;
timedGCStart = 0;
beginPhase(PHASE_MUTATOR);
}
void
Statistics::stopTimingMutator(double &mutator_ms, double &gc_ms)
{
MOZ_ASSERT(timingMutator);
// Should only be called from outside of GC
MOZ_ASSERT(phaseNestingDepth == 1 && phaseNesting[0] == PHASE_MUTATOR);
endPhase(PHASE_MUTATOR);
mutator_ms = t(phaseTimes[PHASE_MUTATOR]);
gc_ms = t(timedGCTime);
timingMutator = false;
}
void
Statistics::beginPhase(Phase phase)
{
/* Guard against re-entry */
MOZ_ASSERT(!phaseStartTimes[phase]);
if (timingMutator) {
if (phaseNestingDepth == 1 && phaseNesting[0] == PHASE_MUTATOR) {
endPhase(PHASE_MUTATOR);
timedGCStart = PRMJ_Now();
}
}
#ifdef DEBUG
MOZ_ASSERT(phases[phase].index == phase);
Phase parent = phaseNestingDepth ? phaseNesting[phaseNestingDepth - 1] : PHASE_NO_PARENT;
@ -868,6 +910,13 @@ Statistics::endPhase(Phase phase)
slices.back().phaseTimes[phase] += t;
phaseTimes[phase] += t;
phaseStartTimes[phase] = 0;
if (timingMutator) {
if (phaseNestingDepth == 0 && phase != PHASE_MUTATOR) {
timedGCTime += now - timedGCStart;
beginPhase(PHASE_MUTATOR);
}
}
}
void

View File

@ -27,6 +27,7 @@ class GCParallelTask;
namespace gcstats {
enum Phase {
PHASE_MUTATOR,
PHASE_GC_BEGIN,
PHASE_WAIT_BACKGROUND_THREAD,
PHASE_MARK_DISCARD_CODE,
@ -128,6 +129,9 @@ struct Statistics
JS::gcreason::Reason reason);
void endSlice();
void startTimingMutator();
void stopTimingMutator(double &mutator_ms, double &gc_ms);
void reset(const char *reason) { slices.back().resetReason = reason; }
void nonincremental(const char *reason) { nonincrementalReason = reason; }
@ -189,6 +193,13 @@ struct Statistics
/* Most recent time when the given phase started. */
int64_t phaseStartTimes[PHASE_LIMIT];
/* Are we currently timing mutator vs GC time? */
bool timingMutator;
/* Bookkeeping for GC timings when timingMutator is true */
int64_t timedGCStart;
int64_t timedGCTime;
/* Total time in a given phase for this GC. */
int64_t phaseTimes[PHASE_LIMIT];
@ -204,12 +215,10 @@ struct Statistics
/* Records the maximum GC pause in an API-controlled interval (in us). */
int64_t maxPauseInInterval;
#ifdef DEBUG
/* Phases that are currently on stack. */
static const size_t MAX_NESTING = 8;
Phase phaseNesting[MAX_NESTING];
#endif
mozilla::DebugOnly<size_t> phaseNestingDepth;
size_t phaseNestingDepth;
/* Sweep times for SCCs of compartments. */
Vector<int64_t, 0, SystemAllocPolicy> sccTimes;

View File

@ -10,6 +10,7 @@
#include "mozilla/Assertions.h"
#include "gc/Statistics.h"
#include "vm/ArgumentsObject.h"
#include "vm/ForkJoin.h"
@ -99,7 +100,7 @@ StoreBuffer::MonoTypeBuffer<T>::handleOverflow(StoreBuffer *owner)
* Compact the buffer now, and if that fails to free enough space then
* trigger a minor collection.
*/
gcstats::AutoPhase ap(owner->stats(), PHASE_COMPACT_STOREBUFFER_NO_PARENT);
gcstats::AutoPhase ap(owner->stats(), gcstats::PHASE_COMPACT_STOREBUFFER_NO_PARENT);
owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
compact(owner);
if (isLowOnSpace())
@ -111,7 +112,7 @@ StoreBuffer::MonoTypeBuffer<T>::handleOverflow(StoreBuffer *owner)
*/
if (storage_->availableInCurrentChunk() < sizeof(T)) {
owner->stats().count(gcstats::STAT_STOREBUFFER_OVERFLOW);
maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_NO_PARENT);
maybeCompact(owner, gcstats::PHASE_COMPACT_STOREBUFFER_NO_PARENT);
}
}
}
@ -154,11 +155,11 @@ StoreBuffer::MonoTypeBuffer<T>::compact(StoreBuffer *owner)
template <typename T>
void
StoreBuffer::MonoTypeBuffer<T>::maybeCompact(StoreBuffer *owner, gcstats::Phase phase)
StoreBuffer::MonoTypeBuffer<T>::maybeCompact(StoreBuffer *owner, int phase)
{
MOZ_ASSERT(storage_);
if (storage_->used() != usedAtLastCompact_) {
gcstats::AutoPhase ap(owner->stats(), phase);
gcstats::AutoPhase ap(owner->stats(), static_cast<gcstats::Phase>(phase));
compact(owner);
}
}
@ -172,7 +173,7 @@ StoreBuffer::MonoTypeBuffer<T>::mark(StoreBuffer *owner, JSTracer *trc)
if (!storage_)
return;
maybeCompact(owner, PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC);
maybeCompact(owner, gcstats::PHASE_COMPACT_STOREBUFFER_IN_MINOR_GC);
for (LifoAlloc::Enum e(*storage_); !e.empty(); e.popFront<T>()) {
T *edge = e.get<T>();

View File

@ -144,7 +144,7 @@ class StoreBuffer
virtual void compact(StoreBuffer *owner);
/* Compacts if any entries have been added since the last compaction. */
void maybeCompact(StoreBuffer *owner, gcstats::Phase phase);
void maybeCompact(StoreBuffer *owner, int phase);
/* Add one item to the buffer. */
void put(StoreBuffer *owner, const T &t) {

View File

@ -1669,6 +1669,43 @@ Quit(JSContext *cx, unsigned argc, jsval *vp)
return false;
}
static bool
StartTimingMutator(JSContext *cx, unsigned argc, jsval *vp)
{
CallArgs args = CallArgsFromVp(argc, vp);
if (args.length() > 0) {
JS_ReportErrorNumber(cx, my_GetErrorMessage, nullptr,
JSSMSG_TOO_MANY_ARGS, "startTimingMutator");
return false;
}
cx->runtime()->gc.stats.startTimingMutator();
args.rval().setUndefined();
return true;
}
static bool
StopTimingMutator(JSContext *cx, unsigned argc, jsval *vp)
{
CallArgs args = CallArgsFromVp(argc, vp);
if (args.length() > 0) {
JS_ReportErrorNumber(cx, my_GetErrorMessage, nullptr,
JSSMSG_TOO_MANY_ARGS, "stopTimingMutator");
return false;
}
double mutator_ms, gc_ms;
cx->runtime()->gc.stats.stopTimingMutator(mutator_ms, gc_ms);
double total_ms = mutator_ms + gc_ms;
if (total_ms > 0) {
fprintf(gOutFile, "Mutator: %.3fms (%.1f%%), GC: %.3fms (%.1f%%)\n",
mutator_ms, mutator_ms / total_ms * 100.0, gc_ms, gc_ms / total_ms * 100.0);
}
args.rval().setUndefined();
return true;
}
static const char *
ToSource(JSContext *cx, MutableHandleValue vp, JSAutoByteString *bytes)
{
@ -4273,6 +4310,14 @@ static const JSFunctionSpecWithHelp shell_functions[] = {
" Throw if the first two arguments are not the same (both +0 or both -0,\n"
" both NaN, or non-zero and ===)."),
JS_FN_HELP("startTimingMutator", StartTimingMutator, 0, 0,
"startTimingMutator()",
" Start accounting time to mutator vs GC."),
JS_FN_HELP("stopTimingMutator", StopTimingMutator, 0, 0,
"stopTimingMutator()",
" Stop accounting time to mutator vs GC and dump the results."),
JS_FN_HELP("throwError", ThrowError, 0, 0,
"throwError()",
" Throw an error from JS_ReportError."),