Backed out changeset 726930634e95 (bug 1814193) for causing bustages on Nursery.cpp. CLOSED TREE

This commit is contained in:
Marian-Vasile Laza 2023-02-01 11:46:03 +02:00
Родитель b40adc4537
Коммит 54b66c6223
4 изменённых файлов: 84 добавлений и 282 удалений

Просмотреть файл

@ -10,7 +10,6 @@
#include "mozilla/DebugOnly.h"
#include "mozilla/IntegerPrintfMacros.h"
#include "mozilla/ScopeExit.h"
#include "mozilla/Sprintf.h"
#include "mozilla/TimeStamp.h"
#include <algorithm>
@ -31,7 +30,6 @@
#include "util/GetPidProvider.h" // getpid()
#include "util/Poison.h"
#include "vm/JSONPrinter.h"
#include "vm/Printer.h"
#include "vm/Realm.h"
#include "vm/Time.h"
@ -910,94 +908,41 @@ void js::Nursery::renderProfileJSON(JSONPrinter& json) const {
json.endObject();
}
// The following macros define nursery GC profile metadata fields that are
// printed before the timing information defined by
// FOR_EACH_NURSERY_PROFILE_TIME.
#define FOR_EACH_NURSERY_PROFILE_COMMON_METADATA(_) \
_("PID", 7, "%7zu", pid) \
_("Runtime", 14, "0x%12p", runtime)
#define FOR_EACH_NURSERY_PROFILE_METADATA(_) \
FOR_EACH_NURSERY_PROFILE_COMMON_METADATA(_) \
_("Timestamp", 10, "%10.6f", timestamp.ToSeconds()) \
_("Reason", 20, "%-20.20s", reasonStr) \
_("PRate", 6, "%5.1f%%", promotionRatePercent) \
_("OldKB", 6, "%6zu", oldSizeKB) \
_("NewKB", 6, "%6zu", newSizeKB) \
_("Dedup", 6, "%6zu", dedupCount)
#define FOR_EACH_NURSERY_PROFILE_TOTALS_METADATA(_) \
FOR_EACH_NURSERY_PROFILE_COMMON_METADATA(_) \
_("CollectionCount", 59, "%-59s", collections)
void js::Nursery::printCollectionProfile(JS::GCReason reason,
double promotionRate) {
stats().maybePrintProfileHeaders();
Sprinter sprinter;
if (!sprinter.init() || !sprinter.put(gcstats::MinorGCProfilePrefix)) {
return;
}
TimeDuration ts = collectionStartTime() - stats().creationTime();
size_t pid = getpid();
JSRuntime* runtime = gc->rt;
TimeDuration timestamp = collectionStartTime() - stats().creationTime();
const char* reasonStr = ExplainGCReason(reason);
double promotionRatePercent = promotionRate * 100;
size_t oldSizeKB = previousGC.nurseryCapacity / 1024;
size_t newSizeKB = capacity() / 1024;
size_t dedupCount = stats().getStat(gcstats::STAT_STRINGS_DEDUPLICATED);
FILE* file = stats().profileFile();
fprintf(
file, "MinorGC: %7zu %14p %10.6f %-20.20s %5.1f%% %6zu %6zu %6" PRIu32,
size_t(getpid()), runtime(), ts.ToSeconds(), JS::ExplainGCReason(reason),
promotionRate * 100, previousGC.nurseryCapacity / 1024, capacity() / 1024,
stats().getStat(gcstats::STAT_STRINGS_DEDUPLICATED));
#define PRINT_FIELD_VALUE(_1, _2, format, value) \
if (!sprinter.jsprintf(" " format, value)) { \
return; \
}
FOR_EACH_NURSERY_PROFILE_METADATA(PRINT_FIELD_VALUE)
#undef PRINT_FIELD_VALUE
printProfileDurations(profileDurations_, sprinter);
fputs(sprinter.string(), stats().profileFile());
printProfileDurations(file, profileDurations_);
}
void js::Nursery::printProfileHeader() {
Sprinter sprinter;
if (!sprinter.init() || !sprinter.put(gcstats::MinorGCProfilePrefix)) {
return;
}
#define PRINT_FIELD_NAME(name, width, _1, _2) \
if (!sprinter.jsprintf(" %-*s", width, name)) { \
return; \
}
FOR_EACH_NURSERY_PROFILE_METADATA(PRINT_FIELD_NAME)
#undef PRINT_FIELD_NAME
#define PRINT_PROFILE_NAME(_1, text) \
if (!sprinter.jsprintf(" %-6.6s", text)) { \
return; \
}
FOR_EACH_NURSERY_PROFILE_TIME(PRINT_PROFILE_NAME)
#undef PRINT_PROFILE_NAME
if (!sprinter.put("\n")) {
return;
}
fputs(sprinter.string(), stats().profileFile());
FILE* file = stats().profileFile();
fprintf(
file,
"MinorGC: PID Runtime Timestamp Reason PRate "
"OldKB NewKB Dedup ");
#define PRINT_HEADER(name, text) fprintf(file, " %-6.6s", text);
FOR_EACH_NURSERY_PROFILE_TIME(PRINT_HEADER)
#undef PRINT_HEADER
fprintf(file, "\n");
}
// static
bool js::Nursery::printProfileDurations(const ProfileDurations& times,
Sprinter& sprinter) {
void js::Nursery::printProfileDurations(FILE* file,
const ProfileDurations& times) {
for (auto time : times) {
if (!sprinter.jsprintf(" %6zu", size_t(time.ToMicroseconds()))) {
return false;
}
fprintf(file, " %6" PRIi64, static_cast<int64_t>(time.ToMicroseconds()));
}
return sprinter.put("\n");
fprintf(file, "\n");
}
void js::Nursery::printTotalProfileTimes() {
@ -1005,31 +950,13 @@ void js::Nursery::printTotalProfileTimes() {
return;
}
Sprinter sprinter;
if (!sprinter.init() || !sprinter.put(gcstats::MinorGCProfilePrefix)) {
return;
}
size_t pid = getpid();
JSRuntime* runtime = gc->rt;
char collections[32];
DebugOnly<int> r = SprintfLiteral(
collections, "TOTALS: %7zu collections:", gc->minorGCCount());
MOZ_ASSERT(r > 0 && r < int(sizeof(collections)));
#define PRINT_FIELD_VALUE(_1, _2, format, value) \
if (!sprinter.jsprintf(" " format, value)) { \
return; \
}
FOR_EACH_NURSERY_PROFILE_TOTALS_METADATA(PRINT_FIELD_VALUE)
#undef PRINT_FIELD_VALUE
if (!printProfileDurations(totalDurations_, sprinter)) {
return;
}
fputs(sprinter.string(), stats().profileFile());
FILE* file = stats().profileFile();
fprintf(file,
"MinorGC: %7zu %14p TOTALS: %7" PRIu64
" collections: %16" PRIu64,
size_t(getpid()), runtime(), gc->stringStats.deduplicatedStrings,
gc->minorGCCount());
printProfileDurations(file, totalDurations_);
}
void js::Nursery::maybeClearProfileDurations() {

Просмотреть файл

@ -60,7 +60,6 @@ class HeapSlot;
class JSONPrinter;
class MapObject;
class SetObject;
class Sprinter;
class TenuringTracer;
namespace gc {
@ -688,8 +687,7 @@ class Nursery {
void maybeClearProfileDurations();
void startProfile(ProfileKey key);
void endProfile(ProfileKey key);
static bool printProfileDurations(const ProfileDurations& times,
Sprinter& sprinter);
static void printProfileDurations(FILE* file, const ProfileDurations& times);
mozilla::TimeStamp collectionStartTime() const;
mozilla::TimeStamp lastCollectionEndTime() const;

Просмотреть файл

@ -21,7 +21,6 @@
#include "util/GetPidProvider.h"
#include "util/Text.h"
#include "vm/JSONPrinter.h"
#include "vm/Printer.h"
#include "vm/Runtime.h"
#include "vm/Time.h"
@ -1550,55 +1549,29 @@ void Statistics::maybePrintProfileHeaders() {
}
}
// The following macros define GC profile metadata fields that are printed
// before the timing information defined by FOR_EACH_GC_PROFILE_TIME.
#define FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
_("PID", 7, "%7zu", pid) \
_("Runtime", 14, "0x%12p", runtime)
#define FOR_EACH_GC_PROFILE_METADATA(_) \
FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
_("Timestamp", 10, "%10.6f", timestamp.ToSeconds()) \
_("Reason", 20, "%-20.20s", reason) \
_("States", 6, "%6s", formatGCStates(slice)) \
_("FSNR", 4, "%4s", formatGCFlags(slice)) \
_("SizeKB", 8, "%8zu", sizeKB) \
_("Budget", 6, "%6s", formatBudget(slice))
#define FOR_EACH_GC_PROFILE_TOTALS_METADATA(_) \
FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
_("SliceCount", 59, "%-59s", formatTotalSlices())
void Statistics::printProfileHeader() {
if (!enableProfiling_) {
return;
}
Sprinter sprinter;
if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
return;
}
FILE* file = profileFile();
fprintf(
file,
"MajorGC: PID Runtime Timestamp Reason States "
"FSNR SizeKB budget total bgwrk ");
#define PRINT_PROFILE_HEADER(name, text, phase) fprintf(file, " %-6.6s", text);
FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_HEADER)
#undef PRINT_PROFILE_HEADER
fprintf(file, "\n");
}
#define PRINT_METADATA_NAME(name, width, _1, _2) \
if (!sprinter.jsprintf(" %-*s", width, name)) { \
return; \
/* static */
void Statistics::printProfileTimes(const ProfileDurations& times) {
FILE* file = profileFile();
for (auto time : times) {
fprintf(file, " %6" PRIi64, static_cast<int64_t>(time.ToMilliseconds()));
}
FOR_EACH_GC_PROFILE_METADATA(PRINT_METADATA_NAME)
#undef PRINT_METADATA_NAME
#define PRINT_PROFILE_NAME(_1, text, _2) \
if (!sprinter.jsprintf(" %-6.6s", text)) { \
return; \
}
FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_NAME)
#undef PRINT_PROFILE_NAME
if (!sprinter.put("\n")) {
return;
}
fputs(sprinter.string(), profileFile());
fprintf(file, "\n");
}
static TimeDuration SumAllPhaseKinds(const Statistics::PhaseKindTimes& times) {
@ -1610,108 +1583,47 @@ static TimeDuration SumAllPhaseKinds(const Statistics::PhaseKindTimes& times) {
}
void Statistics::printSliceProfile() {
const SliceData& slice = slices_.back();
maybePrintProfileHeaders();
const SliceData& slice = slices_.back();
ProfileDurations times = getProfileTimes(slice);
updateTotalProfileTimes(times);
TimeDuration ts = slice.end - creationTime();
Sprinter sprinter;
if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
return;
}
size_t pid = getpid();
JSRuntime* runtime = gc->rt;
TimeDuration timestamp = slice.end - creationTime();
const char* reason = ExplainGCReason(slice.reason);
bool shrinking = gcOptions == JS::GCOptions::Shrink;
bool reset = slice.resetReason != GCAbortReason::None;
bool nonIncremental = nonincrementalReason_ != GCAbortReason::None;
bool full = gc->fullGCRequested;
size_t sizeKB = gc->heapSize.bytes() / 1024;
#define PRINT_FIELD_VALUE(_1, _2, format, value) \
if (!sprinter.jsprintf(" " format, value)) { \
return; \
}
FOR_EACH_GC_PROFILE_METADATA(PRINT_FIELD_VALUE)
#undef PRINT_FIELD_VALUE
FILE* file = profileFile();
fprintf(file,
"MajorGC: %7zu %14p %10.6f %-20.20s %1d -> %1d %1s%1s%1s%1s %6zu",
size_t(getpid()), gc->rt, ts.ToSeconds(),
ExplainGCReason(slice.reason), int(slice.initialState),
int(slice.finalState), full ? "F" : "", shrinking ? "S" : "",
nonIncremental ? "N" : "", reset ? "R" : "", sizeKB);
if (!printProfileTimes(times, sprinter)) {
return;
if (!nonIncremental && !slice.budget.isUnlimited() &&
slice.budget.isTimeBudget()) {
fprintf(file, " %6" PRIi64, slice.budget.timeBudget());
} else {
fprintf(file, " ");
}
fputs(sprinter.string(), profileFile());
}
Statistics::ProfileDurations Statistics::getProfileTimes(
const SliceData& slice) const {
ProfileDurations times;
times[ProfileKey::Total] = slice.duration();
times[ProfileKey::Background] = SumAllPhaseKinds(slice.totalParallelTimes);
totalTimes_[ProfileKey::Total] += times[ProfileKey::Total];
#define GET_PROFILE_TIME(name, text, phase) \
if (phase != PhaseKind::None) { \
times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
} \
times[ProfileKey::Background] = SumAllPhaseKinds(slice.totalParallelTimes);
totalTimes_[ProfileKey::Background] += times[ProfileKey::Background];
#define GET_PROFILE_TIME(name, text, phase) \
times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
totalTimes_[ProfileKey::name] += times[ProfileKey::name];
FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
#undef GET_PROFILE_TIME
return times;
}
void Statistics::updateTotalProfileTimes(const ProfileDurations& times) {
#define UPDATE_PROFILE_TIME(name, _, phase) \
totalTimes_[ProfileKey::name] += times[ProfileKey::name];
FOR_EACH_GC_PROFILE_TIME(UPDATE_PROFILE_TIME)
#undef UPDATE_PROFILE_TIME
}
const char* Statistics::formatGCStates(const SliceData& slice) {
DebugOnly<int> r =
SprintfLiteral(formatBuffer_, "%1d -> %1d", int(slice.initialState),
int(slice.finalState));
MOZ_ASSERT(r > 0 && r < FormatBufferLength);
return formatBuffer_;
}
const char* Statistics::formatGCFlags(const SliceData& slice) {
bool fullGC = gc->fullGCRequested;
bool shrinkingGC = gcOptions == JS::GCOptions::Shrink;
bool nonIncrementalGC = nonincrementalReason_ != GCAbortReason::None;
bool wasReset = slice.resetReason != GCAbortReason::None;
MOZ_ASSERT(FormatBufferLength >= 5);
formatBuffer_[0] = fullGC ? 'F' : ' ';
formatBuffer_[1] = shrinkingGC ? 'S' : ' ';
formatBuffer_[2] = nonIncrementalGC ? 'N' : ' ';
formatBuffer_[3] = wasReset ? 'R' : ' ';
formatBuffer_[4] = '\0';
return formatBuffer_;
}
const char* Statistics::formatBudget(const SliceData& slice) {
if (nonincrementalReason_ != GCAbortReason::None ||
!slice.budget.isTimeBudget()) {
formatBuffer_[0] = '\0';
return formatBuffer_;
}
DebugOnly<int> r =
SprintfLiteral(formatBuffer_, " %6" PRIi64, slice.budget.timeBudget());
MOZ_ASSERT(r > 0 && r < FormatBufferLength);
return formatBuffer_;
}
/* static */
bool Statistics::printProfileTimes(const ProfileDurations& times,
Sprinter& sprinter) {
for (auto time : times) {
if (!sprinter.jsprintf(" %6zu", size_t(time.ToMilliseconds()))) {
return false;
}
}
return sprinter.put("\n");
printProfileTimes(times);
}
void Statistics::printTotalProfileTimes() {
@ -1719,31 +1631,10 @@ void Statistics::printTotalProfileTimes() {
return;
}
Sprinter sprinter;
if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
return;
}
size_t pid = getpid();
JSRuntime* runtime = gc->rt;
#define PRINT_FIELD_VALUE(_1, _2, format, value) \
if (!sprinter.jsprintf(" " format, value)) { \
return; \
}
FOR_EACH_GC_PROFILE_TOTALS_METADATA(PRINT_FIELD_VALUE)
#undef PRINT_FIELD_VALUE
if (!printProfileTimes(totalTimes_, sprinter)) {
return;
}
fputs(sprinter.string(), profileFile());
}
const char* Statistics::formatTotalSlices() {
DebugOnly<int> r =
SprintfLiteral(formatBuffer_, "TOTALS: %7zu slices:", sliceCount_);
MOZ_ASSERT(r > 0 && r < FormatBufferLength);
return formatBuffer_;
FILE* file = profileFile();
fprintf(file,
"MajorGC: %7zu %14p TOTALS: %7" PRIu64
" slices: ",
size_t(getpid()), gc->rt, sliceCount_);
printProfileTimes(totalTimes_);
}

Просмотреть файл

@ -24,7 +24,6 @@
namespace js {
class Sprinter;
class JSONPrinter;
namespace gcstats {
@ -105,8 +104,6 @@ struct Trigger {
};
#define FOR_EACH_GC_PROFILE_TIME(_) \
_(Total, "total", PhaseKind::NONE) \
_(Background, "bgwrk", PhaseKind::NONE) \
_(BeginCallback, "bgnCB", PhaseKind::GC_BEGIN) \
_(MinorForMajor, "evct4m", PhaseKind::EVICT_NURSERY_FOR_MAJOR_GC) \
_(WaitBgThread, "waitBG", PhaseKind::WAIT_BACKGROUND_THREAD) \
@ -118,9 +115,6 @@ struct Trigger {
_(MinorGC, "minor", PhaseKind::MINOR_GC) \
_(EvictNursery, "evict", PhaseKind::EVICT_NURSERY)
static const char* MajorGCProfilePrefix = "MajorGC:";
static const char* MinorGCProfilePrefix = "MinorGC:";
const char* ExplainAbortReason(GCAbortReason reason);
/*
@ -450,9 +444,11 @@ struct Statistics {
/* Profiling data. */
enum class ProfileKey {
#define DEFINE_PROFILE_KEY(name, _1, _2) name,
FOR_EACH_GC_PROFILE_TIME(DEFINE_PROFILE_KEY)
#undef DEFINE_PROFILE_KEY
Total,
Background,
#define DEFINE_TIME_KEY(name, text, phase) name,
FOR_EACH_GC_PROFILE_TIME(DEFINE_TIME_KEY)
#undef DEFINE_TIME_KEY
KeyCount
};
@ -465,9 +461,6 @@ struct Statistics {
ProfileDurations totalTimes_;
uint64_t sliceCount_;
char formatBuffer_[32];
static constexpr int FormatBufferLength = sizeof(formatBuffer_);
JSContext* context();
Phase currentPhase() const;
@ -506,14 +499,7 @@ struct Statistics {
double computeMMU(TimeDuration resolution) const;
void printSliceProfile();
ProfileDurations getProfileTimes(const SliceData& slice) const;
void updateTotalProfileTimes(const ProfileDurations& times);
const char* formatGCStates(const SliceData& slice);
const char* formatGCFlags(const SliceData& slice);
const char* formatBudget(const SliceData& slice);
const char* formatTotalSlices();
static bool printProfileTimes(const ProfileDurations& times,
Sprinter& sprinter);
void printProfileTimes(const ProfileDurations& times);
};
struct MOZ_RAII AutoGCSlice {