1 /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*-
2 * vim: set ts=8 sts=2 et sw=2 tw=80:
3 * This Source Code Form is subject to the terms of the Mozilla Public
4 * License, v. 2.0. If a copy of the MPL was not distributed with this
5 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */
7 #include "gc/Statistics.h"
9 #include "mozilla/DebugOnly.h"
10 #include "mozilla/Sprintf.h"
11 #include "mozilla/TimeStamp.h"
16 #include <type_traits>
19 #include "gc/GCInternals.h"
20 #include "gc/Memory.h"
21 #include "js/Printer.h"
22 #include "util/GetPidProvider.h"
23 #include "util/Text.h"
24 #include "vm/JSONPrinter.h"
25 #include "vm/Runtime.h"
28 #include "gc/PrivateIterators-inl.h"
31 using namespace js::gc
;
32 using namespace js::gcstats
;
34 using mozilla::DebugOnly
;
35 using mozilla::EnumeratedArray
;
37 using mozilla::TimeDuration
;
38 using mozilla::TimeStamp
;
40 static const size_t BYTES_PER_MB
= 1024 * 1024;
43 * If this fails, then you can either delete this assertion and allow all
44 * larger-numbered reasons to pile up in the last telemetry bucket, or switch
45 * to GC_REASON_3 and bump the max value.
47 static_assert(JS::GCReason::NUM_TELEMETRY_REASONS
>= JS::GCReason::NUM_REASONS
);
49 static inline auto AllPhaseKinds() {
50 return mozilla::MakeEnumeratedRange(PhaseKind::FIRST
, PhaseKind::LIMIT
);
53 static inline auto MajorGCPhaseKinds() {
54 return mozilla::MakeEnumeratedRange(PhaseKind::GC_BEGIN
,
55 PhaseKind(size_t(PhaseKind::GC_END
) + 1));
58 static const char* ExplainGCOptions(JS::GCOptions options
) {
60 case JS::GCOptions::Normal
:
62 case JS::GCOptions::Shrink
:
64 case JS::GCOptions::Shutdown
:
68 MOZ_CRASH("Unexpected GCOptions value");
71 JS_PUBLIC_API
const char* JS::ExplainGCReason(JS::GCReason reason
) {
73 #define SWITCH_REASON(name, _) \
74 case JS::GCReason::name: \
76 GCREASONS(SWITCH_REASON
)
79 case JS::GCReason::NO_REASON
:
83 MOZ_CRASH("bad GC reason");
87 JS_PUBLIC_API
bool JS::InternalGCReason(JS::GCReason reason
) {
88 return reason
< JS::GCReason::FIRST_FIREFOX_REASON
;
91 const char* js::gcstats::ExplainAbortReason(GCAbortReason reason
) {
93 #define SWITCH_REASON(name, _) \
94 case GCAbortReason::name: \
96 GC_ABORT_REASONS(SWITCH_REASON
)
99 MOZ_CRASH("bad GC abort reason");
104 static FILE* MaybeOpenFileFromEnv(const char* env
,
105 FILE* defaultFile
= nullptr) {
106 const char* value
= getenv(env
);
112 if (strcmp(value
, "none") == 0) {
114 } else if (strcmp(value
, "stdout") == 0) {
116 } else if (strcmp(value
, "stderr") == 0) {
120 if (value
[0] != '/') {
121 const char* dir
= getenv("MOZ_UPLOAD_DIR");
123 SprintfLiteral(path
, "%s/%s", dir
, value
);
128 file
= fopen(value
, "a");
129 if (!file
|| setvbuf(file
, nullptr, _IOLBF
, 256) != 0) {
130 perror("Error opening log file");
131 MOZ_CRASH("Failed to open log file.");
138 struct PhaseKindInfo
{
140 uint8_t telemetryBucket
;
144 // PhaseInfo objects form a tree.
149 Phase nextWithPhaseKind
;
156 // A table of PhaseInfo indexed by Phase.
157 using PhaseTable
= EnumeratedArray
<Phase
, Phase::LIMIT
, PhaseInfo
>;
159 // A table of PhaseKindInfo indexed by PhaseKind.
160 using PhaseKindTable
=
161 EnumeratedArray
<PhaseKind
, PhaseKind::LIMIT
, PhaseKindInfo
>;
163 #include "gc/StatsPhasesGenerated.inc"
165 // Iterate the phases in a phase kind.
170 explicit PhaseIter(PhaseKind kind
) : phase(phaseKinds
[kind
].firstPhase
) {}
171 bool done() const { return phase
== Phase::NONE
; }
172 void next() { phase
= phases
[phase
].nextWithPhaseKind
; }
173 Phase
get() const { return phase
; }
174 operator Phase() const { return phase
; }
177 static double t(TimeDuration duration
) { return duration
.ToMilliseconds(); }
179 static TimeDuration
TimeBetween(TimeStamp start
, TimeStamp end
) {
181 MOZ_ASSERT(end
>= start
);
183 // Sadly this happens sometimes.
185 return TimeDuration::Zero();
191 inline JSContext
* Statistics::context() {
192 return gc
->rt
->mainContextFromOwnThread();
195 inline Phase
Statistics::currentPhase() const {
196 return phaseStack
.empty() ? Phase::NONE
: phaseStack
.back();
199 PhaseKind
Statistics::currentPhaseKind() const {
200 // Public API to get the current phase kind, suppressing the synthetic
201 // PhaseKind::MUTATOR phase.
203 Phase phase
= currentPhase();
204 MOZ_ASSERT_IF(phase
== Phase::MUTATOR
, phaseStack
.length() == 1);
205 if (phase
== Phase::NONE
|| phase
== Phase::MUTATOR
) {
206 return PhaseKind::NONE
;
209 return phases
[phase
].phaseKind
;
212 static Phase
LookupPhaseWithParent(PhaseKind phaseKind
, Phase parentPhase
) {
213 for (PhaseIter
phase(phaseKind
); !phase
.done(); phase
.next()) {
214 if (phases
[phase
].parent
== parentPhase
) {
222 static const char* PhaseKindName(PhaseKind kind
) {
223 if (kind
== PhaseKind::NONE
) {
227 return phaseKinds
[kind
].name
;
230 Phase
Statistics::lookupChildPhase(PhaseKind phaseKind
) const {
231 if (phaseKind
== PhaseKind::IMPLICIT_SUSPENSION
) {
232 return Phase::IMPLICIT_SUSPENSION
;
234 if (phaseKind
== PhaseKind::EXPLICIT_SUSPENSION
) {
235 return Phase::EXPLICIT_SUSPENSION
;
238 MOZ_ASSERT(phaseKind
< PhaseKind::LIMIT
);
240 // Search all expanded phases that correspond to the required
241 // phase to find the one whose parent is the current expanded phase.
242 Phase phase
= LookupPhaseWithParent(phaseKind
, currentPhase());
244 if (phase
== Phase::NONE
) {
245 MOZ_CRASH_UNSAFE_PRINTF(
246 "Child phase kind %s not found under current phase kind %s",
247 PhaseKindName(phaseKind
), PhaseKindName(currentPhaseKind()));
253 inline auto AllPhases() {
254 return mozilla::MakeEnumeratedRange(Phase::FIRST
, Phase::LIMIT
);
257 void Statistics::gcDuration(TimeDuration
* total
, TimeDuration
* maxPause
) const {
258 *total
= *maxPause
= TimeDuration::Zero();
259 for (const auto& slice
: slices_
) {
260 *total
+= slice
.duration();
261 if (slice
.duration() > *maxPause
) {
262 *maxPause
= slice
.duration();
265 if (*maxPause
> maxPauseInInterval
) {
266 maxPauseInInterval
= *maxPause
;
270 void Statistics::sccDurations(TimeDuration
* total
,
271 TimeDuration
* maxPause
) const {
272 *total
= *maxPause
= TimeDuration::Zero();
273 for (const auto& duration
: sccTimes
) {
275 *maxPause
= std::max(*maxPause
, duration
);
279 using FragmentVector
= Vector
<UniqueChars
, 8, SystemAllocPolicy
>;
281 static UniqueChars
Join(const FragmentVector
& fragments
,
282 const char* separator
= "") {
283 const size_t separatorLength
= strlen(separator
);
285 for (size_t i
= 0; i
< fragments
.length(); ++i
) {
286 length
+= fragments
[i
] ? strlen(fragments
[i
].get()) : 0;
287 if (i
< (fragments
.length() - 1)) {
288 length
+= separatorLength
;
292 char* joined
= js_pod_malloc
<char>(length
+ 1);
294 return UniqueChars();
297 joined
[length
] = '\0';
298 char* cursor
= joined
;
299 for (size_t i
= 0; i
< fragments
.length(); ++i
) {
301 strcpy(cursor
, fragments
[i
].get());
303 cursor
+= fragments
[i
] ? strlen(fragments
[i
].get()) : 0;
304 if (i
< (fragments
.length() - 1)) {
305 if (separatorLength
) {
306 strcpy(cursor
, separator
);
308 cursor
+= separatorLength
;
312 return UniqueChars(joined
);
315 static TimeDuration
SumChildTimes(Phase phase
,
316 const Statistics::PhaseTimes
& phaseTimes
) {
318 for (phase
= phases
[phase
].firstChild
; phase
!= Phase::NONE
;
319 phase
= phases
[phase
].nextSibling
) {
320 total
+= phaseTimes
[phase
];
325 UniqueChars
Statistics::formatCompactSliceMessage() const {
326 // Skip if we OOM'ed.
327 if (slices_
.length() == 0) {
328 return UniqueChars(nullptr);
331 const size_t index
= slices_
.length() - 1;
332 const SliceData
& slice
= slices_
.back();
334 char budgetDescription
[200];
335 slice
.budget
.describe(budgetDescription
, sizeof(budgetDescription
) - 1);
338 "GC Slice %u - Pause: %.3fms of %s budget (@ %.3fms); Reason: %s; Reset: "
341 SprintfLiteral(buffer
, format
, index
, t(slice
.duration()), budgetDescription
,
342 t(slice
.start
- slices_
[0].start
),
343 ExplainGCReason(slice
.reason
),
344 slice
.wasReset() ? "yes - " : "no",
345 slice
.wasReset() ? ExplainAbortReason(slice
.resetReason
) : "");
347 FragmentVector fragments
;
348 if (!fragments
.append(DuplicateString(buffer
)) ||
350 formatCompactSlicePhaseTimes(slices_
[index
].phaseTimes
))) {
351 return UniqueChars(nullptr);
353 return Join(fragments
);
356 UniqueChars
Statistics::formatCompactSummaryMessage() const {
357 FragmentVector fragments
;
358 if (!fragments
.append(DuplicateString("Summary - "))) {
359 return UniqueChars(nullptr);
362 TimeDuration total
, longest
;
363 gcDuration(&total
, &longest
);
365 const double mmu20
= computeMMU(TimeDuration::FromMilliseconds(20));
366 const double mmu50
= computeMMU(TimeDuration::FromMilliseconds(50));
369 if (!nonincremental()) {
370 SprintfLiteral(buffer
,
371 "Max Pause: %.3fms; MMU 20ms: %.1f%%; MMU 50ms: %.1f%%; "
373 t(longest
), mmu20
* 100., mmu50
* 100., t(total
));
375 SprintfLiteral(buffer
, "Non-Incremental: %.3fms (%s); ", t(total
),
376 ExplainAbortReason(nonincrementalReason_
));
378 if (!fragments
.append(DuplicateString(buffer
))) {
379 return UniqueChars(nullptr);
382 SprintfLiteral(buffer
,
383 "Zones: %zu of %zu (-%zu); Compartments: %zu of %zu (-%zu); "
384 "HeapSize: %.3f MiB; "
385 "HeapChange (abs): %+d (%u); ",
386 zoneStats
.collectedZoneCount
, zoneStats
.zoneCount
,
387 zoneStats
.sweptZoneCount
, zoneStats
.collectedCompartmentCount
,
388 zoneStats
.compartmentCount
, zoneStats
.sweptCompartmentCount
,
389 double(preTotalHeapBytes
) / BYTES_PER_MB
,
390 int32_t(counts
[COUNT_NEW_CHUNK
] - counts
[COUNT_DESTROY_CHUNK
]),
391 counts
[COUNT_NEW_CHUNK
] + counts
[COUNT_DESTROY_CHUNK
]);
392 if (!fragments
.append(DuplicateString(buffer
))) {
393 return UniqueChars(nullptr);
396 MOZ_ASSERT_IF(counts
[COUNT_ARENA_RELOCATED
],
397 gcOptions
== JS::GCOptions::Shrink
);
398 if (gcOptions
== JS::GCOptions::Shrink
) {
400 buffer
, "Kind: %s; Relocated: %.3f MiB; ", ExplainGCOptions(gcOptions
),
401 double(ArenaSize
* counts
[COUNT_ARENA_RELOCATED
]) / BYTES_PER_MB
);
402 if (!fragments
.append(DuplicateString(buffer
))) {
403 return UniqueChars(nullptr);
407 return Join(fragments
);
410 UniqueChars
Statistics::formatCompactSlicePhaseTimes(
411 const PhaseTimes
& phaseTimes
) const {
412 static const TimeDuration MaxUnaccountedTime
=
413 TimeDuration::FromMicroseconds(100);
415 FragmentVector fragments
;
417 for (auto phase
: AllPhases()) {
418 DebugOnly
<uint8_t> level
= phases
[phase
].depth
;
419 MOZ_ASSERT(level
< 4);
421 TimeDuration ownTime
= phaseTimes
[phase
];
422 TimeDuration childTime
= SumChildTimes(phase
, phaseTimes
);
423 if (ownTime
> MaxUnaccountedTime
) {
424 SprintfLiteral(buffer
, "%s: %.3fms", phases
[phase
].name
, t(ownTime
));
425 if (!fragments
.append(DuplicateString(buffer
))) {
426 return UniqueChars(nullptr);
429 if (childTime
&& (ownTime
- childTime
) > MaxUnaccountedTime
) {
430 MOZ_ASSERT(level
< 3);
431 SprintfLiteral(buffer
, "%s: %.3fms", "Other", t(ownTime
- childTime
));
432 if (!fragments
.append(DuplicateString(buffer
))) {
433 return UniqueChars(nullptr);
438 return Join(fragments
, ", ");
441 UniqueChars
Statistics::formatDetailedMessage() const {
442 FragmentVector fragments
;
444 if (!fragments
.append(formatDetailedDescription())) {
445 return UniqueChars(nullptr);
448 if (!slices_
.empty()) {
449 for (unsigned i
= 0; i
< slices_
.length(); i
++) {
450 if (!fragments
.append(formatDetailedSliceDescription(i
, slices_
[i
]))) {
451 return UniqueChars(nullptr);
453 if (!fragments
.append(formatDetailedPhaseTimes(slices_
[i
].phaseTimes
))) {
454 return UniqueChars(nullptr);
458 if (!fragments
.append(formatDetailedTotals())) {
459 return UniqueChars(nullptr);
461 if (!fragments
.append(formatDetailedPhaseTimes(phaseTimes
))) {
462 return UniqueChars(nullptr);
465 return Join(fragments
);
468 UniqueChars
Statistics::formatDetailedDescription() const {
469 TimeDuration sccTotal
, sccLongest
;
470 sccDurations(&sccTotal
, &sccLongest
);
472 const double mmu20
= computeMMU(TimeDuration::FromMilliseconds(20));
473 const double mmu50
= computeMMU(TimeDuration::FromMilliseconds(50));
476 "=================================================================\n\
477 Invocation Kind: %s\n\
480 Zones Collected: %d of %d (-%d)\n\
481 Compartments Collected: %d of %d (-%d)\n\
482 MinorGCs since last GC: %d\n\
483 Store Buffer Overflows: %d\n\
484 MMU 20ms:%.1f%%; 50ms:%.1f%%\n\
485 SCC Sweep Total (MaxPause): %.3fms (%.3fms)\n\
486 HeapSize: %.3f MiB\n\
487 Chunk Delta (magnitude): %+d (%d)\n\
488 Arenas Relocated: %.3f MiB\n\
493 buffer
, format
, ExplainGCOptions(gcOptions
),
494 ExplainGCReason(slices_
[0].reason
), nonincremental() ? "no - " : "yes",
495 nonincremental() ? ExplainAbortReason(nonincrementalReason_
) : "",
496 zoneStats
.collectedZoneCount
, zoneStats
.zoneCount
,
497 zoneStats
.sweptZoneCount
, zoneStats
.collectedCompartmentCount
,
498 zoneStats
.compartmentCount
, zoneStats
.sweptCompartmentCount
,
499 getCount(COUNT_MINOR_GC
), getCount(COUNT_STOREBUFFER_OVERFLOW
),
500 mmu20
* 100., mmu50
* 100., t(sccTotal
), t(sccLongest
),
501 double(preTotalHeapBytes
) / BYTES_PER_MB
,
502 getCount(COUNT_NEW_CHUNK
) - getCount(COUNT_DESTROY_CHUNK
),
503 getCount(COUNT_NEW_CHUNK
) + getCount(COUNT_DESTROY_CHUNK
),
504 double(ArenaSize
* getCount(COUNT_ARENA_RELOCATED
)) / BYTES_PER_MB
);
506 return DuplicateString(buffer
);
509 UniqueChars
Statistics::formatDetailedSliceDescription(
510 unsigned i
, const SliceData
& slice
) const {
511 char budgetDescription
[200];
512 slice
.budget
.describe(budgetDescription
, sizeof(budgetDescription
) - 1);
516 ---- Slice %u ----\n\
521 Page Faults: %" PRIu64
523 Pause: %.3fms of %s budget (@ %.3fms)\n\
526 char triggerBuffer
[100] = "n/a";
528 Trigger trigger
= slice
.trigger
.value();
529 SprintfLiteral(triggerBuffer
, "%.3f MiB of %.3f MiB threshold\n",
530 double(trigger
.amount
) / BYTES_PER_MB
,
531 double(trigger
.threshold
) / BYTES_PER_MB
);
536 buffer
, format
, i
, ExplainGCReason(slice
.reason
), triggerBuffer
,
537 slice
.wasReset() ? "yes - " : "no",
538 slice
.wasReset() ? ExplainAbortReason(slice
.resetReason
) : "",
539 gc::StateName(slice
.initialState
), gc::StateName(slice
.finalState
),
540 uint64_t(slice
.endFaults
- slice
.startFaults
), t(slice
.duration()),
541 budgetDescription
, t(slice
.start
- slices_
[0].start
));
542 return DuplicateString(buffer
);
545 static bool IncludePhase(TimeDuration duration
) {
546 // Don't include durations that will print as "0.000ms".
547 return duration
.ToMilliseconds() >= 0.001;
550 UniqueChars
Statistics::formatDetailedPhaseTimes(
551 const PhaseTimes
& phaseTimes
) const {
552 static const TimeDuration MaxUnaccountedChildTime
=
553 TimeDuration::FromMicroseconds(50);
555 FragmentVector fragments
;
557 for (auto phase
: AllPhases()) {
558 uint8_t level
= phases
[phase
].depth
;
559 TimeDuration ownTime
= phaseTimes
[phase
];
560 TimeDuration childTime
= SumChildTimes(phase
, phaseTimes
);
561 if (IncludePhase(ownTime
)) {
562 SprintfLiteral(buffer
, " %*s%s: %.3fms\n", level
* 2, "",
563 phases
[phase
].name
, t(ownTime
));
564 if (!fragments
.append(DuplicateString(buffer
))) {
565 return UniqueChars(nullptr);
568 if (childTime
&& (ownTime
- childTime
) > MaxUnaccountedChildTime
) {
569 SprintfLiteral(buffer
, " %*s%s: %.3fms\n", (level
+ 1) * 2, "",
570 "Other", t(ownTime
- childTime
));
571 if (!fragments
.append(DuplicateString(buffer
))) {
572 return UniqueChars(nullptr);
577 return Join(fragments
);
580 UniqueChars
Statistics::formatDetailedTotals() const {
581 TimeDuration total
, longest
;
582 gcDuration(&total
, &longest
);
587 Total Time: %.3fms\n\
591 SprintfLiteral(buffer
, format
, t(total
), t(longest
));
592 return DuplicateString(buffer
);
595 void Statistics::formatJsonSlice(size_t sliceNum
, JSONPrinter
& json
) const {
597 * We number each of the slice properties to keep the code in
598 * GCTelemetry.jsm in sync. See MAX_SLICE_KEYS.
601 formatJsonSliceDescription(sliceNum
, slices_
[sliceNum
], json
); // # 1-11
603 json
.beginObjectProperty("times"); // # 12
604 formatJsonPhaseTimes(slices_
[sliceNum
].phaseTimes
, json
);
610 UniqueChars
Statistics::renderJsonSlice(size_t sliceNum
) const {
611 Sprinter
printer(nullptr, false);
612 if (!printer
.init()) {
613 return UniqueChars(nullptr);
615 JSONPrinter
json(printer
, false);
617 formatJsonSlice(sliceNum
, json
);
618 return printer
.release();
621 UniqueChars
Statistics::renderNurseryJson() const {
622 Sprinter
printer(nullptr, false);
623 if (!printer
.init()) {
624 return UniqueChars(nullptr);
626 JSONPrinter
json(printer
, false);
627 gc
->nursery().renderProfileJSON(json
);
628 return printer
.release();
632 void Statistics::log(const char* fmt
, ...) {
636 TimeDuration sinceStart
=
637 TimeBetween(TimeStamp::FirstTimeStamp(), TimeStamp::Now());
638 fprintf(gcDebugFile
, "%12.3f: ", sinceStart
.ToMicroseconds());
639 vfprintf(gcDebugFile
, fmt
, args
);
640 fprintf(gcDebugFile
, "\n");
647 UniqueChars
Statistics::renderJsonMessage() const {
649 * The format of the JSON message is specified by the GCMajorMarkerPayload
650 * type in profiler.firefox.com
651 * https://github.com/firefox-devtools/profiler/blob/master/src/types/markers.js#L62
653 * All the properties listed here are created within the timings property
654 * of the GCMajor marker.
657 return DuplicateString("{status:\"aborted\"}"); // May return nullptr
660 Sprinter
printer(nullptr, false);
661 if (!printer
.init()) {
662 return UniqueChars(nullptr);
664 JSONPrinter
json(printer
, false);
667 json
.property("status", "completed");
668 formatJsonDescription(json
);
670 json
.beginObjectProperty("totals");
671 formatJsonPhaseTimes(phaseTimes
, json
);
676 return printer
.release();
679 void Statistics::formatJsonDescription(JSONPrinter
& json
) const {
680 // If you change JSON properties here, please update:
682 // https://github.com/firefox-devtools/profiler
684 TimeDuration total
, longest
;
685 gcDuration(&total
, &longest
);
686 json
.property("max_pause", longest
, JSONPrinter::MILLISECONDS
);
687 json
.property("total_time", total
, JSONPrinter::MILLISECONDS
);
688 // We might be able to omit reason if profiler.firefox.com was able to retrive
689 // it from the first slice. But it doesn't do this yet.
690 json
.property("reason", ExplainGCReason(slices_
[0].reason
));
691 json
.property("zones_collected", zoneStats
.collectedZoneCount
);
692 json
.property("total_zones", zoneStats
.zoneCount
);
693 json
.property("total_compartments", zoneStats
.compartmentCount
);
694 json
.property("minor_gcs", getCount(COUNT_MINOR_GC
));
695 json
.property("minor_gc_number", gc
->minorGCCount());
696 json
.property("major_gc_number", gc
->majorGCCount());
697 uint32_t storebufferOverflows
= getCount(COUNT_STOREBUFFER_OVERFLOW
);
698 if (storebufferOverflows
) {
699 json
.property("store_buffer_overflows", storebufferOverflows
);
701 json
.property("slices", slices_
.length());
703 const double mmu20
= computeMMU(TimeDuration::FromMilliseconds(20));
704 const double mmu50
= computeMMU(TimeDuration::FromMilliseconds(50));
705 json
.property("mmu_20ms", int(mmu20
* 100));
706 json
.property("mmu_50ms", int(mmu50
* 100));
708 TimeDuration sccTotal
, sccLongest
;
709 sccDurations(&sccTotal
, &sccLongest
);
710 json
.property("scc_sweep_total", sccTotal
, JSONPrinter::MILLISECONDS
);
711 json
.property("scc_sweep_max_pause", sccLongest
, JSONPrinter::MILLISECONDS
);
713 if (nonincrementalReason_
!= GCAbortReason::None
) {
714 json
.property("nonincremental_reason",
715 ExplainAbortReason(nonincrementalReason_
));
717 json
.property("allocated_bytes", preTotalHeapBytes
);
718 json
.property("post_heap_size", postTotalHeapBytes
);
720 uint32_t addedChunks
= getCount(COUNT_NEW_CHUNK
);
722 json
.property("added_chunks", addedChunks
);
724 uint32_t removedChunks
= getCount(COUNT_DESTROY_CHUNK
);
726 json
.property("removed_chunks", removedChunks
);
728 json
.property("major_gc_number", startingMajorGCNumber
);
729 json
.property("minor_gc_number", startingMinorGCNumber
);
730 json
.property("slice_number", startingSliceNumber
);
733 void Statistics::formatJsonSliceDescription(unsigned i
, const SliceData
& slice
,
734 JSONPrinter
& json
) const {
735 // If you change JSON properties here, please update:
737 // https://github.com/firefox-devtools/profiler
739 char budgetDescription
[200];
740 slice
.budget
.describe(budgetDescription
, sizeof(budgetDescription
) - 1);
741 TimeStamp originTime
= TimeStamp::ProcessCreation();
743 json
.property("slice", i
);
744 json
.property("pause", slice
.duration(), JSONPrinter::MILLISECONDS
);
745 json
.property("reason", ExplainGCReason(slice
.reason
));
746 json
.property("initial_state", gc::StateName(slice
.initialState
));
747 json
.property("final_state", gc::StateName(slice
.finalState
));
748 json
.property("budget", budgetDescription
);
749 json
.property("major_gc_number", startingMajorGCNumber
);
751 Trigger trigger
= slice
.trigger
.value();
752 json
.property("trigger_amount", trigger
.amount
);
753 json
.property("trigger_threshold", trigger
.threshold
);
755 MOZ_ASSERT(slice
.endFaults
>= slice
.startFaults
);
756 size_t numFaults
= slice
.endFaults
- slice
.startFaults
;
757 if (numFaults
!= 0) {
758 json
.property("page_faults", numFaults
);
760 json
.property("start_timestamp", TimeBetween(originTime
, slice
.start
),
761 JSONPrinter::SECONDS
);
764 void Statistics::formatJsonPhaseTimes(const PhaseTimes
& phaseTimes
,
765 JSONPrinter
& json
) const {
766 for (auto phase
: AllPhases()) {
767 TimeDuration ownTime
= phaseTimes
[phase
];
768 if (!ownTime
.IsZero()) {
769 json
.property(phases
[phase
].path
, ownTime
, JSONPrinter::MILLISECONDS
);
774 Statistics::Statistics(GCRuntime
* gc
)
776 gcTimerFile(nullptr),
777 gcDebugFile(nullptr),
778 nonincrementalReason_(GCAbortReason::None
),
779 creationTime_(TimeStamp::Now()),
780 tenuredAllocsSinceMinorGC(0),
781 preTotalHeapBytes(0),
782 postTotalHeapBytes(0),
783 preCollectedHeapBytes(0),
784 startingMinorGCNumber(0),
785 startingMajorGCNumber(0),
786 startingSliceNumber(0),
787 sliceCallback(nullptr),
789 enableProfiling_(false),
791 for (auto& count
: counts
) {
795 for (auto& stat
: stats
) {
800 for (const auto& duration
: totalTimes_
) {
801 using ElementType
= std::remove_reference_t
<decltype(duration
)>;
802 static_assert(!std::is_trivially_constructible_v
<ElementType
>,
803 "Statistics::Statistics will only initialize "
804 "totalTimes_'s elements if their default constructor is "
806 MOZ_ASSERT(duration
.IsZero(),
807 "totalTimes_ default-initialization should have "
808 "default-initialized every element of totalTimes_ to zero");
812 MOZ_ALWAYS_TRUE(phaseStack
.reserve(MAX_PHASE_NESTING
));
813 MOZ_ALWAYS_TRUE(suspendedPhases
.reserve(MAX_SUSPENDED_PHASES
));
815 gcTimerFile
= MaybeOpenFileFromEnv("MOZ_GCTIMER");
816 gcDebugFile
= MaybeOpenFileFromEnv("JS_GC_DEBUG");
817 gcProfileFile
= MaybeOpenFileFromEnv("JS_GC_PROFILE_FILE", stderr
);
819 gc::ReadProfileEnv("JS_GC_PROFILE",
820 "Report major GCs taking more than N milliseconds for "
821 "all or just the main runtime\n",
822 &enableProfiling_
, &profileWorkers_
, &profileThreshold_
);
825 Statistics::~Statistics() {
826 if (gcTimerFile
&& gcTimerFile
!= stdout
&& gcTimerFile
!= stderr
) {
829 if (gcDebugFile
&& gcDebugFile
!= stdout
&& gcDebugFile
!= stderr
) {
835 bool Statistics::initialize() {
837 // Sanity check generated tables.
838 for (auto i
: AllPhases()) {
839 auto parent
= phases
[i
].parent
;
840 if (parent
!= Phase::NONE
) {
841 MOZ_ASSERT(phases
[i
].depth
== phases
[parent
].depth
+ 1);
843 auto firstChild
= phases
[i
].firstChild
;
844 if (firstChild
!= Phase::NONE
) {
845 MOZ_ASSERT(i
== phases
[firstChild
].parent
);
846 MOZ_ASSERT(phases
[i
].depth
== phases
[firstChild
].depth
- 1);
848 auto nextSibling
= phases
[i
].nextSibling
;
849 if (nextSibling
!= Phase::NONE
) {
850 MOZ_ASSERT(parent
== phases
[nextSibling
].parent
);
851 MOZ_ASSERT(phases
[i
].depth
== phases
[nextSibling
].depth
);
853 auto nextWithPhaseKind
= phases
[i
].nextWithPhaseKind
;
854 if (nextWithPhaseKind
!= Phase::NONE
) {
855 MOZ_ASSERT(phases
[i
].phaseKind
== phases
[nextWithPhaseKind
].phaseKind
);
856 MOZ_ASSERT(parent
!= phases
[nextWithPhaseKind
].parent
);
859 for (auto i
: AllPhaseKinds()) {
860 MOZ_ASSERT(phases
[phaseKinds
[i
].firstPhase
].phaseKind
== i
);
861 for (auto j
: AllPhaseKinds()) {
862 MOZ_ASSERT_IF(i
!= j
, phaseKinds
[i
].telemetryBucket
!=
863 phaseKinds
[j
].telemetryBucket
);
871 JS::GCSliceCallback
Statistics::setSliceCallback(
872 JS::GCSliceCallback newCallback
) {
873 JS::GCSliceCallback oldCallback
= sliceCallback
;
874 sliceCallback
= newCallback
;
878 TimeDuration
Statistics::clearMaxGCPauseAccumulator() {
879 TimeDuration prior
= maxPauseInInterval
;
880 maxPauseInInterval
= TimeDuration::Zero();
884 TimeDuration
Statistics::getMaxGCPauseSinceClear() {
885 return maxPauseInInterval
;
888 // Sum up the time for a phase, including instances of the phase with different
890 static TimeDuration
SumPhase(PhaseKind phaseKind
,
891 const Statistics::PhaseTimes
& times
) {
893 for (PhaseIter
phase(phaseKind
); !phase
.done(); phase
.next()) {
899 static bool CheckSelfTime(Phase parent
, Phase child
,
900 const Statistics::PhaseTimes
& times
,
901 const Statistics::PhaseTimes
& selfTimes
,
902 TimeDuration childTime
) {
903 if (selfTimes
[parent
] < childTime
) {
906 "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
907 phases
[parent
].name
, times
[parent
].ToMilliseconds(),
908 selfTimes
[parent
].ToMilliseconds(), phases
[child
].name
,
909 childTime
.ToMilliseconds());
917 static PhaseKind
FindLongestPhaseKind(const Statistics::PhaseKindTimes
& times
) {
918 TimeDuration longestTime
;
919 PhaseKind phaseKind
= PhaseKind::NONE
;
920 for (auto i
: MajorGCPhaseKinds()) {
921 if (times
[i
] > longestTime
) {
922 longestTime
= times
[i
];
930 static PhaseKind
LongestPhaseSelfTimeInMajorGC(
931 const Statistics::PhaseTimes
& times
) {
932 // Start with total times per expanded phase, including children's times.
933 Statistics::PhaseTimes
selfTimes(times
);
935 // We have the total time spent in each phase, including descendant times.
936 // Loop over the children and subtract their times from their parent's self
938 for (auto i
: AllPhases()) {
939 Phase parent
= phases
[i
].parent
;
940 if (parent
!= Phase::NONE
) {
941 bool ok
= CheckSelfTime(parent
, i
, times
, selfTimes
, times
[i
]);
943 // This happens very occasionally in release builds and frequently
944 // in Windows debug builds. Skip collecting longest phase telemetry
947 MOZ_ASSERT(ok
, "Inconsistent time data; see bug 1400153");
950 return PhaseKind::NONE
;
953 selfTimes
[parent
] -= times
[i
];
957 // Sum expanded phases corresponding to the same phase.
958 Statistics::PhaseKindTimes phaseKindTimes
;
959 for (auto i
: AllPhaseKinds()) {
960 phaseKindTimes
[i
] = SumPhase(i
, selfTimes
);
963 return FindLongestPhaseKind(phaseKindTimes
);
966 void Statistics::printStats() {
969 "OOM during GC statistics collection. The report is unavailable "
972 UniqueChars msg
= formatDetailedMessage();
974 double secSinceStart
=
975 TimeBetween(TimeStamp::ProcessCreation(), slices_
[0].start
)
977 fprintf(gcTimerFile
, "GC(T+%.3fs) %s\n", secSinceStart
, msg
.get());
983 void Statistics::beginGC(JS::GCOptions options
, const TimeStamp
& currentTime
) {
984 slices_
.clearAndFree();
985 sccTimes
.clearAndFree();
987 nonincrementalReason_
= GCAbortReason::None
;
989 preTotalHeapBytes
= gc
->heapSize
.bytes();
991 preCollectedHeapBytes
= 0;
993 startingMajorGCNumber
= gc
->majorGCCount();
994 startingSliceNumber
= gc
->gcNumber();
996 if (gc
->lastGCEndTime()) {
997 timeSinceLastGC
= TimeBetween(gc
->lastGCEndTime(), currentTime
);
1000 totalGCTime_
= TimeDuration::Zero();
1003 void Statistics::measureInitialHeapSize() {
1004 MOZ_ASSERT(preCollectedHeapBytes
== 0);
1005 for (GCZonesIter
zone(gc
); !zone
.done(); zone
.next()) {
1006 preCollectedHeapBytes
+= zone
->gcHeapSize
.bytes();
1010 void Statistics::endGC() {
1011 postTotalHeapBytes
= gc
->heapSize
.bytes();
1016 TimeDuration
Statistics::sumTotalParallelTime(PhaseKind phaseKind
) const {
1018 for (const SliceData
& slice
: slices_
) {
1019 total
+= slice
.totalParallelTimes
[phaseKind
];
1024 void Statistics::sendGCTelemetry() {
1025 JSRuntime
* runtime
= gc
->rt
;
1026 // NOTE: "Compartmental" is term that was deprecated with the
1027 // introduction of zone-based GC, but the old telemetry probe
1028 // continues to be used.
1029 runtime
->metrics().GC_IS_COMPARTMENTAL(!gc
->fullGCRequested
);
1030 runtime
->metrics().GC_ZONE_COUNT(zoneStats
.zoneCount
);
1031 runtime
->metrics().GC_ZONES_COLLECTED(zoneStats
.collectedZoneCount
);
1033 TimeDuration prepareTotal
= phaseTimes
[Phase::PREPARE
];
1034 TimeDuration markTotal
= SumPhase(PhaseKind::MARK
, phaseTimes
);
1035 TimeDuration markRootsTotal
= SumPhase(PhaseKind::MARK_ROOTS
, phaseTimes
);
1037 // Gray and weak marking time is counted under MARK_WEAK and not MARK_GRAY.
1038 TimeDuration markWeakTotal
= SumPhase(PhaseKind::MARK_WEAK
, phaseTimes
);
1039 TimeDuration markGrayNotWeak
=
1040 SumPhase(PhaseKind::MARK_GRAY
, phaseTimes
) +
1041 SumPhase(PhaseKind::MARK_INCOMING_GRAY
, phaseTimes
);
1042 TimeDuration markGrayWeak
= SumPhase(PhaseKind::MARK_GRAY_WEAK
, phaseTimes
);
1043 TimeDuration markGrayTotal
= markGrayNotWeak
+ markGrayWeak
;
1044 TimeDuration markNotGrayOrWeak
= markTotal
- markGrayNotWeak
- markWeakTotal
;
1045 if (markNotGrayOrWeak
< TimeDuration::FromMilliseconds(0)) {
1046 markNotGrayOrWeak
= TimeDuration::Zero();
1049 size_t markCount
= getCount(COUNT_CELLS_MARKED
);
1051 runtime
->metrics().GC_PREPARE_MS(prepareTotal
);
1052 runtime
->metrics().GC_MARK_MS(markNotGrayOrWeak
);
1053 if (markTotal
>= TimeDuration::FromMicroseconds(1)) {
1054 double markRate
= double(markCount
) / t(markTotal
);
1055 runtime
->metrics().GC_MARK_RATE_2(uint32_t(markRate
));
1057 runtime
->metrics().GC_SWEEP_MS(phaseTimes
[Phase::SWEEP
]);
1058 if (gc
->didCompactZones()) {
1059 runtime
->metrics().GC_COMPACT_MS(phaseTimes
[Phase::COMPACT
]);
1061 runtime
->metrics().GC_MARK_ROOTS_US(markRootsTotal
);
1062 runtime
->metrics().GC_MARK_GRAY_MS_2(markGrayTotal
);
1063 runtime
->metrics().GC_MARK_WEAK_MS(markWeakTotal
);
1064 runtime
->metrics().GC_NON_INCREMENTAL(nonincremental());
1065 if (nonincremental()) {
1066 runtime
->metrics().GC_NON_INCREMENTAL_REASON(
1067 uint32_t(nonincrementalReason_
));
1071 // Reset happens non-incrementally, so only the last slice can be reset.
1072 for (size_t i
= 0; i
< slices_
.length() - 1; i
++) {
1073 MOZ_ASSERT(!slices_
[i
].wasReset());
1076 const auto& lastSlice
= slices_
.back();
1077 runtime
->metrics().GC_RESET(lastSlice
.wasReset());
1078 if (lastSlice
.wasReset()) {
1079 runtime
->metrics().GC_RESET_REASON(uint32_t(lastSlice
.resetReason
));
1082 TimeDuration total
, longest
;
1083 gcDuration(&total
, &longest
);
1085 runtime
->metrics().GC_MS(total
);
1086 runtime
->metrics().GC_MAX_PAUSE_MS_2(longest
);
1088 const double mmu50
= computeMMU(TimeDuration::FromMilliseconds(50));
1089 runtime
->metrics().GC_MMU_50(mmu50
* 100.0);
1091 // Record scheduling telemetry for the main runtime but not for workers, which
1092 // are scheduled differently.
1093 if (!runtime
->parentRuntime
&& timeSinceLastGC
) {
1094 runtime
->metrics().GC_TIME_BETWEEN_S(timeSinceLastGC
);
1095 if (!nonincremental()) {
1096 runtime
->metrics().GC_SLICE_COUNT(slices_
.length());
1100 if (!lastSlice
.wasReset() && preCollectedHeapBytes
!= 0) {
1101 size_t bytesSurvived
= 0;
1102 for (ZonesIter
zone(runtime
, WithAtoms
); !zone
.done(); zone
.next()) {
1103 if (zone
->wasCollected()) {
1104 bytesSurvived
+= zone
->gcHeapSize
.retainedBytes();
1108 MOZ_ASSERT(preCollectedHeapBytes
>= bytesSurvived
);
1109 double survivalRate
=
1110 100.0 * double(bytesSurvived
) / double(preCollectedHeapBytes
);
1111 runtime
->metrics().GC_TENURED_SURVIVAL_RATE(survivalRate
);
1113 // Calculate 'effectiveness' in MB / second, on main thread only for now.
1114 if (!runtime
->parentRuntime
) {
1115 size_t bytesFreed
= preCollectedHeapBytes
- bytesSurvived
;
1116 TimeDuration clampedTotal
=
1117 TimeDuration::Max(total
, TimeDuration::FromMilliseconds(1));
1118 double effectiveness
=
1119 (double(bytesFreed
) / BYTES_PER_MB
) / clampedTotal
.ToSeconds();
1120 runtime
->metrics().GC_EFFECTIVENESS(uint32_t(effectiveness
));
1124 // Parallel marking stats.
1125 if (gc
->isParallelMarkingEnabled()) {
1126 TimeDuration wallTime
= SumPhase(PhaseKind::PARALLEL_MARK
, phaseTimes
);
1127 TimeDuration parallelMarkTime
=
1128 sumTotalParallelTime(PhaseKind::PARALLEL_MARK_MARK
);
1129 TimeDuration parallelRunTime
=
1130 parallelMarkTime
+ sumTotalParallelTime(PhaseKind::PARALLEL_MARK_OTHER
);
1131 if (wallTime
&& parallelMarkTime
) {
1132 uint32_t threadCount
= gc
->markers
.length();
1133 double speedup
= parallelMarkTime
/ wallTime
;
1134 double utilization
= parallelRunTime
/ (wallTime
* threadCount
);
1135 MOZ_ASSERT(utilization
<= 1.0);
1136 runtime
->metrics().GC_PARALLEL_MARK_SPEEDUP(uint32_t(speedup
* 100.0));
1137 runtime
->metrics().GC_PARALLEL_MARK_UTILIZATION(
1138 std::clamp(utilization
* 100.0, 0.0, 100.0));
1139 runtime
->metrics().GC_PARALLEL_MARK_INTERRUPTIONS(
1140 getCount(COUNT_PARALLEL_MARK_INTERRUPTIONS
));
1145 void Statistics::beginNurseryCollection() {
1146 count(COUNT_MINOR_GC
);
1147 startingMinorGCNumber
= gc
->minorGCCount();
1150 void Statistics::endNurseryCollection() { tenuredAllocsSinceMinorGC
= 0; }
1152 Statistics::SliceData::SliceData(const SliceBudget
& budget
,
1153 Maybe
<Trigger
> trigger
, JS::GCReason reason
,
1154 TimeStamp start
, size_t startFaults
,
1155 gc::State initialState
)
1159 initialState(initialState
),
1161 startFaults(startFaults
) {}
1163 TimeDuration
Statistics::SliceData::duration() const {
1164 return TimeBetween(start
, end
);
1167 void Statistics::beginSlice(const ZoneGCStats
& zoneStats
, JS::GCOptions options
,
1168 const SliceBudget
& budget
, JS::GCReason reason
,
1169 bool budgetWasIncreased
) {
1170 MOZ_ASSERT(phaseStack
.empty() ||
1171 (phaseStack
.length() == 1 && phaseStack
[0] == Phase::MUTATOR
));
1173 this->zoneStats
= zoneStats
;
1175 TimeStamp currentTime
= TimeStamp::Now();
1177 bool first
= !gc
->isIncrementalGCInProgress();
1179 beginGC(options
, currentTime
);
1182 JSRuntime
* runtime
= gc
->rt
;
1183 if (!runtime
->parentRuntime
&& !slices_
.empty()) {
1184 TimeDuration timeSinceLastSlice
=
1185 TimeBetween(slices_
.back().end
, currentTime
);
1186 runtime
->metrics().GC_TIME_BETWEEN_SLICES_MS(timeSinceLastSlice
);
1189 Maybe
<Trigger
> trigger
= recordedTrigger
;
1190 recordedTrigger
.reset();
1192 if (!slices_
.emplaceBack(budget
, trigger
, reason
, currentTime
,
1193 GetPageFaultCount(), gc
->state())) {
1194 // If we are OOM, set a flag to indicate we have missing slice data.
1199 runtime
->metrics().GC_REASON_2(uint32_t(reason
));
1200 runtime
->metrics().GC_BUDGET_WAS_INCREASED(budgetWasIncreased
);
1202 // Slice callbacks should only fire for the outermost level.
1203 if (sliceCallback
) {
1204 JSContext
* cx
= context();
1205 JS::GCDescription
desc(!gc
->fullGCRequested
, false, options
, reason
);
1207 (*sliceCallback
)(cx
, JS::GC_CYCLE_BEGIN
, desc
);
1209 (*sliceCallback
)(cx
, JS::GC_SLICE_BEGIN
, desc
);
1215 void Statistics::endSlice() {
1216 MOZ_ASSERT(phaseStack
.empty() ||
1217 (phaseStack
.length() == 1 && phaseStack
[0] == Phase::MUTATOR
));
1220 auto& slice
= slices_
.back();
1221 slice
.end
= TimeStamp::Now();
1222 slice
.endFaults
= GetPageFaultCount();
1223 slice
.finalState
= gc
->state();
1227 sendSliceTelemetry(slice
);
1231 totalGCTime_
+= slice
.duration();
1234 bool last
= !gc
->isIncrementalGCInProgress();
1246 ShouldPrintProfile(gc
->rt
, enableProfiling_
, profileWorkers_
,
1247 profileThreshold_
, slices_
.back().duration())) {
1248 printSliceProfile();
1251 // Slice callbacks should only fire for the outermost level.
1253 if (sliceCallback
) {
1254 JSContext
* cx
= context();
1255 JS::GCDescription
desc(!gc
->fullGCRequested
, last
, gcOptions
,
1256 slices_
.back().reason
);
1257 (*sliceCallback
)(cx
, JS::GC_SLICE_END
, desc
);
1259 (*sliceCallback
)(cx
, JS::GC_CYCLE_END
, desc
);
1264 // Do this after the slice callback since it uses these values.
1266 for (auto& count
: counts
) {
1270 // Clear the timers at the end of a GC, preserving the data for
1271 // PhaseKind::MUTATOR.
1272 auto mutatorStartTime
= phaseStartTimes
[Phase::MUTATOR
];
1273 auto mutatorTime
= phaseTimes
[Phase::MUTATOR
];
1275 phaseStartTimes
= PhaseTimeStamps();
1277 phaseEndTimes
= PhaseTimeStamps();
1279 phaseTimes
= PhaseTimes();
1281 phaseStartTimes
[Phase::MUTATOR
] = mutatorStartTime
;
1282 phaseTimes
[Phase::MUTATOR
] = mutatorTime
;
1288 void Statistics::sendSliceTelemetry(const SliceData
& slice
) {
1289 JSRuntime
* runtime
= gc
->rt
;
1290 TimeDuration sliceTime
= slice
.duration();
1291 runtime
->metrics().GC_SLICE_MS(sliceTime
);
1293 if (slice
.budget
.isTimeBudget()) {
1294 TimeDuration budgetDuration
= slice
.budget
.timeBudgetDuration();
1295 runtime
->metrics().GC_BUDGET_MS_2(budgetDuration
);
1297 if (IsCurrentlyAnimating(runtime
->lastAnimationTime
, slice
.end
)) {
1298 runtime
->metrics().GC_ANIMATION_MS(sliceTime
);
1301 bool wasLongSlice
= false;
1302 if (sliceTime
> budgetDuration
) {
1303 // Record how long we went over budget.
1304 TimeDuration overrun
= sliceTime
- budgetDuration
;
1305 runtime
->metrics().GC_BUDGET_OVERRUN(overrun
);
1307 // Long GC slices are those that go 50% or 5ms over their budget.
1308 wasLongSlice
= (overrun
> TimeDuration::FromMilliseconds(5)) ||
1309 (overrun
> (budgetDuration
/ int64_t(2)));
1311 // Record the longest phase in any long slice.
1313 PhaseKind longest
= LongestPhaseSelfTimeInMajorGC(slice
.phaseTimes
);
1314 reportLongestPhaseInMajorGC(longest
, [runtime
](auto sample
) {
1315 runtime
->metrics().GC_SLOW_PHASE(sample
);
1318 // If the longest phase was waiting for parallel tasks then record the
1320 if (longest
== PhaseKind::JOIN_PARALLEL_TASKS
) {
1321 PhaseKind longestParallel
=
1322 FindLongestPhaseKind(slice
.maxParallelTimes
);
1323 reportLongestPhaseInMajorGC(longestParallel
, [runtime
](auto sample
) {
1324 runtime
->metrics().GC_SLOW_TASK(sample
);
1330 // Record `wasLongSlice` for all TimeBudget slices.
1331 runtime
->metrics().GC_SLICE_WAS_LONG(wasLongSlice
);
1335 template <typename Fn
>
1336 void Statistics::reportLongestPhaseInMajorGC(PhaseKind longest
, Fn reportFn
) {
1337 if (longest
!= PhaseKind::NONE
) {
1338 uint8_t bucket
= phaseKinds
[longest
].telemetryBucket
;
1343 bool Statistics::startTimingMutator() {
1344 if (phaseStack
.length() != 0) {
1345 // Should only be called from outside of GC.
1346 MOZ_ASSERT(phaseStack
.length() == 1);
1347 MOZ_ASSERT(phaseStack
[0] == Phase::MUTATOR
);
1351 MOZ_ASSERT(suspendedPhases
.empty());
1353 timedGCTime
= TimeDuration::Zero();
1354 phaseStartTimes
[Phase::MUTATOR
] = TimeStamp();
1355 phaseTimes
[Phase::MUTATOR
] = TimeDuration::Zero();
1356 timedGCStart
= TimeStamp();
1358 beginPhase(PhaseKind::MUTATOR
);
1362 bool Statistics::stopTimingMutator(double& mutator_ms
, double& gc_ms
) {
1363 // This should only be called from outside of GC, while timing the mutator.
1364 if (phaseStack
.length() != 1 || phaseStack
[0] != Phase::MUTATOR
) {
1368 endPhase(PhaseKind::MUTATOR
);
1369 mutator_ms
= t(phaseTimes
[Phase::MUTATOR
]);
1370 gc_ms
= t(timedGCTime
);
1375 void Statistics::suspendPhases(PhaseKind suspension
) {
1376 MOZ_ASSERT(suspension
== PhaseKind::EXPLICIT_SUSPENSION
||
1377 suspension
== PhaseKind::IMPLICIT_SUSPENSION
);
1378 while (!phaseStack
.empty()) {
1379 MOZ_ASSERT(suspendedPhases
.length() < MAX_SUSPENDED_PHASES
);
1380 Phase parent
= phaseStack
.back();
1381 suspendedPhases
.infallibleAppend(parent
);
1382 recordPhaseEnd(parent
);
1384 suspendedPhases
.infallibleAppend(lookupChildPhase(suspension
));
1387 void Statistics::resumePhases() {
1388 MOZ_ASSERT(suspendedPhases
.back() == Phase::EXPLICIT_SUSPENSION
||
1389 suspendedPhases
.back() == Phase::IMPLICIT_SUSPENSION
);
1390 suspendedPhases
.popBack();
1392 while (!suspendedPhases
.empty() &&
1393 suspendedPhases
.back() != Phase::EXPLICIT_SUSPENSION
&&
1394 suspendedPhases
.back() != Phase::IMPLICIT_SUSPENSION
) {
1395 Phase resumePhase
= suspendedPhases
.popCopy();
1396 if (resumePhase
== Phase::MUTATOR
) {
1397 timedGCTime
+= TimeBetween(timedGCStart
, TimeStamp::Now());
1399 recordPhaseBegin(resumePhase
);
1403 void Statistics::beginPhase(PhaseKind phaseKind
) {
1404 // No longer timing these phases. We should never see these.
1405 MOZ_ASSERT(phaseKind
!= PhaseKind::GC_BEGIN
&&
1406 phaseKind
!= PhaseKind::GC_END
);
1408 // PhaseKind::MUTATOR is suspended while performing GC.
1409 if (currentPhase() == Phase::MUTATOR
) {
1410 suspendPhases(PhaseKind::IMPLICIT_SUSPENSION
);
1413 recordPhaseBegin(lookupChildPhase(phaseKind
));
1416 void Statistics::recordPhaseBegin(Phase phase
) {
1417 MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc
->rt
));
1419 // Guard against any other re-entry.
1420 MOZ_ASSERT(!phaseStartTimes
[phase
]);
1422 MOZ_ASSERT(phaseStack
.length() < MAX_PHASE_NESTING
);
1424 Phase current
= currentPhase();
1425 MOZ_ASSERT(phases
[phase
].parent
== current
);
1427 TimeStamp now
= TimeStamp::Now();
1429 if (current
!= Phase::NONE
) {
1430 MOZ_ASSERT(now
>= phaseStartTimes
[currentPhase()],
1431 "Inconsistent time data; see bug 1400153");
1432 if (now
< phaseStartTimes
[currentPhase()]) {
1433 now
= phaseStartTimes
[currentPhase()];
1438 phaseStack
.infallibleAppend(phase
);
1439 phaseStartTimes
[phase
] = now
;
1440 log("begin: %s", phases
[phase
].path
);
1443 void Statistics::recordPhaseEnd(Phase phase
) {
1444 MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc
->rt
));
1446 MOZ_ASSERT(phaseStartTimes
[phase
]);
1448 TimeStamp now
= TimeStamp::Now();
1450 // Make sure this phase ends after it starts.
1451 MOZ_ASSERT(now
>= phaseStartTimes
[phase
],
1452 "Inconsistent time data; see bug 1400153");
1455 // Make sure this phase ends after all of its children. Note that some
1456 // children might not have run in this instance, in which case they will
1457 // have run in a previous instance of this parent or not at all.
1458 for (Phase kid
= phases
[phase
].firstChild
; kid
!= Phase::NONE
;
1459 kid
= phases
[kid
].nextSibling
) {
1460 if (phaseEndTimes
[kid
].IsNull()) {
1463 if (phaseEndTimes
[kid
] > now
) {
1465 "Parent %s ended at %.3fms, before child %s ended at %.3fms?\n",
1467 t(TimeBetween(TimeStamp::FirstTimeStamp(), now
)),
1469 t(TimeBetween(TimeStamp::FirstTimeStamp(), phaseEndTimes
[kid
])));
1471 MOZ_ASSERT(phaseEndTimes
[kid
] <= now
,
1472 "Inconsistent time data; see bug 1400153");
1476 if (now
< phaseStartTimes
[phase
]) {
1477 now
= phaseStartTimes
[phase
];
1481 if (phase
== Phase::MUTATOR
) {
1485 phaseStack
.popBack();
1487 TimeDuration t
= TimeBetween(phaseStartTimes
[phase
], now
);
1488 if (!slices_
.empty()) {
1489 slices_
.back().phaseTimes
[phase
] += t
;
1491 phaseTimes
[phase
] += t
;
1492 phaseStartTimes
[phase
] = TimeStamp();
1495 phaseEndTimes
[phase
] = now
;
1496 log("end: %s", phases
[phase
].path
);
1500 void Statistics::endPhase(PhaseKind phaseKind
) {
1501 Phase phase
= currentPhase();
1502 MOZ_ASSERT(phase
!= Phase::NONE
);
1503 MOZ_ASSERT(phases
[phase
].phaseKind
== phaseKind
);
1505 recordPhaseEnd(phase
);
1507 // When emptying the stack, we may need to return to timing the mutator
1508 // (PhaseKind::MUTATOR).
1509 if (phaseStack
.empty() && !suspendedPhases
.empty() &&
1510 suspendedPhases
.back() == Phase::IMPLICIT_SUSPENSION
) {
1515 void Statistics::recordParallelPhase(PhaseKind phaseKind
,
1516 TimeDuration duration
) {
1517 MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc
->rt
));
1523 slices_
.back().totalParallelTimes
[phaseKind
] += duration
;
1525 // Also record the maximum task time for each phase. Don't record times for
1527 TimeDuration
& maxTime
= slices_
.back().maxParallelTimes
[phaseKind
];
1528 maxTime
= std::max(maxTime
, duration
);
1531 TimeStamp
Statistics::beginSCC() { return TimeStamp::Now(); }
1533 void Statistics::endSCC(unsigned scc
, TimeStamp start
) {
1534 if (scc
>= sccTimes
.length() && !sccTimes
.resize(scc
+ 1)) {
1538 sccTimes
[scc
] += TimeBetween(start
, TimeStamp::Now());
1542 * Calculate minimum mutator utilization for previous incremental GC.
1544 * MMU (minimum mutator utilization) is a measure of how much garbage collection
1545 * is affecting the responsiveness of the system. MMU measurements are given
1546 * with respect to a certain window size. If we report MMU(50ms) = 80%, then
1547 * that means that, for any 50ms window of time, at least 80% of the window is
1548 * devoted to the mutator. In other words, the GC is running for at most 20% of
1549 * the window, or 10ms. The GC can run multiple slices during the 50ms window
1550 * as long as the total time it spends is at most 10ms.
1552 double Statistics::computeMMU(TimeDuration window
) const {
1553 MOZ_ASSERT(window
> TimeDuration::Zero());
1554 MOZ_ASSERT(!slices().empty());
1556 // Examine all ranges of slices from |startIndex| to |endIndex| inclusive
1557 // whose timestamps span less than the window duration. The time spent in GC
1558 // in each range is stored in |gcInRange| by maintaining a running total. The
1559 // maximum value of this after adjustment to the window size is recorded in
1562 size_t startIndex
= 0;
1563 const SliceData
* startSlice
= &sliceAt(startIndex
);
1564 TimeDuration gcInRange
= startSlice
->duration();
1565 if (gcInRange
>= window
) {
1569 TimeDuration maxGCInWindow
= gcInRange
;
1571 for (size_t endIndex
= 1; endIndex
< slices().length(); endIndex
++) {
1572 const SliceData
* endSlice
= &sliceAt(endIndex
);
1573 if (endSlice
->duration() >= window
) {
1577 gcInRange
+= endSlice
->duration();
1579 while (TimeBetween(startSlice
->end
, endSlice
->end
) >= window
) {
1580 gcInRange
-= startSlice
->duration();
1582 MOZ_ASSERT(startIndex
<= endIndex
);
1583 startSlice
= &sliceAt(startIndex
);
1586 TimeDuration totalInRange
= TimeBetween(startSlice
->start
, endSlice
->end
);
1587 MOZ_ASSERT(gcInRange
<= totalInRange
);
1589 TimeDuration gcInWindow
= gcInRange
;
1590 if (totalInRange
> window
) {
1591 gcInWindow
-= (totalInRange
- window
);
1593 MOZ_ASSERT(gcInWindow
<= window
);
1595 if (gcInWindow
> maxGCInWindow
) {
1596 maxGCInWindow
= gcInWindow
;
1600 MOZ_ASSERT(maxGCInWindow
>= TimeDuration::Zero());
1601 MOZ_ASSERT(maxGCInWindow
<= window
);
1602 return (window
- maxGCInWindow
) / window
;
1605 void Statistics::maybePrintProfileHeaders() {
1606 static int printedHeader
= 0;
1607 if ((printedHeader
++ % 200) == 0) {
1608 printProfileHeader();
1609 if (gc
->nursery().enableProfiling()) {
1610 gc
->nursery().printProfileHeader();
1615 // The following macros define GC profile metadata fields that are printed
1616 // before the timing information defined by FOR_EACH_GC_PROFILE_TIME.
1618 #define FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
1619 _("PID", 7, "%7zu", pid) \
1620 _("Runtime", 14, "0x%12p", runtime)
1622 #define FOR_EACH_GC_PROFILE_SLICE_METADATA(_) \
1623 _("Timestamp", 10, "%10.6f", timestamp.ToSeconds()) \
1624 _("Reason", 20, "%-20.20s", reason) \
1625 _("States", 6, "%6s", formatGCStates(slice)) \
1626 _("FSNR", 4, "%4s", formatGCFlags(slice)) \
1627 _("SizeKB", 8, "%8zu", sizeKB) \
1628 _("Zs", 3, "%3zu", zoneCount) \
1629 _("Cs", 3, "%3zu", compartmentCount) \
1630 _("Rs", 3, "%3zu", realmCount) \
1631 _("Budget", 6, "%6s", formatBudget(slice))
1633 #define FOR_EACH_GC_PROFILE_METADATA(_) \
1634 FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
1635 FOR_EACH_GC_PROFILE_SLICE_METADATA(_)
1637 void Statistics::printProfileHeader() {
1638 if (!enableProfiling_
) {
1643 if (!sprinter
.init() || !sprinter
.put(MajorGCProfilePrefix
)) {
1647 #define PRINT_METADATA_NAME(name, width, _1, _2) \
1648 if (!sprinter.jsprintf(" %-*s", width, name)) { \
1651 FOR_EACH_GC_PROFILE_METADATA(PRINT_METADATA_NAME
)
1652 #undef PRINT_METADATA_NAME
1654 #define PRINT_PROFILE_NAME(_1, text, _2) \
1655 if (!sprinter.jsprintf(" %-6.6s", text)) { \
1658 FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_NAME
)
1659 #undef PRINT_PROFILE_NAME
1661 if (!sprinter
.put("\n")) {
1665 fputs(sprinter
.string(), profileFile());
1668 static TimeDuration
SumAllPhaseKinds(const Statistics::PhaseKindTimes
& times
) {
1670 for (PhaseKind kind
: AllPhaseKinds()) {
1676 void Statistics::printSliceProfile() {
1677 maybePrintProfileHeaders();
1679 const SliceData
& slice
= slices_
.back();
1680 ProfileDurations times
= getProfileTimes(slice
);
1681 updateTotalProfileTimes(times
);
1684 if (!sprinter
.init() || !sprinter
.put(MajorGCProfilePrefix
)) {
1688 size_t pid
= getpid();
1689 JSRuntime
* runtime
= gc
->rt
;
1690 TimeDuration timestamp
= TimeBetween(creationTime(), slice
.end
);
1691 const char* reason
= ExplainGCReason(slice
.reason
);
1692 size_t sizeKB
= gc
->heapSize
.bytes() / 1024;
1693 size_t zoneCount
= zoneStats
.zoneCount
;
1694 size_t compartmentCount
= zoneStats
.compartmentCount
;
1695 size_t realmCount
= zoneStats
.realmCount
;
1697 #define PRINT_FIELD_VALUE(_1, _2, format, value) \
1698 if (!sprinter.jsprintf(" " format, value)) { \
1701 FOR_EACH_GC_PROFILE_METADATA(PRINT_FIELD_VALUE
)
1702 #undef PRINT_FIELD_VALUE
1704 if (!printProfileTimes(times
, sprinter
)) {
1708 fputs(sprinter
.string(), profileFile());
1711 Statistics::ProfileDurations
Statistics::getProfileTimes(
1712 const SliceData
& slice
) const {
1713 ProfileDurations times
;
1715 times
[ProfileKey::Total
] = slice
.duration();
1716 times
[ProfileKey::Background
] = SumAllPhaseKinds(slice
.totalParallelTimes
);
1718 #define GET_PROFILE_TIME(name, text, phase) \
1719 if (phase != PhaseKind::NONE) { \
1720 times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
1722 FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME
)
1723 #undef GET_PROFILE_TIME
1728 void Statistics::updateTotalProfileTimes(const ProfileDurations
& times
) {
1729 #define UPDATE_PROFILE_TIME(name, _, phase) \
1730 totalTimes_[ProfileKey::name] += times[ProfileKey::name];
1731 FOR_EACH_GC_PROFILE_TIME(UPDATE_PROFILE_TIME
)
1732 #undef UPDATE_PROFILE_TIME
1735 const char* Statistics::formatGCStates(const SliceData
& slice
) {
1737 SprintfLiteral(formatBuffer_
, "%1d -> %1d", int(slice
.initialState
),
1738 int(slice
.finalState
));
1739 MOZ_ASSERT(r
> 0 && r
< FormatBufferLength
);
1740 return formatBuffer_
;
1743 const char* Statistics::formatGCFlags(const SliceData
& slice
) {
1744 bool fullGC
= gc
->fullGCRequested
;
1745 bool shrinkingGC
= gcOptions
== JS::GCOptions::Shrink
;
1746 bool nonIncrementalGC
= nonincrementalReason_
!= GCAbortReason::None
;
1747 bool wasReset
= slice
.resetReason
!= GCAbortReason::None
;
1749 MOZ_ASSERT(FormatBufferLength
>= 5);
1750 formatBuffer_
[0] = fullGC
? 'F' : ' ';
1751 formatBuffer_
[1] = shrinkingGC
? 'S' : ' ';
1752 formatBuffer_
[2] = nonIncrementalGC
? 'N' : ' ';
1753 formatBuffer_
[3] = wasReset
? 'R' : ' ';
1754 formatBuffer_
[4] = '\0';
1756 return formatBuffer_
;
1759 const char* Statistics::formatBudget(const SliceData
& slice
) {
1760 if (nonincrementalReason_
!= GCAbortReason::None
||
1761 !slice
.budget
.isTimeBudget()) {
1762 formatBuffer_
[0] = '\0';
1763 return formatBuffer_
;
1767 SprintfLiteral(formatBuffer_
, "%6" PRIi64
, slice
.budget
.timeBudget());
1768 MOZ_ASSERT(r
> 0 && r
< FormatBufferLength
);
1769 return formatBuffer_
;
1773 bool Statistics::printProfileTimes(const ProfileDurations
& times
,
1774 Sprinter
& sprinter
) {
1775 for (auto time
: times
) {
1776 int64_t millis
= int64_t(time
.ToMilliseconds());
1777 if (!sprinter
.jsprintf(" %6" PRIi64
, millis
)) {
1782 return sprinter
.put("\n");
1785 constexpr size_t SliceMetadataFormatWidth() {
1786 size_t fieldCount
= 0;
1787 size_t totalWidth
= 0;
1789 #define UPDATE_COUNT_AND_WIDTH(_1, width, _2, _3) \
1791 totalWidth += width;
1792 FOR_EACH_GC_PROFILE_SLICE_METADATA(UPDATE_COUNT_AND_WIDTH
)
1793 #undef UPDATE_COUNT_AND_WIDTH
1795 // Add padding between fields.
1796 totalWidth
+= fieldCount
- 1;
1801 void Statistics::printTotalProfileTimes() {
1802 if (!enableProfiling_
) {
1807 if (!sprinter
.init() || !sprinter
.put(MajorGCProfilePrefix
)) {
1811 size_t pid
= getpid();
1812 JSRuntime
* runtime
= gc
->rt
;
1814 #define PRINT_FIELD_VALUE(_1, _2, format, value) \
1815 if (!sprinter.jsprintf(" " format, value)) { \
1818 FOR_EACH_GC_PROFILE_COMMON_METADATA(PRINT_FIELD_VALUE
)
1819 #undef PRINT_FIELD_VALUE
1821 // Use whole width of per-slice metadata to print total slices so the profile
1822 // totals that follow line up.
1823 size_t width
= SliceMetadataFormatWidth();
1824 if (!sprinter
.jsprintf(" %-*s", int(width
), formatTotalSlices())) {
1828 if (!printProfileTimes(totalTimes_
, sprinter
)) {
1832 fputs(sprinter
.string(), profileFile());
1835 const char* Statistics::formatTotalSlices() {
1836 DebugOnly
<int> r
= SprintfLiteral(
1837 formatBuffer_
, "TOTALS: %7" PRIu64
" slices:", sliceCount_
);
1838 MOZ_ASSERT(r
> 0 && r
< FormatBufferLength
);
1839 return formatBuffer_
;