corysanin/tubestation
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

Bug 641025 - Incremental GC (r=igor,smaug,roc,cdleary,gregor)

Browse Source
This commit is contained in:
Bill McCloskey
2012-02-17 14:35:20 -08:00
parent d5bba64499
commit ca293fdba6
71 changed files with 2806 additions and 966 deletions
Download Patch File Download Diff File Expand all files Collapse all files

370
js/src/gc/Statistics.cpp
View File

@@ -38,9 +38,10 @@
* ***** END LICENSE BLOCK ***** */
#include <stdio.h>
#include <ctype.h>
#include <stdarg.h>
#include "jscntxt.h"
#include "jscompartment.h"
#include "jscrashformat.h"
#include "jscrashreport.h"
#include "jsprf.h"
@@ -69,78 +70,114 @@ ExplainReason(gcreason::Reason reason)
}
}
Statistics::ColumnInfo::ColumnInfo(const char *title, double t, double total)
: title(title)
void
Statistics::fmt(const char *f, ...)
{
JS_snprintf(str, sizeof(str), "%.1f", t);
JS_snprintf(totalStr, sizeof(totalStr), "%.1f", total);
width = 6;
}
va_list va;
size_t off = strlen(buffer);
Statistics::ColumnInfo::ColumnInfo(const char *title, double t)
: title(title)
{
JS_snprintf(str, sizeof(str), "%.1f", t);
strcpy(totalStr, "n/a");
width = 6;
va_start(va, f);
JS_vsnprintf(buffer + off, BUFFER_SIZE - off, f, va);
va_end(va);
}
Statistics::ColumnInfo::ColumnInfo(const char *title, unsigned int data)
: title(title)
{
JS_snprintf(str, sizeof(str), "%d", data);
strcpy(totalStr, "n/a");
width = 4;
}
Statistics::ColumnInfo::ColumnInfo(const char *title, const char *data)
: title(title)
{
JS_ASSERT(strlen(data) < sizeof(str));
strcpy(str, data);
strcpy(totalStr, "n/a ");
width = 0;
}
static const int NUM_COLUMNS = 17;
void
Statistics::makeTable(ColumnInfo *cols)
Statistics::fmtIfNonzero(const char *name, double t)
{
int i = 0;
if (t) {
if (needComma)
fmt(", ");
fmt("%s: %.1f", name, t);
needComma = true;
}
}
cols[i++] = ColumnInfo("Type", compartment ? "Comp" : "Glob");
void
Statistics::formatPhases(int64_t *times)
{
needComma = false;
fmtIfNonzero("mark", t(times[PHASE_MARK]));
fmtIfNonzero("mark-roots", t(times[PHASE_MARK_ROOTS]));
fmtIfNonzero("mark-delayed", t(times[PHASE_MARK_DELAYED]));
fmtIfNonzero("mark-other", t(times[PHASE_MARK_OTHER]));
fmtIfNonzero("sweep", t(times[PHASE_SWEEP]));
fmtIfNonzero("sweep-obj", t(times[PHASE_SWEEP_OBJECT]));
fmtIfNonzero("sweep-string", t(times[PHASE_SWEEP_STRING]));
fmtIfNonzero("sweep-script", t(times[PHASE_SWEEP_SCRIPT]));
fmtIfNonzero("sweep-shape", t(times[PHASE_SWEEP_SHAPE]));
fmtIfNonzero("discard-code", t(times[PHASE_DISCARD_CODE]));
fmtIfNonzero("discard-analysis", t(times[PHASE_DISCARD_ANALYSIS]));
fmtIfNonzero("xpconnect", t(times[PHASE_XPCONNECT]));
fmtIfNonzero("deallocate", t(times[PHASE_DESTROY]));
}
cols[i++] = ColumnInfo("Total", t(PHASE_GC), total(PHASE_GC));
cols[i++] = ColumnInfo("Wait", beginDelay(PHASE_MARK, PHASE_GC));
cols[i++] = ColumnInfo("Mark", t(PHASE_MARK), total(PHASE_MARK));
cols[i++] = ColumnInfo("Sweep", t(PHASE_SWEEP), total(PHASE_SWEEP));
cols[i++] = ColumnInfo("FinObj", t(PHASE_SWEEP_OBJECT), total(PHASE_SWEEP_OBJECT));
cols[i++] = ColumnInfo("FinStr", t(PHASE_SWEEP_STRING), total(PHASE_SWEEP_STRING));
cols[i++] = ColumnInfo("FinScr", t(PHASE_SWEEP_SCRIPT), total(PHASE_SWEEP_SCRIPT));
cols[i++] = ColumnInfo("FinShp", t(PHASE_SWEEP_SHAPE), total(PHASE_SWEEP_SHAPE));
cols[i++] = ColumnInfo("DisCod", t(PHASE_DISCARD_CODE), total(PHASE_DISCARD_CODE));
cols[i++] = ColumnInfo("DisAnl", t(PHASE_DISCARD_ANALYSIS), total(PHASE_DISCARD_ANALYSIS));
cols[i++] = ColumnInfo("XPCnct", t(PHASE_XPCONNECT), total(PHASE_XPCONNECT));
cols[i++] = ColumnInfo("Destry", t(PHASE_DESTROY), total(PHASE_DESTROY));
cols[i++] = ColumnInfo("End", endDelay(PHASE_GC, PHASE_DESTROY));
/* Except for the first and last, slices of less than 12ms are not reported. */
static const int64_t SLICE_MIN_REPORT_TIME = 12 * PRMJ_USEC_PER_MSEC;
cols[i++] = ColumnInfo("+Chu", counts[STAT_NEW_CHUNK]);
cols[i++] = ColumnInfo("-Chu", counts[STAT_DESTROY_CHUNK]);
const char *
Statistics::formatData()
{
buffer[0] = 0x00;
cols[i++] = ColumnInfo("Reason", ExplainReason(triggerReason));
int64_t total = 0, longest = 0;
JS_ASSERT(i == NUM_COLUMNS);
for (SliceData *slice = slices.begin(); slice != slices.end(); slice++) {
total += slice->duration();
if (slice->duration() > longest)
longest = slice->duration();
}
double mmu20 = computeMMU(20 * PRMJ_USEC_PER_MSEC);
double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
fmt("TotalTime: %.1fms, Type: %s", t(total), compartment ? "compartment" : "global");
fmt(", MMU(20ms): %d%%, MMU(50ms): %d%%", int(mmu20 * 100), int(mmu50 * 100));
if (slices.length() > 1)
fmt(", MaxPause: %.1f", t(longest));
else
fmt(", Reason: %s", ExplainReason(slices[0].reason));
if (wasReset)
fmt(", ***RESET***");
fmt(", +chunks: %d, -chunks: %d\n", counts[STAT_NEW_CHUNK], counts[STAT_DESTROY_CHUNK]);
if (slices.length() > 1) {
for (size_t i = 0; i < slices.length(); i++) {
int64_t width = slices[i].duration();
if (i != 0 && i != slices.length() - 1 && width < SLICE_MIN_REPORT_TIME)
continue;
fmt(" Slice %d @ %.1fms (Pause: %.1f, Reason: %s): ",
i,
t(slices[i].end - slices[0].start),
t(width),
ExplainReason(slices[i].reason));
formatPhases(slices[i].phaseTimes);
fmt("\n");
}
fmt(" Totals: ");
}
formatPhases(phaseTimes);
fmt("\n");
return buffer;
}
Statistics::Statistics(JSRuntime *rt)
: runtime(rt),
triggerReason(gcreason::NO_REASON)
startupTime(PRMJ_Now()),
fp(NULL),
fullFormat(false),
compartment(NULL),
wasReset(false),
needComma(false)
{
PodArrayZero(phaseTotals);
PodArrayZero(counts);
PodArrayZero(totals);
startupTime = PRMJ_Now();
char *env = getenv("MOZ_GCTIMER");
if (!env || strcmp(env, "none") == 0) {
@@ -159,14 +196,6 @@ Statistics::Statistics(JSRuntime *rt)
fp = fopen(env, "a");
JS_ASSERT(fp);
fprintf(fp, " AppTime");
ColumnInfo cols[NUM_COLUMNS];
makeTable(cols);
for (int i = 0; i < NUM_COLUMNS; i++)
fprintf(fp, ", %*s", cols[i].width, cols[i].title);
fprintf(fp, "\n");
}
}
@@ -174,13 +203,9 @@ Statistics::~Statistics()
{
if (fp) {
if (fullFormat) {
fprintf(fp, "------>TOTAL");
ColumnInfo cols[NUM_COLUMNS];
makeTable(cols);
for (int i = 0; i < NUM_COLUMNS && cols[i].totalStr[0]; i++)
fprintf(fp, ", %*s", cols[i].width, cols[i].totalStr);
fprintf(fp, "\n");
buffer[0] = 0x00;
formatPhases(phaseTotals);
fprintf(fp, "TOTALS\n%s\n\n-------\n", buffer);
}
if (fp != stdout && fp != stderr)
@@ -188,120 +213,65 @@ Statistics::~Statistics()
}
}
struct GCCrashData
{
int isRegen;
int isCompartment;
};
void
Statistics::beginGC(JSCompartment *comp, gcreason::Reason reason)
{
compartment = comp;
PodArrayZero(phaseStarts);
PodArrayZero(phaseEnds);
PodArrayZero(phaseTimes);
triggerReason = reason;
beginPhase(PHASE_GC);
Probes::GCStart();
GCCrashData crashData;
crashData.isCompartment = !!compartment;
crash::SaveCrashData(crash::JS_CRASH_TAG_GC, &crashData, sizeof(crashData));
}
double
Statistics::t(Phase phase)
Statistics::t(int64_t t)
{
return double(phaseTimes[phase]) / PRMJ_USEC_PER_MSEC;
return double(t) / PRMJ_USEC_PER_MSEC;
}
double
Statistics::total(Phase phase)
int64_t
Statistics::gcDuration()
{
return double(totals[phase]) / PRMJ_USEC_PER_MSEC;
}
double
Statistics::beginDelay(Phase phase1, Phase phase2)
{
return double(phaseStarts[phase1] - phaseStarts[phase2]) / PRMJ_USEC_PER_MSEC;
}
double
Statistics::endDelay(Phase phase1, Phase phase2)
{
return double(phaseEnds[phase1] - phaseEnds[phase2]) / PRMJ_USEC_PER_MSEC;
}
void
Statistics::statsToString(char *buffer, size_t size)
{
JS_ASSERT(size);
buffer[0] = 0x00;
ColumnInfo cols[NUM_COLUMNS];
makeTable(cols);
size_t pos = 0;
for (int i = 0; i < NUM_COLUMNS; i++) {
int len = strlen(cols[i].title) + 1 + strlen(cols[i].str);
if (i > 0)
len += 2;
if (pos + len >= size)
break;
if (i > 0)
strcat(buffer, ", ");
strcat(buffer, cols[i].title);
strcat(buffer, ":");
strcat(buffer, cols[i].str);
pos += len;
}
return slices.back().end - slices[0].start;
}
void
Statistics::printStats()
{
if (fullFormat) {
fprintf(fp, "%12.0f", double(phaseStarts[PHASE_GC] - startupTime) / PRMJ_USEC_PER_MSEC);
ColumnInfo cols[NUM_COLUMNS];
makeTable(cols);
for (int i = 0; i < NUM_COLUMNS; i++)
fprintf(fp, ", %*s", cols[i].width, cols[i].str);
fprintf(fp, "\n");
fprintf(fp, "GC(T+%.3fs) %s\n",
t(slices[0].start - startupTime) / 1000.0,
formatData());
} else {
fprintf(fp, "%f %f %f\n",
t(PHASE_GC), t(PHASE_MARK), t(PHASE_SWEEP));
t(gcDuration()),
t(phaseTimes[PHASE_MARK]),
t(phaseTimes[PHASE_SWEEP]));
}
fflush(fp);
}
void
Statistics::beginGC()
{
PodArrayZero(phaseStarts);
PodArrayZero(phaseTimes);
slices.clearAndFree();
wasReset = false;
Probes::GCStart();
}
void
Statistics::endGC()
{
Probes::GCEnd();
endPhase(PHASE_GC);
crash::SnapshotGCStack();
for (int i = 0; i < PHASE_LIMIT; i++)
totals[i] += phaseTimes[i];
phaseTotals[i] += phaseTimes[i];
if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback) {
(*cb)(JS_TELEMETRY_GC_REASON, triggerReason);
(*cb)(JS_TELEMETRY_GC_IS_COMPARTMENTAL, compartment ? 1 : 0);
(*cb)(JS_TELEMETRY_GC_MS, t(PHASE_GC));
(*cb)(JS_TELEMETRY_GC_MARK_MS, t(PHASE_MARK));
(*cb)(JS_TELEMETRY_GC_SWEEP_MS, t(PHASE_SWEEP));
}
(*cb)(JS_TELEMETRY_GC_MS, t(gcDuration()));
(*cb)(JS_TELEMETRY_GC_MARK_MS, t(phaseTimes[PHASE_MARK]));
(*cb)(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[PHASE_SWEEP]));
(*cb)(JS_TELEMETRY_GC_RESET, wasReset);
(*cb)(JS_TELEMETRY_GC_INCREMENTAL_DISABLED, !runtime->gcIncrementalEnabled);
if (JSGCFinishedCallback cb = runtime->gcFinishedCallback) {
char buffer[1024];
statsToString(buffer, sizeof(buffer));
(*cb)(runtime, compartment, buffer);
double mmu50 = computeMMU(50 * PRMJ_USEC_PER_MSEC);
(*cb)(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
}
if (fp)
@@ -310,6 +280,47 @@ Statistics::endGC()
PodArrayZero(counts);
}
void
Statistics::beginSlice(JSCompartment *comp, gcreason::Reason reason)
{
compartment = comp;
bool first = runtime->gcIncrementalState == gc::NO_INCREMENTAL;
if (first)
beginGC();
SliceData data(reason, PRMJ_Now());
(void) slices.append(data); /* Ignore any OOMs here. */
if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback)
(*cb)(JS_TELEMETRY_GC_REASON, reason);
if (GCSliceCallback cb = runtime->gcSliceCallback) {
GCDescription desc(NULL, !!compartment);
(*cb)(runtime, first ? GC_CYCLE_BEGIN : GC_SLICE_BEGIN, desc);
}
}
void
Statistics::endSlice()
{
slices.back().end = PRMJ_Now();
if (JSAccumulateTelemetryDataCallback cb = runtime->telemetryCallback)
(*cb)(JS_TELEMETRY_GC_SLICE_MS, t(slices.back().end - slices.back().start));
bool last = runtime->gcIncrementalState == gc::NO_INCREMENTAL;
if (last)
endGC();
if (GCSliceCallback cb = runtime->gcSliceCallback) {
if (last)
(*cb)(runtime, GC_CYCLE_END, GCDescription(formatData(), !!compartment));
else
(*cb)(runtime, GC_SLICE_END, GCDescription(NULL, !!compartment));
}
}
void
Statistics::beginPhase(Phase phase)
{
@@ -324,8 +335,10 @@ Statistics::beginPhase(Phase phase)
void
Statistics::endPhase(Phase phase)
{
phaseEnds[phase] = PRMJ_Now();
phaseTimes[phase] += phaseEnds[phase] - phaseStarts[phase];
int64_t now = PRMJ_Now();
int64_t t = now - phaseStarts[phase];
slices.back().phaseTimes[phase] += t;
phaseTimes[phase] += t;
if (phase == gcstats::PHASE_MARK)
Probes::GCEndMarkPhase();
@@ -333,5 +346,44 @@ Statistics::endPhase(Phase phase)
Probes::GCEndSweepPhase();
}
/*
* MMU (minimum mutator utilization) is a measure of how much garbage collection
* is affecting the responsiveness of the system. MMU measurements are given
* with respect to a certain window size. If we report MMU(50ms) = 80%, then
* that means that, for any 50ms window of time, at least 80% of the window is
* devoted to the mutator. In other words, the GC is running for at most 20% of
* the window, or 10ms. The GC can run multiple slices during the 50ms window
* as long as the total time it spends is at most 10ms.
*/
double
Statistics::computeMMU(int64_t window)
{
JS_ASSERT(!slices.empty());
int64_t gc = slices[0].end - slices[0].start;
int64_t gcMax = gc;
if (gc >= window)
return 0.0;
int startIndex = 0;
for (size_t endIndex = 1; endIndex < slices.length(); endIndex++) {
gc += slices[endIndex].end - slices[endIndex].start;
while (slices[endIndex].end - slices[startIndex].end >= window) {
gc -= slices[startIndex].end - slices[startIndex].start;
startIndex++;
}
int64_t cur = gc;
if (slices[endIndex].end - slices[startIndex].start > window)
cur -= (slices[endIndex].end - slices[startIndex].start - window);
if (cur > gcMax)
gcMax = cur;
}
return double(window - gcMax) / window;
}
} /* namespace gcstats */
} /* namespace js */