mozilla
/
gecko-dev
зеркало из https://github.com/mozilla/gecko-dev.git
1
0
Форкнуть 0
Код Задачи Пакеты Проекты Релизы Вики Активность

Bug 699298 - Overhaul GC statistics gathering (r=gwagner)

This commit is contained in:
Bill McCloskey 2011-11-09 13:32:17 -08:00
Родитель d694c0c03c
Коммит b77a56e06b
9 изменённых файлов: 230 добавлений и 100 удалений
Показать статистику Скачать Patch файл Скачать Diff файл Показать все файлы Свернуть все файлы

114
dom/base/nsJSEnvironment.cpp
Просмотреть файл

@ -162,7 +162,7 @@ JSRuntime *nsJSRuntime::sRuntime;
static const char kJSRuntimeServiceContractID[] =
"@mozilla.org/js/xpc/RuntimeService;1";
static JSGCCallback gOldJSGCCallback;
static PRTime sFirstCollectionTime;
static bool sIsInitialized;
static bool sDidShutdown;
@ -3252,10 +3252,17 @@ nsJSContext::CycleCollectNow(nsICycleCollectorListener *aListener)
if (sPostGCEventsToConsole) {
PRTime now = PR_Now();
PRTime delta = 0;
if (sFirstCollectionTime) {
delta = now - sFirstCollectionTime;
} else {
sFirstCollectionTime = now;
}
NS_NAMED_LITERAL_STRING(kFmt,
"CC timestamp: %lld, collected: %lu (%lu waiting for GC), suspected: %lu, duration: %llu ms.");
"CC(T+%.1f) collected: %lu (%lu waiting for GC), suspected: %lu, duration: %llu ms.");
nsString msg;
msg.Adopt(nsTextFormatter::smprintf(kFmt.get(), now,
msg.Adopt(nsTextFormatter::smprintf(kFmt.get(), double(delta) / PR_USEC_PER_SEC,
collected, sCCollectedWaitingForGC, suspected,
(now - start) / PR_USEC_PER_MSEC));
nsCOMPtr<nsIConsoleService> cs =
@ -3396,67 +3403,59 @@ nsJSContext::GC()
PokeGC();
}
static JSBool
DOMGCCallback(JSContext *cx, JSGCStatus status)
static void
DOMGCFinishedCallback(JSRuntime *rt, JSCompartment *comp, const char *status)
{
static PRTime start;
NS_ASSERTION(NS_IsMainThread(), "GCs must run on the main thread");
if (sPostGCEventsToConsole && NS_IsMainThread()) {
if (status == JSGC_BEGIN) {
start = PR_Now();
} else if (status == JSGC_END) {
PRTime now = PR_Now();
NS_NAMED_LITERAL_STRING(kFmt, "GC mode: %s, timestamp: %lld, duration: %llu ms.");
nsString msg;
msg.Adopt(nsTextFormatter::smprintf(kFmt.get(),
cx->runtime->gcTriggerCompartment ? "compartment" : "full",
now,
(now - start) / PR_USEC_PER_MSEC));
nsCOMPtr<nsIConsoleService> cs = do_GetService(NS_CONSOLESERVICE_CONTRACTID);
if (cs) {
cs->LogStringMessage(msg.get());
}
}
}
if (status == JSGC_END) {
sCCollectedWaitingForGC = 0;
if (sGCTimer) {
// If we were waiting for a GC to happen, kill the timer.
nsJSContext::KillGCTimer();
// If this is a compartment GC, restart it. We still want
// a full GC to happen. Compartment GCs usually happen as a
// result of last-ditch or MaybeGC. In both cases its
// probably a time of heavy activity and we want to delay
// the full GC, but we do want it to happen eventually.
if (cx->runtime->gcTriggerCompartment) {
nsJSContext::PokeGC();
// We poked the GC, so we can kill any pending CC here.
nsJSContext::KillCCTimer();
}
if (sPostGCEventsToConsole) {
PRTime now = PR_Now();
PRTime delta = 0;
if (sFirstCollectionTime) {
delta = now - sFirstCollectionTime;
} else {
// If this was a full GC, poke the CC to run soon.
if (!cx->runtime->gcTriggerCompartment) {
sGCHasRun = true;
nsJSContext::PokeCC();
}
sFirstCollectionTime = now;
}
// If we didn't end up scheduling a GC, and there are unused
// chunks waiting to expire, make sure we will GC again soon.
if (!sGCTimer && JS_GetGCParameter(cx->runtime, JSGC_UNUSED_CHUNKS) > 0) {
nsJSContext::PokeGC();
NS_NAMED_LITERAL_STRING(kFmt, "GC(T+%.1f) %s");
nsString msg;
msg.Adopt(nsTextFormatter::smprintf(kFmt.get(),
double(delta) / PR_USEC_PER_SEC, status));
nsCOMPtr<nsIConsoleService> cs = do_GetService(NS_CONSOLESERVICE_CONTRACTID);
if (cs) {
cs->LogStringMessage(msg.get());
}
}
JSBool result = gOldJSGCCallback ? gOldJSGCCallback(cx, status) : JS_TRUE;
sCCollectedWaitingForGC = 0;
if (sGCTimer) {
// If we were waiting for a GC to happen, kill the timer.
nsJSContext::KillGCTimer();
if (status == JSGC_BEGIN && !NS_IsMainThread())
return JS_FALSE;
// If this is a compartment GC, restart it. We still want
// a full GC to happen. Compartment GCs usually happen as a
// result of last-ditch or MaybeGC. In both cases its
// probably a time of heavy activity and we want to delay
// the full GC, but we do want it to happen eventually.
if (comp) {
nsJSContext::PokeGC();
return result;
// We poked the GC, so we can kill any pending CC here.
nsJSContext::KillCCTimer();
}
} else {
// If this was a full GC, poke the CC to run soon.
if (!comp) {
sGCHasRun = true;
nsJSContext::PokeCC();
}
}
// If we didn't end up scheduling a GC, and there are unused
// chunks waiting to expire, make sure we will GC again soon.
if (!sGCTimer && JS_GetGCParameter(rt, JSGC_UNUSED_CHUNKS) > 0) {
nsJSContext::PokeGC();
}
}
// Script object mananagement - note duplicate implementation
@ -3561,7 +3560,6 @@ nsJSRuntime::Startup()
gNameSpaceManager = nsnull;
sRuntimeService = nsnull;
sRuntime = nsnull;
gOldJSGCCallback = nsnull;
sIsInitialized = false;
sDidShutdown = false;
sContextCount = 0;
@ -3715,11 +3713,7 @@ nsJSRuntime::Init()
// Let's make sure that our main thread is the same as the xpcom main thread.
NS_ASSERTION(NS_IsMainThread(), "bad");
NS_ASSERTION(!gOldJSGCCallback,
"nsJSRuntime initialized more than once");
// Save the old GC callback to chain to it, for GC-observing generality.
gOldJSGCCallback = ::JS_SetGCCallbackRT(sRuntime, DOMGCCallback);
::JS_SetGCFinishedCallback(sRuntime, DOMGCFinishedCallback);
JSSecurityCallbacks *callbacks = JS_GetRuntimeSecurityCallbacks(sRuntime);
NS_ASSERTION(callbacks, "SecMan should have set security callbacks!");

140
js/src/gc/Statistics.cpp
Просмотреть файл

@ -51,6 +51,70 @@
namespace js {
namespace gcstats {
Statistics::ColumnInfo::ColumnInfo(const char *title, double t, double total)
: title(title)
{
snprintf(str, sizeof(str), "%.1f", t);
snprintf(totalStr, sizeof(totalStr), "%.1f", total);
width = 6;
}
Statistics::ColumnInfo::ColumnInfo(const char *title, double t)
: title(title)
{
snprintf(str, sizeof(str), "%.1f", t);
strcpy(totalStr, "n/a");
width = 6;
}
Statistics::ColumnInfo::ColumnInfo(const char *title, unsigned int data)
: title(title)
{
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)
{
int i = 0;
cols[i++] = ColumnInfo("Type", compartment ? "Comp" : "Glob");
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));
cols[i++] = ColumnInfo("+Chu", counts[STAT_NEW_CHUNK]);
cols[i++] = ColumnInfo("-Chu", counts[STAT_DESTROY_CHUNK]);
cols[i++] = ColumnInfo("Reason", ExplainReason(triggerReason));
JS_ASSERT(i == NUM_COLUMNS);
}
Statistics::Statistics(JSRuntime *rt)
: runtime(rt)
{
@ -72,8 +136,13 @@ Statistics::Statistics(JSRuntime *rt)
fp = fopen(env, "a");
JS_ASSERT(fp);
fprintf(fp, " AppTime, Total, Wait, Mark, Sweep, FinObj,"
" FinStr, FinScr, FinShp, Destry, End, +Chu, -Chu, T, Reason\n");
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");
}
PodArrayZero(counts);
@ -85,14 +154,15 @@ Statistics::Statistics(JSRuntime *rt)
Statistics::~Statistics()
{
if (fp) {
if (fullFormat)
fprintf(fp,
"------>TOTAL "
"%6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f\n",
total(PHASE_GC), total(PHASE_MARK), total(PHASE_SWEEP),
total(PHASE_SWEEP_OBJECT), total(PHASE_SWEEP_STRING),
total(PHASE_SWEEP_SCRIPT), total(PHASE_SWEEP_SHAPE),
total(PHASE_DESTROY));
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");
}
if (fp != stdout && fp != stderr)
fclose(fp);
@ -149,24 +219,42 @@ 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;
}
}
void
Statistics::printStats()
{
if (fullFormat) {
/* App , Total, Wait , Mark , Sweep, FinOb, FinSt, FinSc, FinSh, Destry, End */
fprintf(fp,
"%12.0f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, %6.1f, ",
double(phaseStarts[PHASE_GC] - startupTime) / PRMJ_USEC_PER_MSEC,
t(PHASE_GC),
beginDelay(PHASE_MARK, PHASE_GC),
t(PHASE_MARK), t(PHASE_SWEEP),
t(PHASE_SWEEP_OBJECT), t(PHASE_SWEEP_STRING),
t(PHASE_SWEEP_SCRIPT), t(PHASE_SWEEP_SHAPE),
t(PHASE_DESTROY),
endDelay(PHASE_GC, PHASE_DESTROY));
fprintf(fp, "%12.0f", double(phaseStarts[PHASE_GC] - startupTime) / PRMJ_USEC_PER_MSEC);
fprintf(fp, "%4d, %4d,", counts[STAT_NEW_CHUNK], counts[STAT_DESTROY_CHUNK]);
fprintf(fp, " %s, %s\n", compartment ? "C" : "G", ExplainReason(triggerReason));
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");
} else {
fprintf(fp, "%f %f %f\n",
t(PHASE_GC), t(PHASE_MARK), t(PHASE_SWEEP));
@ -194,6 +282,12 @@ Statistics::endGC()
(*cb)(JS_TELEMETRY_GC_SWEEP_MS, t(PHASE_SWEEP));
}
if (JSGCFinishedCallback cb = runtime->gcFinishedCallback) {
char buffer[1024];
statsToString(buffer, sizeof(buffer));
(*cb)(runtime, compartment, buffer);
}
if (fp)
printStats();

19
js/src/gc/Statistics.h
Просмотреть файл

@ -84,6 +84,9 @@ enum Phase {
PHASE_SWEEP_STRING,
PHASE_SWEEP_SCRIPT,
PHASE_SWEEP_SHAPE,
PHASE_DISCARD_CODE,
PHASE_DISCARD_ANALYSIS,
PHASE_XPCONNECT,
PHASE_DESTROY,
PHASE_LIMIT
@ -133,6 +136,22 @@ struct Statistics {
double beginDelay(Phase phase1, Phase phase2);
double endDelay(Phase phase1, Phase phase2);
void printStats();
void statsToString(char *buffer, size_t size);
struct ColumnInfo {
const char *title;
char str[12];
char totalStr[12];
int width;
ColumnInfo() {}
ColumnInfo(const char *title, double t, double total);
ColumnInfo(const char *title, double t);
ColumnInfo(const char *title, unsigned int data);
ColumnInfo(const char *title, const char *data);
};
void makeTable(ColumnInfo *cols);
};
struct AutoGC {

1
js/src/jsapi.cpp
Просмотреть файл

@ -679,6 +679,7 @@ JSRuntime::JSRuntime()
gcDebugCompartmentGC(false),
#endif
gcCallback(NULL),
gcFinishedCallback(NULL),
gcMallocBytes(0),
gcBlackRootsTraceOp(NULL),
gcBlackRootsData(NULL),

1
js/src/jscntxt.h
Просмотреть файл

@ -545,6 +545,7 @@ struct JSRuntime
#endif
JSGCCallback gcCallback;
JSGCFinishedCallback gcFinishedCallback;
private:
/*

36
js/src/jscompartment.cpp
Просмотреть файл

@ -495,27 +495,33 @@ JSCompartment::sweep(JSContext *cx, bool releaseTypes)
traceMonitor()->sweep(cx);
#endif
/*
* Kick all frames on the stack into the interpreter, and release all JIT
* code in the compartment.
*/
#ifdef JS_METHODJIT
mjit::ClearAllFrames(this);
for (CellIterUnderGC i(this, FINALIZE_SCRIPT); !i.done(); i.next()) {
JSScript *script = i.get<JSScript>();
mjit::ReleaseScriptCode(cx, script);
{
gcstats::AutoPhase ap(rt->gcStats, gcstats::PHASE_DISCARD_CODE);
/*
* Use counts for scripts are reset on GC. After discarding code we
* need to let it warm back up to get information like which opcodes
* are setting array holes or accessing getter properties.
* Kick all frames on the stack into the interpreter, and release all JIT
* code in the compartment.
*/
script->resetUseCount();
}
#ifdef JS_METHODJIT
mjit::ClearAllFrames(this);
for (CellIterUnderGC i(this, FINALIZE_SCRIPT); !i.done(); i.next()) {
JSScript *script = i.get<JSScript>();
mjit::ReleaseScriptCode(cx, script);
/*
* Use counts for scripts are reset on GC. After discarding code we
* need to let it warm back up to get information like which opcodes
* are setting array holes or accessing getter properties.
*/
script->resetUseCount();
}
#endif
}
if (!activeAnalysis) {
gcstats::AutoPhase ap(rt->gcStats, gcstats::PHASE_DISCARD_ANALYSIS);
/*
* Clear the analysis pool, but don't release its data yet. While
* sweeping types any live data will be allocated into the pool.

6
js/src/jsfriendapi.cpp
Просмотреть файл

@ -229,6 +229,12 @@ JS_SetAccumulateTelemetryCallback(JSRuntime *rt, JSAccumulateTelemetryDataCallba
rt->telemetryCallback = callback;
}
JS_FRIEND_API(void)
JS_SetGCFinishedCallback(JSRuntime *rt, JSGCFinishedCallback callback)
{
rt->gcFinishedCallback = callback;
}
#ifdef DEBUG
struct DumpingChildInfo {

6
js/src/jsfriendapi.h
Просмотреть файл

@ -97,6 +97,12 @@ typedef void
extern JS_FRIEND_API(void)
JS_SetAccumulateTelemetryCallback(JSRuntime *rt, JSAccumulateTelemetryDataCallback callback);
typedef void
(* JSGCFinishedCallback)(JSRuntime *rt, JSCompartment *comp, const char *description);
extern JS_FRIEND_API(void)
JS_SetGCFinishedCallback(JSRuntime *rt, JSGCFinishedCallback callback);
/* Data for tracking analysis/inference memory usage. */
typedef struct TypeInferenceMemoryStats
{

7
js/src/jsgc.cpp
Просмотреть файл

@ -2635,8 +2635,11 @@ SweepPhase(JSContext *cx, GCMarker *gcmarker, JSGCInvocationKind gckind)
DecommitFreePages(cx);
}
if (rt->gcCallback)
(void) rt->gcCallback(cx, JSGC_FINALIZE_END);
{
gcstats::AutoPhase ap(rt->gcStats, gcstats::PHASE_XPCONNECT);
if (rt->gcCallback)
(void) rt->gcCallback(cx, JSGC_FINALIZE_END);
}
}
/*