Line data Source code
1 : /* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 4 -*-
2 : * vim: set ts=8 sts=4 et sw=4 tw=99:
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/. */
6 :
7 : #include "gc/Statistics.h"
8 :
9 : #include "mozilla/ArrayUtils.h"
10 : #include "mozilla/DebugOnly.h"
11 : #include "mozilla/IntegerRange.h"
12 : #include "mozilla/PodOperations.h"
13 : #include "mozilla/Sprintf.h"
14 : #include "mozilla/TimeStamp.h"
15 :
16 : #include <ctype.h>
17 : #include <stdarg.h>
18 : #include <stdio.h>
19 :
20 : #include "jsprf.h"
21 : #include "jsutil.h"
22 :
23 : #include "gc/Memory.h"
24 : #include "vm/Debugger.h"
25 : #include "vm/HelperThreads.h"
26 : #include "vm/Runtime.h"
27 : #include "vm/Time.h"
28 :
29 : using namespace js;
30 : using namespace js::gc;
31 : using namespace js::gcstats;
32 :
33 : using mozilla::DebugOnly;
34 : using mozilla::EnumeratedArray;
35 : using mozilla::IntegerRange;
36 : using mozilla::PodArrayZero;
37 : using mozilla::PodZero;
38 : using mozilla::TimeStamp;
39 : using mozilla::TimeDuration;
40 :
41 : /*
42 : * If this fails, then you can either delete this assertion and allow all
43 : * larger-numbered reasons to pile up in the last telemetry bucket, or switch
44 : * to GC_REASON_3 and bump the max value.
45 : */
46 : JS_STATIC_ASSERT(JS::gcreason::NUM_TELEMETRY_REASONS >= JS::gcreason::NUM_REASONS);
47 :
48 : static inline decltype(mozilla::MakeEnumeratedRange(PhaseKind::FIRST, PhaseKind::LIMIT))
49 212 : AllPhaseKinds()
50 : {
51 212 : return mozilla::MakeEnumeratedRange(PhaseKind::FIRST, PhaseKind::LIMIT);
52 : }
53 :
54 : const char*
55 0 : js::gcstats::ExplainInvocationKind(JSGCInvocationKind gckind)
56 : {
57 0 : MOZ_ASSERT(gckind == GC_NORMAL || gckind == GC_SHRINK);
58 0 : if (gckind == GC_NORMAL)
59 0 : return "Normal";
60 : else
61 0 : return "Shrinking";
62 : }
63 :
64 : JS_PUBLIC_API(const char*)
65 3 : JS::gcreason::ExplainReason(JS::gcreason::Reason reason)
66 : {
67 3 : switch (reason) {
68 : #define SWITCH_REASON(name) \
69 : case JS::gcreason::name: \
70 : return #name;
71 0 : GCREASONS(SWITCH_REASON)
72 :
73 : default:
74 0 : MOZ_CRASH("bad GC reason");
75 : #undef SWITCH_REASON
76 : }
77 : }
78 :
79 : const char*
80 0 : js::gcstats::ExplainAbortReason(gc::AbortReason reason)
81 : {
82 0 : switch (reason) {
83 : #define SWITCH_REASON(name) \
84 : case gc::AbortReason::name: \
85 : return #name;
86 0 : GC_ABORT_REASONS(SWITCH_REASON)
87 :
88 : default:
89 0 : MOZ_CRASH("bad GC abort reason");
90 : #undef SWITCH_REASON
91 : }
92 : }
93 :
94 : struct PhaseKindInfo
95 : {
96 : Phase firstPhase;
97 : uint8_t telemetryBucket;
98 : };
99 :
100 : // PhaseInfo objects form a tree.
101 : struct PhaseInfo
102 : {
103 : Phase parent;
104 : Phase firstChild;
105 : Phase nextSibling;
106 : Phase nextInPhase;
107 : PhaseKind phaseKind;
108 : uint8_t depth;
109 : const char* name;
110 : const char* path;
111 : };
112 :
113 : // A table of PhaseInfo indexed by Phase.
114 : using PhaseTable = EnumeratedArray<Phase, Phase::LIMIT, PhaseInfo>;
115 :
116 : // A table of PhaseKindInfo indexed by PhaseKind.
117 : using PhaseKindTable = EnumeratedArray<PhaseKind, PhaseKind::LIMIT, PhaseKindInfo>;
118 :
119 : #include "gc/StatsPhasesGenerated.cpp"
120 :
121 : static double
122 3 : t(TimeDuration duration)
123 : {
124 3 : return duration.ToMilliseconds();
125 : }
126 :
127 : inline Phase
128 707 : Statistics::currentPhase() const
129 : {
130 707 : return phaseStack.empty() ? Phase::NONE : phaseStack.back();
131 : }
132 :
133 : PhaseKind
134 48 : Statistics::currentPhaseKind() const
135 : {
136 : // Public API to get the current phase kind, suppressing the synthetic
137 : // PhaseKind::MUTATOR phase.
138 :
139 48 : Phase phase = currentPhase();
140 48 : MOZ_ASSERT_IF(phase == Phase::MUTATOR, phaseStack.length() == 1);
141 48 : if (phase == Phase::NONE || phase == Phase::MUTATOR)
142 27 : return PhaseKind::NONE;
143 :
144 21 : return phases[phase].phaseKind;
145 : }
146 :
147 : Phase
148 144 : Statistics::lookupChildPhase(PhaseKind phaseKind) const
149 : {
150 144 : if (phaseKind == PhaseKind::IMPLICIT_SUSPENSION)
151 0 : return Phase::IMPLICIT_SUSPENSION;
152 144 : if (phaseKind == PhaseKind::EXPLICIT_SUSPENSION)
153 0 : return Phase::EXPLICIT_SUSPENSION;
154 :
155 144 : MOZ_ASSERT(phaseKind < PhaseKind::LIMIT);
156 :
157 : // Most phases only correspond to a single expanded phase so check for that
158 : // first.
159 144 : Phase phase = phaseKinds[phaseKind].firstPhase;
160 144 : if (phases[phase].nextInPhase == Phase::NONE) {
161 72 : MOZ_ASSERT(phases[phase].parent == currentPhase());
162 72 : return phase;
163 : }
164 :
165 : // Otherwise search all expanded phases that correspond to the required
166 : // phase to find the one whose parent is the current expanded phase.
167 72 : Phase parent = currentPhase();
168 342 : while (phases[phase].parent != parent) {
169 135 : phase = phases[phase].nextInPhase;
170 135 : MOZ_ASSERT(phase != Phase::NONE);
171 : }
172 :
173 72 : return phase;
174 : }
175 :
176 : inline decltype(mozilla::MakeEnumeratedRange(Phase::FIRST, Phase::LIMIT))
177 4 : AllPhases()
178 : {
179 4 : return mozilla::MakeEnumeratedRange(Phase::FIRST, Phase::LIMIT);
180 : }
181 :
182 : void
183 0 : Statistics::gcDuration(TimeDuration* total, TimeDuration* maxPause) const
184 : {
185 0 : *total = *maxPause = 0;
186 0 : for (auto& slice : slices_) {
187 0 : *total += slice.duration();
188 0 : if (slice.duration() > *maxPause)
189 0 : *maxPause = slice.duration();
190 : }
191 0 : if (*maxPause > maxPauseInInterval)
192 0 : maxPauseInInterval = *maxPause;
193 0 : }
194 :
195 : void
196 0 : Statistics::sccDurations(TimeDuration* total, TimeDuration* maxPause) const
197 : {
198 0 : *total = *maxPause = 0;
199 0 : for (size_t i = 0; i < sccTimes.length(); i++) {
200 0 : *total += sccTimes[i];
201 0 : *maxPause = Max(*maxPause, sccTimes[i]);
202 : }
203 0 : }
204 :
205 : typedef Vector<UniqueChars, 8, SystemAllocPolicy> FragmentVector;
206 :
207 : static UniqueChars
208 0 : Join(const FragmentVector& fragments, const char* separator = "")
209 : {
210 0 : const size_t separatorLength = strlen(separator);
211 0 : size_t length = 0;
212 0 : for (size_t i = 0; i < fragments.length(); ++i) {
213 0 : length += fragments[i] ? strlen(fragments[i].get()) : 0;
214 0 : if (i < (fragments.length() - 1))
215 0 : length += separatorLength;
216 : }
217 :
218 0 : char* joined = js_pod_malloc<char>(length + 1);
219 0 : if (!joined)
220 0 : return UniqueChars();
221 :
222 0 : joined[length] = '\0';
223 0 : char* cursor = joined;
224 0 : for (size_t i = 0; i < fragments.length(); ++i) {
225 0 : if (fragments[i])
226 0 : strcpy(cursor, fragments[i].get());
227 0 : cursor += fragments[i] ? strlen(fragments[i].get()) : 0;
228 0 : if (i < (fragments.length() - 1)) {
229 0 : if (separatorLength)
230 0 : strcpy(cursor, separator);
231 0 : cursor += separatorLength;
232 : }
233 : }
234 :
235 0 : return UniqueChars(joined);
236 : }
237 :
238 : static TimeDuration
239 0 : SumChildTimes(Phase phase, const Statistics::PhaseTimeTable& phaseTimes)
240 : {
241 0 : TimeDuration total = 0;
242 0 : for (phase = phases[phase].firstChild;
243 0 : phase != Phase::NONE;
244 0 : phase = phases[phase].nextSibling)
245 : {
246 0 : total += phaseTimes[phase];
247 : }
248 0 : return total;
249 : }
250 :
251 : UniqueChars
252 0 : Statistics::formatCompactSliceMessage() const
253 : {
254 : // Skip if we OOM'ed.
255 0 : if (slices_.length() == 0)
256 0 : return UniqueChars(nullptr);
257 :
258 0 : const size_t index = slices_.length() - 1;
259 0 : const SliceData& slice = slices_.back();
260 :
261 : char budgetDescription[200];
262 0 : slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
263 :
264 : const char* format =
265 0 : "GC Slice %u - Pause: %.3fms of %s budget (@ %.3fms); Reason: %s; Reset: %s%s; Times: ";
266 : char buffer[1024];
267 0 : SprintfLiteral(buffer, format, index,
268 0 : t(slice.duration()), budgetDescription, t(slice.start - slices_[0].start),
269 0 : ExplainReason(slice.reason),
270 0 : slice.wasReset() ? "yes - " : "no",
271 0 : slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "");
272 :
273 0 : FragmentVector fragments;
274 0 : if (!fragments.append(DuplicateString(buffer)) ||
275 0 : !fragments.append(formatCompactSlicePhaseTimes(slices_[index].phaseTimes)))
276 : {
277 0 : return UniqueChars(nullptr);
278 : }
279 0 : return Join(fragments);
280 : }
281 :
282 : UniqueChars
283 0 : Statistics::formatCompactSummaryMessage() const
284 : {
285 0 : const double bytesPerMiB = 1024 * 1024;
286 :
287 0 : FragmentVector fragments;
288 0 : if (!fragments.append(DuplicateString("Summary - ")))
289 0 : return UniqueChars(nullptr);
290 :
291 0 : TimeDuration total, longest;
292 0 : gcDuration(&total, &longest);
293 :
294 0 : const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
295 0 : const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
296 :
297 : char buffer[1024];
298 0 : if (!nonincremental()) {
299 0 : SprintfLiteral(buffer,
300 : "Max Pause: %.3fms; MMU 20ms: %.1f%%; MMU 50ms: %.1f%%; Total: %.3fms; ",
301 0 : t(longest), mmu20 * 100., mmu50 * 100., t(total));
302 : } else {
303 0 : SprintfLiteral(buffer, "Non-Incremental: %.3fms (%s); ",
304 0 : t(total), ExplainAbortReason(nonincrementalReason_));
305 : }
306 0 : if (!fragments.append(DuplicateString(buffer)))
307 0 : return UniqueChars(nullptr);
308 :
309 0 : SprintfLiteral(buffer,
310 : "Zones: %d of %d (-%d); Compartments: %d of %d (-%d); HeapSize: %.3f MiB; " \
311 : "HeapChange (abs): %+d (%d); ",
312 0 : zoneStats.collectedZoneCount, zoneStats.zoneCount, zoneStats.sweptZoneCount,
313 0 : zoneStats.collectedCompartmentCount, zoneStats.compartmentCount,
314 0 : zoneStats.sweptCompartmentCount,
315 0 : double(preBytes) / bytesPerMiB,
316 0 : counts[STAT_NEW_CHUNK] - counts[STAT_DESTROY_CHUNK],
317 0 : counts[STAT_NEW_CHUNK] + counts[STAT_DESTROY_CHUNK]);
318 0 : if (!fragments.append(DuplicateString(buffer)))
319 0 : return UniqueChars(nullptr);
320 :
321 0 : MOZ_ASSERT_IF(counts[STAT_ARENA_RELOCATED], gckind == GC_SHRINK);
322 0 : if (gckind == GC_SHRINK) {
323 0 : SprintfLiteral(buffer,
324 : "Kind: %s; Relocated: %.3f MiB; ",
325 0 : ExplainInvocationKind(gckind),
326 0 : double(ArenaSize * counts[STAT_ARENA_RELOCATED]) / bytesPerMiB);
327 0 : if (!fragments.append(DuplicateString(buffer)))
328 0 : return UniqueChars(nullptr);
329 : }
330 :
331 0 : return Join(fragments);
332 : }
333 :
334 : UniqueChars
335 0 : Statistics::formatCompactSlicePhaseTimes(const PhaseTimeTable& phaseTimes) const
336 : {
337 0 : static const TimeDuration MaxUnaccountedTime = TimeDuration::FromMicroseconds(100);
338 :
339 0 : FragmentVector fragments;
340 : char buffer[128];
341 0 : for (auto phase : AllPhases()) {
342 0 : DebugOnly<uint8_t> level = phases[phase].depth;
343 0 : MOZ_ASSERT(level < 4);
344 :
345 0 : TimeDuration ownTime = phaseTimes[phase];
346 0 : TimeDuration childTime = SumChildTimes(phase, phaseTimes);
347 0 : if (ownTime > MaxUnaccountedTime) {
348 0 : SprintfLiteral(buffer, "%s: %.3fms", phases[phase].name, t(ownTime));
349 0 : if (!fragments.append(DuplicateString(buffer)))
350 0 : return UniqueChars(nullptr);
351 :
352 0 : if (childTime && (ownTime - childTime) > MaxUnaccountedTime) {
353 0 : MOZ_ASSERT(level < 3);
354 0 : SprintfLiteral(buffer, "%s: %.3fms", "Other", t(ownTime - childTime));
355 0 : if (!fragments.append(DuplicateString(buffer)))
356 0 : return UniqueChars(nullptr);
357 : }
358 : }
359 : }
360 0 : return Join(fragments, ", ");
361 : }
362 :
363 : UniqueChars
364 0 : Statistics::formatDetailedMessage() const
365 : {
366 0 : FragmentVector fragments;
367 :
368 0 : if (!fragments.append(formatDetailedDescription()))
369 0 : return UniqueChars(nullptr);
370 :
371 0 : if (!slices_.empty()) {
372 0 : for (unsigned i = 0; i < slices_.length(); i++) {
373 0 : if (!fragments.append(formatDetailedSliceDescription(i, slices_[i])))
374 0 : return UniqueChars(nullptr);
375 0 : if (!fragments.append(formatDetailedPhaseTimes(slices_[i].phaseTimes)))
376 0 : return UniqueChars(nullptr);
377 : }
378 : }
379 0 : if (!fragments.append(formatDetailedTotals()))
380 0 : return UniqueChars(nullptr);
381 0 : if (!fragments.append(formatDetailedPhaseTimes(phaseTimes)))
382 0 : return UniqueChars(nullptr);
383 :
384 0 : return Join(fragments);
385 : }
386 :
387 : UniqueChars
388 0 : Statistics::formatDetailedDescription() const
389 : {
390 0 : const double bytesPerMiB = 1024 * 1024;
391 :
392 0 : TimeDuration sccTotal, sccLongest;
393 0 : sccDurations(&sccTotal, &sccLongest);
394 :
395 0 : const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
396 0 : const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
397 :
398 : const char* format =
399 0 : "=================================================================\n\
400 : Invocation Kind: %s\n\
401 : Reason: %s\n\
402 : Incremental: %s%s\n\
403 : Zones Collected: %d of %d (-%d)\n\
404 : Compartments Collected: %d of %d (-%d)\n\
405 : MinorGCs since last GC: %d\n\
406 : Store Buffer Overflows: %d\n\
407 : MMU 20ms:%.1f%%; 50ms:%.1f%%\n\
408 : SCC Sweep Total (MaxPause): %.3fms (%.3fms)\n\
409 : HeapSize: %.3f MiB\n\
410 : Chunk Delta (magnitude): %+d (%d)\n\
411 : Arenas Relocated: %.3f MiB\n\
412 : ";
413 : char buffer[1024];
414 0 : SprintfLiteral(buffer, format,
415 0 : ExplainInvocationKind(gckind),
416 0 : ExplainReason(slices_[0].reason),
417 0 : nonincremental() ? "no - " : "yes",
418 0 : nonincremental() ? ExplainAbortReason(nonincrementalReason_) : "",
419 0 : zoneStats.collectedZoneCount, zoneStats.zoneCount, zoneStats.sweptZoneCount,
420 0 : zoneStats.collectedCompartmentCount, zoneStats.compartmentCount,
421 0 : zoneStats.sweptCompartmentCount,
422 : getCount(STAT_MINOR_GC),
423 : getCount(STAT_STOREBUFFER_OVERFLOW),
424 : mmu20 * 100., mmu50 * 100.,
425 : t(sccTotal), t(sccLongest),
426 0 : double(preBytes) / bytesPerMiB,
427 0 : getCount(STAT_NEW_CHUNK) - getCount(STAT_DESTROY_CHUNK),
428 0 : getCount(STAT_NEW_CHUNK) + getCount(STAT_DESTROY_CHUNK),
429 0 : double(ArenaSize * getCount(STAT_ARENA_RELOCATED)) / bytesPerMiB);
430 0 : return DuplicateString(buffer);
431 : }
432 :
433 : UniqueChars
434 0 : Statistics::formatDetailedSliceDescription(unsigned i, const SliceData& slice) const
435 : {
436 : char budgetDescription[200];
437 0 : slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
438 :
439 : const char* format =
440 0 : "\
441 : ---- Slice %u ----\n\
442 : Reason: %s\n\
443 : Reset: %s%s\n\
444 : State: %s -> %s\n\
445 : Page Faults: %ld\n\
446 : Pause: %.3fms of %s budget (@ %.3fms)\n\
447 : ";
448 : char buffer[1024];
449 0 : SprintfLiteral(buffer, format, i, ExplainReason(slice.reason),
450 0 : slice.wasReset() ? "yes - " : "no",
451 0 : slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "",
452 0 : gc::StateName(slice.initialState), gc::StateName(slice.finalState),
453 0 : uint64_t(slice.endFaults - slice.startFaults),
454 0 : t(slice.duration()), budgetDescription, t(slice.start - slices_[0].start));
455 0 : return DuplicateString(buffer);
456 : }
457 :
458 : UniqueChars
459 0 : Statistics::formatDetailedPhaseTimes(const PhaseTimeTable& phaseTimes) const
460 : {
461 0 : static const TimeDuration MaxUnaccountedChildTime = TimeDuration::FromMicroseconds(50);
462 :
463 0 : FragmentVector fragments;
464 : char buffer[128];
465 0 : for (auto phase : AllPhases()) {
466 0 : uint8_t level = phases[phase].depth;
467 0 : TimeDuration ownTime = phaseTimes[phase];
468 0 : TimeDuration childTime = SumChildTimes(phase, phaseTimes);
469 0 : if (!ownTime.IsZero()) {
470 0 : SprintfLiteral(buffer, " %*s: %.3fms\n",
471 0 : level * 2, phases[phase].name, t(ownTime));
472 0 : if (!fragments.append(DuplicateString(buffer)))
473 0 : return UniqueChars(nullptr);
474 :
475 0 : if (childTime && (ownTime - childTime) > MaxUnaccountedChildTime) {
476 0 : SprintfLiteral(buffer, " %*s: %.3fms\n",
477 0 : (level + 1) * 2, "Other", t(ownTime - childTime));
478 0 : if (!fragments.append(DuplicateString(buffer)))
479 0 : return UniqueChars(nullptr);
480 : }
481 : }
482 : }
483 0 : return Join(fragments);
484 : }
485 :
486 : UniqueChars
487 0 : Statistics::formatDetailedTotals() const
488 : {
489 0 : TimeDuration total, longest;
490 0 : gcDuration(&total, &longest);
491 :
492 : const char* format =
493 0 : "\
494 : ---- Totals ----\n\
495 : Total Time: %.3fms\n\
496 : Max Pause: %.3fms\n\
497 : ";
498 : char buffer[1024];
499 0 : SprintfLiteral(buffer, format, t(total), t(longest));
500 0 : return DuplicateString(buffer);
501 : }
502 :
503 : void
504 0 : Statistics::formatJsonSlice(size_t sliceNum, JSONPrinter& json) const
505 : {
506 0 : json.beginObject();
507 0 : formatJsonSliceDescription(sliceNum, slices_[sliceNum], json);
508 :
509 0 : json.beginObjectProperty("times");
510 0 : formatJsonPhaseTimes(slices_[sliceNum].phaseTimes, json);
511 0 : json.endObject();
512 :
513 0 : json.endObject();
514 0 : }
515 :
516 : UniqueChars
517 0 : Statistics::renderJsonSlice(size_t sliceNum) const
518 : {
519 0 : Sprinter printer(nullptr, false);
520 0 : if (!printer.init())
521 0 : return UniqueChars(nullptr);
522 0 : JSONPrinter json(printer);
523 :
524 0 : formatJsonSlice(sliceNum, json);
525 0 : return UniqueChars(printer.release());
526 : }
527 :
528 : UniqueChars
529 0 : Statistics::renderNurseryJson(JSRuntime* rt) const
530 : {
531 0 : Sprinter printer(nullptr, false);
532 0 : if (!printer.init())
533 0 : return UniqueChars(nullptr);
534 0 : JSONPrinter json(printer);
535 0 : rt->gc.nursery().renderProfileJSON(json);
536 0 : return UniqueChars(printer.release());
537 : }
538 :
539 : UniqueChars
540 0 : Statistics::renderJsonMessage(uint64_t timestamp, bool includeSlices) const
541 : {
542 0 : if (aborted)
543 0 : return DuplicateString("{status:\"aborted\"}"); // May return nullptr
544 :
545 0 : Sprinter printer(nullptr, false);
546 0 : if (!printer.init())
547 0 : return UniqueChars(nullptr);
548 0 : JSONPrinter json(printer);
549 :
550 0 : json.beginObject();
551 0 : formatJsonDescription(timestamp, json);
552 :
553 0 : if (includeSlices) {
554 0 : json.beginListProperty("slices");
555 0 : for (unsigned i = 0; i < slices_.length(); i++)
556 0 : formatJsonSlice(i, json);
557 0 : json.endList();
558 : }
559 :
560 0 : json.beginObjectProperty("totals");
561 0 : formatJsonPhaseTimes(phaseTimes, json);
562 0 : json.endObject();
563 :
564 0 : json.endObject();
565 :
566 0 : return UniqueChars(printer.release());
567 : }
568 :
569 : void
570 0 : Statistics::formatJsonDescription(uint64_t timestamp, JSONPrinter& json) const
571 : {
572 0 : json.property("timestamp", timestamp);
573 :
574 0 : TimeDuration total, longest;
575 0 : gcDuration(&total, &longest);
576 0 : json.property("max_pause", longest, JSONPrinter::MILLISECONDS);
577 0 : json.property("total_time", total, JSONPrinter::MILLISECONDS);
578 :
579 0 : json.property("reason", ExplainReason(slices_[0].reason));
580 0 : json.property("zones_collected", zoneStats.collectedZoneCount);
581 0 : json.property("total_zones", zoneStats.zoneCount);
582 0 : json.property("total_compartments", zoneStats.compartmentCount);
583 0 : json.property("minor_gcs", counts[STAT_MINOR_GC]);
584 0 : json.property("store_buffer_overflows", counts[STAT_STOREBUFFER_OVERFLOW]);
585 0 : json.property("slices", slices_.length());
586 :
587 0 : const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
588 0 : const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
589 0 : json.property("mmu_20ms", int(mmu20 * 100));
590 0 : json.property("mmu_50ms", int(mmu50 * 100));
591 :
592 0 : TimeDuration sccTotal, sccLongest;
593 0 : sccDurations(&sccTotal, &sccLongest);
594 0 : json.property("scc_sweep_total", sccTotal, JSONPrinter::MILLISECONDS);
595 0 : json.property("scc_sweep_max_pause", sccLongest, JSONPrinter::MILLISECONDS);
596 :
597 0 : json.property("nonincremental_reason", ExplainAbortReason(nonincrementalReason_));
598 0 : json.property("allocated", uint64_t(preBytes) / 1024 / 1024);
599 0 : json.property("added_chunks", getCount(STAT_NEW_CHUNK));
600 0 : json.property("removed_chunks", getCount(STAT_DESTROY_CHUNK));
601 0 : json.property("major_gc_number", startingMajorGCNumber);
602 0 : json.property("minor_gc_number", startingMinorGCNumber);
603 0 : }
604 :
605 : void
606 0 : Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice, JSONPrinter& json) const
607 : {
608 0 : TimeDuration when = slice.start - slices_[0].start;
609 : char budgetDescription[200];
610 0 : slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
611 0 : TimeStamp originTime = TimeStamp::ProcessCreation();
612 :
613 0 : json.property("slice", i);
614 0 : json.property("pause", slice.duration(), JSONPrinter::MILLISECONDS);
615 0 : json.property("when", when, JSONPrinter::MILLISECONDS);
616 0 : json.property("reason", ExplainReason(slice.reason));
617 0 : json.property("initial_state", gc::StateName(slice.initialState));
618 0 : json.property("final_state", gc::StateName(slice.finalState));
619 0 : json.property("budget", budgetDescription);
620 0 : json.property("major_gc_number", startingMajorGCNumber);
621 0 : if (thresholdTriggered) {
622 0 : json.floatProperty("trigger_amount", triggerAmount, 0);
623 0 : json.floatProperty("trigger_threshold", triggerThreshold, 0);
624 : }
625 0 : json.property("page_faults", int64_t(slice.endFaults - slice.startFaults));
626 0 : json.property("start_timestamp", slice.start - originTime, JSONPrinter::SECONDS);
627 0 : json.property("end_timestamp", slice.end - originTime, JSONPrinter::SECONDS);
628 0 : }
629 :
630 : void
631 0 : Statistics::formatJsonPhaseTimes(const PhaseTimeTable& phaseTimes, JSONPrinter& json) const
632 : {
633 0 : for (auto phase : AllPhases()) {
634 0 : TimeDuration ownTime = phaseTimes[phase];
635 0 : if (!ownTime.IsZero())
636 0 : json.property(phases[phase].path, ownTime, JSONPrinter::MILLISECONDS);
637 : }
638 0 : }
639 :
640 4 : Statistics::Statistics(JSRuntime* rt)
641 : : runtime(rt),
642 : fp(nullptr),
643 : nonincrementalReason_(gc::AbortReason::None),
644 : preBytes(0),
645 : thresholdTriggered(false),
646 : triggerAmount(0.0),
647 : triggerThreshold(0.0),
648 : maxPauseInInterval(0),
649 : sliceCallback(nullptr),
650 : nurseryCollectionCallback(nullptr),
651 : aborted(false),
652 : enableProfiling_(false),
653 4 : sliceCount_(0)
654 : {
655 24 : for (auto& count : counts)
656 20 : count = 0;
657 4 : PodZero(&totalTimes_);
658 :
659 4 : MOZ_ALWAYS_TRUE(phaseStack.reserve(MAX_PHASE_NESTING));
660 4 : MOZ_ALWAYS_TRUE(suspendedPhases.reserve(MAX_SUSPENDED_PHASES));
661 :
662 4 : const char* env = getenv("MOZ_GCTIMER");
663 4 : if (env) {
664 0 : if (strcmp(env, "none") == 0) {
665 0 : fp = nullptr;
666 0 : } else if (strcmp(env, "stdout") == 0) {
667 0 : fp = stdout;
668 0 : } else if (strcmp(env, "stderr") == 0) {
669 0 : fp = stderr;
670 : } else {
671 0 : fp = fopen(env, "a");
672 0 : if (!fp)
673 0 : MOZ_CRASH("Failed to open MOZ_GCTIMER log file.");
674 : }
675 : }
676 :
677 4 : env = getenv("JS_GC_PROFILE");
678 4 : if (env) {
679 0 : if (0 == strcmp(env, "help")) {
680 : fprintf(stderr, "JS_GC_PROFILE=N\n"
681 0 : "\tReport major GC's taking more than N milliseconds.\n");
682 0 : exit(0);
683 : }
684 0 : enableProfiling_ = true;
685 0 : profileThreshold_ = TimeDuration::FromMilliseconds(atoi(env));
686 : }
687 4 : }
688 :
689 0 : Statistics::~Statistics()
690 : {
691 0 : if (fp && fp != stdout && fp != stderr)
692 0 : fclose(fp);
693 0 : }
694 :
695 : /* static */ bool
696 3 : Statistics::initialize()
697 : {
698 : #ifdef DEBUG
699 : // Sanity check generated tables.
700 291 : for (auto i : AllPhases()) {
701 288 : auto parent = phases[i].parent;
702 288 : if (parent != Phase::NONE) {
703 252 : MOZ_ASSERT(phases[i].depth == phases[parent].depth + 1);
704 : }
705 288 : auto firstChild = phases[i].firstChild;
706 288 : if (firstChild != Phase::NONE) {
707 54 : MOZ_ASSERT(i == phases[firstChild].parent);
708 54 : MOZ_ASSERT(phases[i].depth == phases[firstChild].depth - 1);
709 : }
710 288 : auto nextSibling = phases[i].nextSibling;
711 288 : if (nextSibling != Phase::NONE) {
712 198 : MOZ_ASSERT(parent == phases[nextSibling].parent);
713 198 : MOZ_ASSERT(phases[i].depth == phases[nextSibling].depth);
714 : }
715 288 : auto nextInPhase = phases[i].nextInPhase;
716 288 : if (nextInPhase != Phase::NONE) {
717 81 : MOZ_ASSERT(phases[i].phaseKind == phases[nextInPhase].phaseKind);
718 81 : MOZ_ASSERT(parent != phases[nextInPhase].parent);
719 : }
720 : }
721 210 : for (auto i : AllPhaseKinds()) {
722 207 : MOZ_ASSERT(phases[phaseKinds[i].firstPhase].phaseKind == i);
723 14490 : for (auto j : AllPhaseKinds()) {
724 14283 : MOZ_ASSERT_IF(i != j,
725 : phaseKinds[i].telemetryBucket != phaseKinds[j].telemetryBucket);
726 : }
727 : }
728 : #endif
729 :
730 3 : return true;
731 : }
732 :
733 : JS::GCSliceCallback
734 9 : Statistics::setSliceCallback(JS::GCSliceCallback newCallback)
735 : {
736 9 : JS::GCSliceCallback oldCallback = sliceCallback;
737 9 : sliceCallback = newCallback;
738 9 : return oldCallback;
739 : }
740 :
741 : JS::GCNurseryCollectionCallback
742 3 : Statistics::setNurseryCollectionCallback(JS::GCNurseryCollectionCallback newCallback)
743 : {
744 3 : auto oldCallback = nurseryCollectionCallback;
745 3 : nurseryCollectionCallback = newCallback;
746 3 : return oldCallback;
747 : }
748 :
749 : TimeDuration
750 0 : Statistics::clearMaxGCPauseAccumulator()
751 : {
752 0 : TimeDuration prior = maxPauseInInterval;
753 0 : maxPauseInInterval = 0;
754 0 : return prior;
755 : }
756 :
757 : TimeDuration
758 0 : Statistics::getMaxGCPauseSinceClear()
759 : {
760 0 : return maxPauseInInterval;
761 : }
762 :
763 : // Sum up the time for a phase, including instances of the phase with different
764 : // parents.
765 : static TimeDuration
766 70 : SumPhase(PhaseKind phaseKind, const Statistics::PhaseTimeTable& times)
767 : {
768 70 : TimeDuration sum = 0;
769 170 : for (Phase phase = phaseKinds[phaseKind].firstPhase;
770 170 : phase != Phase::NONE;
771 100 : phase = phases[phase].nextInPhase)
772 : {
773 100 : sum += times[phase];
774 : }
775 70 : return sum;
776 : }
777 :
778 : static void
779 84 : CheckSelfTime(Phase parent,
780 : Phase child,
781 : const Statistics::PhaseTimeTable& times,
782 : const Statistics::PhaseTimeTable& selfTimes,
783 : TimeDuration childTime)
784 : {
785 84 : if (selfTimes[parent] < childTime) {
786 0 : fprintf(stderr,
787 : "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
788 0 : phases[parent].name,
789 0 : times[parent].ToMilliseconds(),
790 0 : selfTimes[parent].ToMilliseconds(),
791 0 : phases[child].name,
792 0 : childTime.ToMilliseconds());
793 0 : fflush(stderr);
794 0 : MOZ_CRASH();
795 : }
796 84 : }
797 :
798 : static PhaseKind
799 1 : LongestPhaseSelfTime(const Statistics::PhaseTimeTable& times)
800 : {
801 : // Start with total times per expanded phase, including children's times.
802 1 : Statistics::PhaseTimeTable selfTimes(times);
803 :
804 : // We have the total time spent in each phase, including descendant times.
805 : // Loop over the children and subtract their times from their parent's self
806 : // time.
807 97 : for (auto i : AllPhases()) {
808 96 : Phase parent = phases[i].parent;
809 96 : if (parent != Phase::NONE) {
810 84 : CheckSelfTime(parent, i, times, selfTimes, times[i]);
811 84 : selfTimes[parent] -= times[i];
812 : }
813 : }
814 :
815 : // Sum expanded phases corresponding to the same phase.
816 1 : EnumeratedArray<PhaseKind, PhaseKind::LIMIT, TimeDuration> phaseTimes;
817 70 : for (auto i : AllPhaseKinds())
818 69 : phaseTimes[i] = SumPhase(i, selfTimes);
819 :
820 : // Loop over this table to find the longest phase.
821 1 : TimeDuration longestTime = 0;
822 1 : PhaseKind longestPhase = PhaseKind::NONE;
823 70 : for (auto i : AllPhaseKinds()) {
824 69 : if (phaseTimes[i] > longestTime) {
825 4 : longestTime = phaseTimes[i];
826 4 : longestPhase = i;
827 : }
828 : }
829 :
830 1 : return longestPhase;
831 : }
832 :
833 : void
834 0 : Statistics::printStats()
835 : {
836 0 : if (aborted) {
837 0 : fprintf(fp, "OOM during GC statistics collection. The report is unavailable for this GC.\n");
838 : } else {
839 0 : UniqueChars msg = formatDetailedMessage();
840 0 : if (msg) {
841 : double secSinceStart =
842 0 : (slices_[0].start - TimeStamp::ProcessCreation()).ToSeconds();
843 0 : fprintf(fp, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
844 : }
845 : }
846 0 : fflush(fp);
847 0 : }
848 :
849 : void
850 1 : Statistics::beginGC(JSGCInvocationKind kind)
851 : {
852 1 : slices_.clearAndFree();
853 1 : sccTimes.clearAndFree();
854 1 : gckind = kind;
855 1 : nonincrementalReason_ = gc::AbortReason::None;
856 :
857 1 : preBytes = runtime->gc.usage.gcBytes();
858 1 : startingMajorGCNumber = runtime->gc.majorGCCount();
859 1 : }
860 :
861 : void
862 0 : Statistics::endGC()
863 : {
864 0 : TimeDuration sccTotal, sccLongest;
865 0 : sccDurations(&sccTotal, &sccLongest);
866 :
867 0 : runtime->addTelemetry(JS_TELEMETRY_GC_IS_ZONE_GC, !zoneStats.isCollectingAllZones());
868 0 : TimeDuration markTotal = SumPhase(PhaseKind::MARK, phaseTimes);
869 0 : TimeDuration markRootsTotal = SumPhase(PhaseKind::MARK_ROOTS, phaseTimes);
870 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MARK_MS, t(markTotal));
871 0 : runtime->addTelemetry(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[Phase::SWEEP]));
872 0 : if (runtime->gc.isCompactingGc()) {
873 0 : runtime->addTelemetry(JS_TELEMETRY_GC_COMPACT_MS,
874 0 : t(phaseTimes[Phase::COMPACT]));
875 : }
876 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MARK_ROOTS_MS, t(markRootsTotal));
877 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MARK_GRAY_MS, t(phaseTimes[Phase::SWEEP_MARK_GRAY]));
878 0 : runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL, nonincremental());
879 0 : if (nonincremental())
880 0 : runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL_REASON, uint32_t(nonincrementalReason_));
881 0 : runtime->addTelemetry(JS_TELEMETRY_GC_INCREMENTAL_DISABLED, !runtime->gc.isIncrementalGCAllowed());
882 0 : runtime->addTelemetry(JS_TELEMETRY_GC_SCC_SWEEP_TOTAL_MS, t(sccTotal));
883 0 : runtime->addTelemetry(JS_TELEMETRY_GC_SCC_SWEEP_MAX_PAUSE_MS, t(sccLongest));
884 :
885 0 : TimeDuration total, longest;
886 0 : gcDuration(&total, &longest);
887 :
888 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MS, t(total));
889 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MAX_PAUSE_MS, t(longest));
890 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MAX_PAUSE_MS_2, t(longest));
891 :
892 0 : const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
893 0 : runtime->addTelemetry(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);
894 0 : thresholdTriggered = false;
895 0 : }
896 :
897 : void
898 24 : Statistics::beginNurseryCollection(JS::gcreason::Reason reason)
899 : {
900 24 : count(STAT_MINOR_GC);
901 24 : startingMinorGCNumber = runtime->gc.minorGCCount();
902 24 : if (nurseryCollectionCallback) {
903 24 : (*nurseryCollectionCallback)(TlsContext.get(),
904 : JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START,
905 24 : reason);
906 : }
907 24 : }
908 :
909 : void
910 24 : Statistics::endNurseryCollection(JS::gcreason::Reason reason)
911 : {
912 24 : if (nurseryCollectionCallback) {
913 24 : (*nurseryCollectionCallback)(TlsContext.get(),
914 : JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END,
915 24 : reason);
916 : }
917 24 : }
918 :
919 : void
920 3 : Statistics::beginSlice(const ZoneGCStats& zoneStats, JSGCInvocationKind gckind,
921 : SliceBudget budget, JS::gcreason::Reason reason)
922 : {
923 3 : this->zoneStats = zoneStats;
924 :
925 3 : bool first = !runtime->gc.isIncrementalGCInProgress();
926 3 : if (first)
927 1 : beginGC(gckind);
928 :
929 6 : if (!slices_.emplaceBack(budget,
930 : reason,
931 6 : TimeStamp::Now(),
932 6 : GetPageFaultCount(),
933 6 : runtime->gc.state()))
934 : {
935 : // If we are OOM, set a flag to indicate we have missing slice data.
936 0 : aborted = true;
937 0 : return;
938 : }
939 :
940 3 : runtime->addTelemetry(JS_TELEMETRY_GC_REASON, reason);
941 :
942 : // Slice callbacks should only fire for the outermost level.
943 3 : bool wasFullGC = zoneStats.isCollectingAllZones();
944 3 : if (sliceCallback) {
945 3 : JSContext* cx = TlsContext.get();
946 3 : JS::GCDescription desc(!wasFullGC, false, gckind, reason);
947 3 : if (first)
948 1 : (*sliceCallback)(cx, JS::GC_CYCLE_BEGIN, desc);
949 3 : (*sliceCallback)(cx, JS::GC_SLICE_BEGIN, desc);
950 : }
951 : }
952 :
953 : void
954 3 : Statistics::endSlice()
955 : {
956 3 : if (!aborted) {
957 3 : auto& slice = slices_.back();
958 3 : slice.end = TimeStamp::Now();
959 3 : slice.endFaults = GetPageFaultCount();
960 3 : slice.finalState = runtime->gc.state();
961 :
962 3 : TimeDuration sliceTime = slice.end - slice.start;
963 3 : runtime->addTelemetry(JS_TELEMETRY_GC_SLICE_MS, t(sliceTime));
964 3 : runtime->addTelemetry(JS_TELEMETRY_GC_RESET, slice.wasReset());
965 3 : if (slice.wasReset())
966 0 : runtime->addTelemetry(JS_TELEMETRY_GC_RESET_REASON, uint32_t(slice.resetReason));
967 :
968 3 : if (slice.budget.isTimeBudget()) {
969 3 : int64_t budget_ms = slice.budget.timeBudget.budget;
970 3 : runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_MS, budget_ms);
971 3 : if (budget_ms == runtime->gc.defaultSliceBudget())
972 0 : runtime->addTelemetry(JS_TELEMETRY_GC_ANIMATION_MS, t(sliceTime));
973 :
974 : // Record any phase that goes more than 2x over its budget.
975 3 : if (sliceTime.ToMilliseconds() > 2 * budget_ms) {
976 1 : reportLongestPhase(slice.phaseTimes, JS_TELEMETRY_GC_SLOW_PHASE);
977 : // If we spend a significant length of time waiting for parallel
978 : // tasks then report the longest task.
979 1 : TimeDuration joinTime = SumPhase(PhaseKind::JOIN_PARALLEL_TASKS, slice.phaseTimes);
980 1 : if (joinTime.ToMilliseconds() > budget_ms)
981 0 : reportLongestPhase(slice.parallelTimes, JS_TELEMETRY_GC_SLOW_TASK);
982 : }
983 : }
984 :
985 3 : sliceCount_++;
986 : }
987 :
988 3 : bool last = !runtime->gc.isIncrementalGCInProgress();
989 3 : if (last) {
990 0 : if (fp)
991 0 : printStats();
992 :
993 0 : if (!aborted)
994 0 : endGC();
995 : }
996 :
997 3 : if (enableProfiling_ && !aborted && slices_.back().duration() >= profileThreshold_)
998 0 : printSliceProfile();
999 :
1000 : // Slice callbacks should only fire for the outermost level.
1001 3 : if (!aborted) {
1002 3 : bool wasFullGC = zoneStats.isCollectingAllZones();
1003 3 : if (sliceCallback) {
1004 3 : JSContext* cx = TlsContext.get();
1005 3 : JS::GCDescription desc(!wasFullGC, last, gckind, slices_.back().reason);
1006 3 : (*sliceCallback)(cx, JS::GC_SLICE_END, desc);
1007 3 : if (last)
1008 0 : (*sliceCallback)(cx, JS::GC_CYCLE_END, desc);
1009 : }
1010 : }
1011 :
1012 : // Do this after the slice callback since it uses these values.
1013 3 : if (last) {
1014 0 : for (auto& count : counts)
1015 0 : count = 0;
1016 :
1017 : // Clear the timers at the end of a GC, preserving the data for PhaseKind::MUTATOR.
1018 0 : auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
1019 0 : auto mutatorTime = phaseTimes[Phase::MUTATOR];
1020 0 : PodZero(&phaseStartTimes);
1021 0 : PodZero(&phaseTimes);
1022 0 : phaseStartTimes[Phase::MUTATOR] = mutatorStartTime;
1023 0 : phaseTimes[Phase::MUTATOR] = mutatorTime;
1024 : }
1025 :
1026 3 : aborted = false;
1027 3 : }
1028 :
1029 : void
1030 1 : Statistics::reportLongestPhase(const PhaseTimeTable& times, int telemetryId)
1031 : {
1032 1 : PhaseKind longest = LongestPhaseSelfTime(times);
1033 1 : if (longest == PhaseKind::NONE)
1034 0 : return;
1035 :
1036 1 : uint8_t bucket = phaseKinds[longest].telemetryBucket;
1037 1 : runtime->addTelemetry(telemetryId, bucket);
1038 : }
1039 :
1040 : bool
1041 0 : Statistics::startTimingMutator()
1042 : {
1043 0 : if (phaseStack.length() != 0) {
1044 : // Should only be called from outside of GC.
1045 0 : MOZ_ASSERT(phaseStack.length() == 1);
1046 0 : MOZ_ASSERT(phaseStack[0] == Phase::MUTATOR);
1047 0 : return false;
1048 : }
1049 :
1050 0 : MOZ_ASSERT(suspendedPhases.empty());
1051 :
1052 0 : timedGCTime = 0;
1053 0 : phaseStartTimes[Phase::MUTATOR] = TimeStamp();
1054 0 : phaseTimes[Phase::MUTATOR] = 0;
1055 0 : timedGCStart = TimeStamp();
1056 :
1057 0 : beginPhase(PhaseKind::MUTATOR);
1058 0 : return true;
1059 : }
1060 :
1061 : bool
1062 0 : Statistics::stopTimingMutator(double& mutator_ms, double& gc_ms)
1063 : {
1064 : // This should only be called from outside of GC, while timing the mutator.
1065 0 : if (phaseStack.length() != 1 || phaseStack[0] != Phase::MUTATOR)
1066 0 : return false;
1067 :
1068 0 : endPhase(PhaseKind::MUTATOR);
1069 0 : mutator_ms = t(phaseTimes[Phase::MUTATOR]);
1070 0 : gc_ms = t(timedGCTime);
1071 :
1072 0 : return true;
1073 : }
1074 :
1075 : void
1076 0 : Statistics::suspendPhases(PhaseKind suspension)
1077 : {
1078 0 : MOZ_ASSERT(suspension == PhaseKind::EXPLICIT_SUSPENSION ||
1079 : suspension == PhaseKind::IMPLICIT_SUSPENSION);
1080 0 : while (!phaseStack.empty()) {
1081 0 : MOZ_ASSERT(suspendedPhases.length() < MAX_SUSPENDED_PHASES);
1082 0 : Phase parent = phaseStack.back();
1083 0 : suspendedPhases.infallibleAppend(parent);
1084 0 : recordPhaseEnd(parent);
1085 : }
1086 0 : suspendedPhases.infallibleAppend(lookupChildPhase(suspension));
1087 0 : }
1088 :
1089 : void
1090 0 : Statistics::resumePhases()
1091 : {
1092 0 : MOZ_ASSERT(suspendedPhases.back() == Phase::EXPLICIT_SUSPENSION ||
1093 : suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION);
1094 0 : suspendedPhases.popBack();
1095 :
1096 0 : while (!suspendedPhases.empty() &&
1097 0 : suspendedPhases.back() != Phase::EXPLICIT_SUSPENSION &&
1098 0 : suspendedPhases.back() != Phase::IMPLICIT_SUSPENSION)
1099 : {
1100 0 : Phase resumePhase = suspendedPhases.popCopy();
1101 0 : if (resumePhase == Phase::MUTATOR)
1102 0 : timedGCTime += TimeStamp::Now() - timedGCStart;
1103 0 : recordPhaseBegin(resumePhase);
1104 : }
1105 0 : }
1106 :
1107 : void
1108 142 : Statistics::beginPhase(PhaseKind phaseKind)
1109 : {
1110 : // No longer timing these phases. We should never see these.
1111 142 : MOZ_ASSERT(phaseKind != PhaseKind::GC_BEGIN && phaseKind != PhaseKind::GC_END);
1112 :
1113 : // PhaseKind::MUTATOR is suspended while performing GC.
1114 142 : if (currentPhase() == Phase::MUTATOR)
1115 0 : suspendPhases(PhaseKind::IMPLICIT_SUSPENSION);
1116 :
1117 142 : recordPhaseBegin(lookupChildPhase(phaseKind));
1118 142 : }
1119 :
1120 : void
1121 142 : Statistics::recordPhaseBegin(Phase phase)
1122 : {
1123 142 : MOZ_ASSERT(CurrentThreadCanAccessRuntime(runtime));
1124 :
1125 : // Guard against any other re-entry.
1126 142 : MOZ_ASSERT(!phaseStartTimes[phase]);
1127 :
1128 142 : MOZ_ASSERT(phaseStack.length() < MAX_PHASE_NESTING);
1129 :
1130 142 : Phase current = currentPhase();
1131 142 : MOZ_ASSERT(phases[phase].parent == current);
1132 :
1133 142 : TimeStamp now = TimeStamp::Now();
1134 :
1135 142 : if (current != Phase::NONE) {
1136 : #ifdef ANDROID
1137 : // Sadly this happens sometimes.
1138 : if (now < phaseStartTimes[currentPhase()]) {
1139 : now = phaseStartTimes[currentPhase()];
1140 : aborted = true;
1141 : }
1142 : #endif
1143 :
1144 89 : MOZ_RELEASE_ASSERT(now >= phaseStartTimes[currentPhase()]);
1145 : }
1146 :
1147 142 : phaseStack.infallibleAppend(phase);
1148 142 : phaseStartTimes[phase] = now;
1149 142 : }
1150 :
1151 : void
1152 142 : Statistics::recordPhaseEnd(Phase phase)
1153 : {
1154 142 : MOZ_ASSERT(CurrentThreadCanAccessRuntime(runtime));
1155 :
1156 142 : MOZ_ASSERT(phaseStartTimes[phase]);
1157 :
1158 142 : TimeStamp now = TimeStamp::Now();
1159 :
1160 : #ifdef ANDROID
1161 : // Sadly this happens sometimes.
1162 : if (now < phaseStartTimes[phase]) {
1163 : now = phaseStartTimes[phase];
1164 : aborted = true;
1165 : }
1166 : #endif
1167 :
1168 142 : MOZ_RELEASE_ASSERT(now >= phaseStartTimes[phase]);
1169 :
1170 142 : if (phase == Phase::MUTATOR)
1171 0 : timedGCStart = now;
1172 :
1173 142 : phaseStack.popBack();
1174 :
1175 142 : TimeDuration t = now - phaseStartTimes[phase];
1176 142 : if (!slices_.empty())
1177 49 : slices_.back().phaseTimes[phase] += t;
1178 142 : phaseTimes[phase] += t;
1179 142 : phaseStartTimes[phase] = TimeStamp();
1180 142 : }
1181 :
1182 : void
1183 142 : Statistics::endPhase(PhaseKind phaseKind)
1184 : {
1185 142 : Phase phase = currentPhase();
1186 142 : MOZ_ASSERT(phase != Phase::NONE);
1187 142 : MOZ_ASSERT(phases[phase].phaseKind == phaseKind);
1188 :
1189 142 : recordPhaseEnd(phase);
1190 :
1191 : // When emptying the stack, we may need to return to timing the mutator
1192 : // (PhaseKind::MUTATOR).
1193 337 : if (phaseStack.empty() &&
1194 142 : !suspendedPhases.empty() &&
1195 0 : suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION)
1196 : {
1197 0 : resumePhases();
1198 : }
1199 142 : }
1200 :
1201 : void
1202 2 : Statistics::recordParallelPhase(PhaseKind phaseKind, TimeDuration duration)
1203 : {
1204 2 : Phase phase = lookupChildPhase(phaseKind);
1205 :
1206 : // Record the duration for all phases in the tree up to the root. This is
1207 : // not strictly necessary but makes the invariant that parent phase times
1208 : // include their children apply to both phaseTimes and parallelTimes.
1209 10 : while (phase != Phase::NONE) {
1210 4 : if (!slices_.empty())
1211 4 : slices_.back().parallelTimes[phase] += duration;
1212 4 : parallelTimes[phase] += duration;
1213 4 : phase = phases[phase].parent;
1214 : }
1215 2 : }
1216 :
1217 : void
1218 0 : Statistics::endParallelPhase(PhaseKind phaseKind, const GCParallelTask* task)
1219 : {
1220 0 : Phase phase = lookupChildPhase(phaseKind);
1221 0 : phaseStack.popBack();
1222 :
1223 0 : if (!slices_.empty())
1224 0 : slices_.back().phaseTimes[phase] += task->duration();
1225 0 : phaseTimes[phase] += task->duration();
1226 0 : phaseStartTimes[phase] = TimeStamp();
1227 0 : }
1228 :
1229 : TimeStamp
1230 0 : Statistics::beginSCC()
1231 : {
1232 0 : return TimeStamp::Now();
1233 : }
1234 :
1235 : void
1236 0 : Statistics::endSCC(unsigned scc, TimeStamp start)
1237 : {
1238 0 : if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1))
1239 0 : return;
1240 :
1241 0 : sccTimes[scc] += TimeStamp::Now() - start;
1242 : }
1243 :
1244 : /*
1245 : * MMU (minimum mutator utilization) is a measure of how much garbage collection
1246 : * is affecting the responsiveness of the system. MMU measurements are given
1247 : * with respect to a certain window size. If we report MMU(50ms) = 80%, then
1248 : * that means that, for any 50ms window of time, at least 80% of the window is
1249 : * devoted to the mutator. In other words, the GC is running for at most 20% of
1250 : * the window, or 10ms. The GC can run multiple slices during the 50ms window
1251 : * as long as the total time it spends is at most 10ms.
1252 : */
1253 : double
1254 0 : Statistics::computeMMU(TimeDuration window) const
1255 : {
1256 0 : MOZ_ASSERT(!slices_.empty());
1257 :
1258 0 : TimeDuration gc = slices_[0].end - slices_[0].start;
1259 0 : TimeDuration gcMax = gc;
1260 :
1261 0 : if (gc >= window)
1262 0 : return 0.0;
1263 :
1264 0 : int startIndex = 0;
1265 0 : for (size_t endIndex = 1; endIndex < slices_.length(); endIndex++) {
1266 0 : auto* startSlice = &slices_[startIndex];
1267 0 : auto& endSlice = slices_[endIndex];
1268 0 : gc += endSlice.end - endSlice.start;
1269 :
1270 0 : while (endSlice.end - startSlice->end >= window) {
1271 0 : gc -= startSlice->end - startSlice->start;
1272 0 : startSlice = &slices_[++startIndex];
1273 : }
1274 :
1275 0 : TimeDuration cur = gc;
1276 0 : if (endSlice.end - startSlice->start > window)
1277 0 : cur -= (endSlice.end - startSlice->start - window);
1278 0 : if (cur > gcMax)
1279 0 : gcMax = cur;
1280 : }
1281 :
1282 0 : return double((window - gcMax) / window);
1283 : }
1284 :
1285 : void
1286 0 : Statistics::maybePrintProfileHeaders()
1287 : {
1288 : static int printedHeader = 0;
1289 0 : if ((printedHeader++ % 200) == 0) {
1290 0 : printProfileHeader();
1291 0 : for (ZoneGroupsIter group(runtime); !group.done(); group.next()) {
1292 0 : if (group->nursery().enableProfiling()) {
1293 0 : Nursery::printProfileHeader();
1294 0 : break;
1295 : }
1296 : }
1297 : }
1298 0 : }
1299 :
1300 : void
1301 0 : Statistics::printProfileHeader()
1302 : {
1303 0 : if (!enableProfiling_)
1304 0 : return;
1305 :
1306 0 : fprintf(stderr, "MajorGC: Reason States ");
1307 0 : fprintf(stderr, " %6s", "total");
1308 : #define PRINT_PROFILE_HEADER(name, text, phase) \
1309 : fprintf(stderr, " %6s", text);
1310 0 : FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_HEADER)
1311 : #undef PRINT_PROFILE_HEADER
1312 0 : fprintf(stderr, "\n");
1313 : }
1314 :
1315 : /* static */ void
1316 0 : Statistics::printProfileTimes(const ProfileDurations& times)
1317 : {
1318 0 : for (auto time : times)
1319 0 : fprintf(stderr, " %6" PRIi64, static_cast<int64_t>(time.ToMilliseconds()));
1320 0 : fprintf(stderr, "\n");
1321 0 : }
1322 :
1323 : void
1324 0 : Statistics::printSliceProfile()
1325 : {
1326 0 : const SliceData& slice = slices_.back();
1327 :
1328 0 : maybePrintProfileHeaders();
1329 :
1330 0 : fprintf(stderr, "MajorGC: %20s %1d -> %1d ",
1331 0 : ExplainReason(slice.reason), int(slice.initialState), int(slice.finalState));
1332 :
1333 0 : ProfileDurations times;
1334 0 : times[ProfileKey::Total] = slice.duration();
1335 0 : totalTimes_[ProfileKey::Total] += times[ProfileKey::Total];
1336 :
1337 : #define GET_PROFILE_TIME(name, text, phase) \
1338 : times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
1339 : totalTimes_[ProfileKey::name] += times[ProfileKey::name];
1340 0 : FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
1341 : #undef GET_PROFILE_TIME
1342 :
1343 0 : printProfileTimes(times);
1344 0 : }
1345 :
1346 : void
1347 0 : Statistics::printTotalProfileTimes()
1348 : {
1349 0 : if (enableProfiling_) {
1350 0 : fprintf(stderr, "MajorGC TOTALS: %7" PRIu64 " slices: ", sliceCount_);
1351 0 : printProfileTimes(totalTimes_);
1352 : }
1353 0 : }
1354 :
|
