js/src/gc/Statistics.cpp

   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/. */
   6
   7 #include "gc/Statistics.h"
   8
   9 #include "mozilla/DebugOnly.h"
  10 #include "mozilla/Sprintf.h"
  11 #include "mozilla/TimeStamp.h"
  12
  13 #include <algorithm>
  14 #include <stdarg.h>
  15 #include <stdio.h>
  16 #include <type_traits>
  17
  18 #include "gc/GC.h"
  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"
  26 #include "vm/Time.h"
  27
  28 #include "gc/PrivateIterators-inl.h"
  29
  30 using namespace js;
  31 using namespace js::gc;
  32 using namespace js::gcstats;
  33
  34 using mozilla::DebugOnly;
  35 using mozilla::EnumeratedArray;
  36 using mozilla::Maybe;
  37 using mozilla::TimeDuration;
  38 using mozilla::TimeStamp;
  39
  40 static const size_t BYTES_PER_MB = 1024 * 1024;
  41
  42 /*
  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.
  46  */
  47 static_assert(JS::GCReason::NUM_TELEMETRY_REASONS >= JS::GCReason::NUM_REASONS);
  48
  49 static inline auto AllPhaseKinds() {
  50   return mozilla::MakeEnumeratedRange(PhaseKind::FIRST, PhaseKind::LIMIT);
  51 }
  52
  53 static inline auto MajorGCPhaseKinds() {
  54   return mozilla::MakeEnumeratedRange(PhaseKind::GC_BEGIN,
  55                                       PhaseKind(size_t(PhaseKind::GC_END) + 1));
  56 }
  57
  58 static const char* ExplainGCOptions(JS::GCOptions options) {
  59   switch (options) {
  60     case JS::GCOptions::Normal:
  61       return "Normal";
  62     case JS::GCOptions::Shrink:
  63       return "Shrink";
  64     case JS::GCOptions::Shutdown:
  65       return "Shutdown";
  66   }
  67
  68   MOZ_CRASH("Unexpected GCOptions value");
  69 }
  70
  71 JS_PUBLIC_API const char* JS::ExplainGCReason(JS::GCReason reason) {
  72   switch (reason) {
  73 #define SWITCH_REASON(name, _) \
  74   case JS::GCReason::name:     \
  75     return #name;
  76     GCREASONS(SWITCH_REASON)
  77 #undef SWITCH_REASON
  78
  79     case JS::GCReason::NO_REASON:
  80       return "NO_REASON";
  81
  82     default:
  83       MOZ_CRASH("bad GC reason");
  84   }
  85 }
  86
  87 JS_PUBLIC_API bool JS::InternalGCReason(JS::GCReason reason) {
  88   return reason < JS::GCReason::FIRST_FIREFOX_REASON;
  89 }
  90
  91 const char* js::gcstats::ExplainAbortReason(GCAbortReason reason) {
  92   switch (reason) {
  93 #define SWITCH_REASON(name, _) \
  94   case GCAbortReason::name:    \
  95     return #name;
  96     GC_ABORT_REASONS(SWITCH_REASON)
  97
  98     default:
  99       MOZ_CRASH("bad GC abort reason");
 100 #undef SWITCH_REASON
 101   }
 102 }
 103
 104 static FILE* MaybeOpenFileFromEnv(const char* env,
 105                                   FILE* defaultFile = nullptr) {
 106   const char* value = getenv(env);
 107   if (!value) {
 108     return defaultFile;
 109   }
 110
 111   FILE* file;
 112   if (strcmp(value, "none") == 0) {
 113     file = nullptr;
 114   } else if (strcmp(value, "stdout") == 0) {
 115     file = stdout;
 116   } else if (strcmp(value, "stderr") == 0) {
 117     file = stderr;
 118   } else {
 119     char path[300];
 120     if (value[0] != '/') {
 121       const char* dir = getenv("MOZ_UPLOAD_DIR");
 122       if (dir) {
 123         SprintfLiteral(path, "%s/%s", dir, value);
 124         value = path;
 125       }
 126     }
 127
 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.");
 132     }
 133   }
 134
 135   return file;
 136 }
 137
 138 struct PhaseKindInfo {
 139   Phase firstPhase;
 140   uint8_t telemetryBucket;
 141   const char* name;
 142 };
 143
 144 // PhaseInfo objects form a tree.
 145 struct PhaseInfo {
 146   Phase parent;
 147   Phase firstChild;
 148   Phase nextSibling;
 149   Phase nextWithPhaseKind;
 150   PhaseKind phaseKind;
 151   uint8_t depth;
 152   const char* name;
 153   const char* path;
 154 };
 155
 156 // A table of PhaseInfo indexed by Phase.
 157 using PhaseTable = EnumeratedArray<Phase, Phase::LIMIT, PhaseInfo>;
 158
 159 // A table of PhaseKindInfo indexed by PhaseKind.
 160 using PhaseKindTable =
 161     EnumeratedArray<PhaseKind, PhaseKind::LIMIT, PhaseKindInfo>;
 162
 163 #include "gc/StatsPhasesGenerated.inc"
 164
 165 // Iterate the phases in a phase kind.
 166 class PhaseIter {
 167   Phase phase;
 168
 169  public:
 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; }
 175 };
 176
 177 static double t(TimeDuration duration) { return duration.ToMilliseconds(); }
 178
 179 static TimeDuration TimeBetween(TimeStamp start, TimeStamp end) {
 180 #ifndef XP_WIN
 181   MOZ_ASSERT(end >= start);
 182 #else
 183   // Sadly this happens sometimes.
 184   if (end < start) {
 185     return TimeDuration::Zero();
 186   }
 187 #endif
 188   return end - start;
 189 }
 190
 191 inline JSContext* Statistics::context() {
 192   return gc->rt->mainContextFromOwnThread();
 193 }
 194
 195 inline Phase Statistics::currentPhase() const {
 196   return phaseStack.empty() ? Phase::NONE : phaseStack.back();
 197 }
 198
 199 PhaseKind Statistics::currentPhaseKind() const {
 200   // Public API to get the current phase kind, suppressing the synthetic
 201   // PhaseKind::MUTATOR phase.
 202
 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;
 207   }
 208
 209   return phases[phase].phaseKind;
 210 }
 211
 212 static Phase LookupPhaseWithParent(PhaseKind phaseKind, Phase parentPhase) {
 213   for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
 214     if (phases[phase].parent == parentPhase) {
 215       return phase;
 216     }
 217   }
 218
 219   return Phase::NONE;
 220 }
 221
 222 static const char* PhaseKindName(PhaseKind kind) {
 223   if (kind == PhaseKind::NONE) {
 224     return "NONE";
 225   }
 226
 227   return phaseKinds[kind].name;
 228 }
 229
 230 Phase Statistics::lookupChildPhase(PhaseKind phaseKind) const {
 231   if (phaseKind == PhaseKind::IMPLICIT_SUSPENSION) {
 232     return Phase::IMPLICIT_SUSPENSION;
 233   }
 234   if (phaseKind == PhaseKind::EXPLICIT_SUSPENSION) {
 235     return Phase::EXPLICIT_SUSPENSION;
 236   }
 237
 238   MOZ_ASSERT(phaseKind < PhaseKind::LIMIT);
 239
 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());
 243
 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()));
 248   }
 249
 250   return phase;
 251 }
 252
 253 inline auto AllPhases() {
 254   return mozilla::MakeEnumeratedRange(Phase::FIRST, Phase::LIMIT);
 255 }
 256
 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();
 263     }
 264   }
 265   if (*maxPause > maxPauseInInterval) {
 266     maxPauseInInterval = *maxPause;
 267   }
 268 }
 269
 270 void Statistics::sccDurations(TimeDuration* total,
 271                               TimeDuration* maxPause) const {
 272   *total = *maxPause = TimeDuration::Zero();
 273   for (const auto& duration : sccTimes) {
 274     *total += duration;
 275     *maxPause = std::max(*maxPause, duration);
 276   }
 277 }
 278
 279 using FragmentVector = Vector<UniqueChars, 8, SystemAllocPolicy>;
 280
 281 static UniqueChars Join(const FragmentVector& fragments,
 282                         const char* separator = "") {
 283   const size_t separatorLength = strlen(separator);
 284   size_t length = 0;
 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;
 289     }
 290   }
 291
 292   char* joined = js_pod_malloc<char>(length + 1);
 293   if (!joined) {
 294     return UniqueChars();
 295   }
 296
 297   joined[length] = '\0';
 298   char* cursor = joined;
 299   for (size_t i = 0; i < fragments.length(); ++i) {
 300     if (fragments[i]) {
 301       strcpy(cursor, fragments[i].get());
 302     }
 303     cursor += fragments[i] ? strlen(fragments[i].get()) : 0;
 304     if (i < (fragments.length() - 1)) {
 305       if (separatorLength) {
 306         strcpy(cursor, separator);
 307       }
 308       cursor += separatorLength;
 309     }
 310   }
 311
 312   return UniqueChars(joined);
 313 }
 314
 315 static TimeDuration SumChildTimes(Phase phase,
 316                                   const Statistics::PhaseTimes& phaseTimes) {
 317   TimeDuration total;
 318   for (phase = phases[phase].firstChild; phase != Phase::NONE;
 319        phase = phases[phase].nextSibling) {
 320     total += phaseTimes[phase];
 321   }
 322   return total;
 323 }
 324
 325 UniqueChars Statistics::formatCompactSliceMessage() const {
 326   // Skip if we OOM'ed.
 327   if (slices_.length() == 0) {
 328     return UniqueChars(nullptr);
 329   }
 330
 331   const size_t index = slices_.length() - 1;
 332   const SliceData& slice = slices_.back();
 333
 334   char budgetDescription[200];
 335   slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
 336
 337   const char* format =
 338       "GC Slice %u - Pause: %.3fms of %s budget (@ %.3fms); Reason: %s; Reset: "
 339       "%s%s; Times: ";
 340   char buffer[1024];
 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) : "");
 346
 347   FragmentVector fragments;
 348   if (!fragments.append(DuplicateString(buffer)) ||
 349       !fragments.append(
 350           formatCompactSlicePhaseTimes(slices_[index].phaseTimes))) {
 351     return UniqueChars(nullptr);
 352   }
 353   return Join(fragments);
 354 }
 355
 356 UniqueChars Statistics::formatCompactSummaryMessage() const {
 357   FragmentVector fragments;
 358   if (!fragments.append(DuplicateString("Summary - "))) {
 359     return UniqueChars(nullptr);
 360   }
 361
 362   TimeDuration total, longest;
 363   gcDuration(&total, &longest);
 364
 365   const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
 366   const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
 367
 368   char buffer[1024];
 369   if (!nonincremental()) {
 370     SprintfLiteral(buffer,
 371                    "Max Pause: %.3fms; MMU 20ms: %.1f%%; MMU 50ms: %.1f%%; "
 372                    "Total: %.3fms; ",
 373                    t(longest), mmu20 * 100., mmu50 * 100., t(total));
 374   } else {
 375     SprintfLiteral(buffer, "Non-Incremental: %.3fms (%s); ", t(total),
 376                    ExplainAbortReason(nonincrementalReason_));
 377   }
 378   if (!fragments.append(DuplicateString(buffer))) {
 379     return UniqueChars(nullptr);
 380   }
 381
 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);
 394   }
 395
 396   MOZ_ASSERT_IF(counts[COUNT_ARENA_RELOCATED],
 397                 gcOptions == JS::GCOptions::Shrink);
 398   if (gcOptions == JS::GCOptions::Shrink) {
 399     SprintfLiteral(
 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);
 404     }
 405   }
 406
 407   return Join(fragments);
 408 }
 409
 410 UniqueChars Statistics::formatCompactSlicePhaseTimes(
 411     const PhaseTimes& phaseTimes) const {
 412   static const TimeDuration MaxUnaccountedTime =
 413       TimeDuration::FromMicroseconds(100);
 414
 415   FragmentVector fragments;
 416   char buffer[128];
 417   for (auto phase : AllPhases()) {
 418     DebugOnly<uint8_t> level = phases[phase].depth;
 419     MOZ_ASSERT(level < 4);
 420
 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);
 427       }
 428
 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);
 434         }
 435       }
 436     }
 437   }
 438   return Join(fragments, ", ");
 439 }
 440
 441 UniqueChars Statistics::formatDetailedMessage() const {
 442   FragmentVector fragments;
 443
 444   if (!fragments.append(formatDetailedDescription())) {
 445     return UniqueChars(nullptr);
 446   }
 447
 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);
 452       }
 453       if (!fragments.append(formatDetailedPhaseTimes(slices_[i].phaseTimes))) {
 454         return UniqueChars(nullptr);
 455       }
 456     }
 457   }
 458   if (!fragments.append(formatDetailedTotals())) {
 459     return UniqueChars(nullptr);
 460   }
 461   if (!fragments.append(formatDetailedPhaseTimes(phaseTimes))) {
 462     return UniqueChars(nullptr);
 463   }
 464
 465   return Join(fragments);
 466 }
 467
 468 UniqueChars Statistics::formatDetailedDescription() const {
 469   TimeDuration sccTotal, sccLongest;
 470   sccDurations(&sccTotal, &sccLongest);
 471
 472   const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
 473   const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
 474
 475   const char* format =
 476       "=================================================================\n\
 477   Invocation Kind: %s\n\
 478   Reason: %s\n\
 479   Incremental: %s%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\
 489 ";
 490
 491   char buffer[1024];
 492   SprintfLiteral(
 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);
 505
 506   return DuplicateString(buffer);
 507 }
 508
 509 UniqueChars Statistics::formatDetailedSliceDescription(
 510     unsigned i, const SliceData& slice) const {
 511   char budgetDescription[200];
 512   slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
 513
 514   const char* format =
 515       "\
 516   ---- Slice %u ----\n\
 517     Reason: %s\n\
 518     Trigger: %s\n\
 519     Reset: %s%s\n\
 520     State: %s -> %s\n\
 521     Page Faults: %" PRIu64
 522       "\n\
 523     Pause: %.3fms of %s budget (@ %.3fms)\n\
 524 ";
 525
 526   char triggerBuffer[100] = "n/a";
 527   if (slice.trigger) {
 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);
 532   }
 533
 534   char buffer[1024];
 535   SprintfLiteral(
 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);
 543 }
 544
 545 static bool IncludePhase(TimeDuration duration) {
 546   // Don't include durations that will print as "0.000ms".
 547   return duration.ToMilliseconds() >= 0.001;
 548 }
 549
 550 UniqueChars Statistics::formatDetailedPhaseTimes(
 551     const PhaseTimes& phaseTimes) const {
 552   static const TimeDuration MaxUnaccountedChildTime =
 553       TimeDuration::FromMicroseconds(50);
 554
 555   FragmentVector fragments;
 556   char buffer[128];
 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);
 566       }
 567
 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);
 573         }
 574       }
 575     }
 576   }
 577   return Join(fragments);
 578 }
 579
 580 UniqueChars Statistics::formatDetailedTotals() const {
 581   TimeDuration total, longest;
 582   gcDuration(&total, &longest);
 583
 584   const char* format =
 585       "\
 586   ---- Totals ----\n\
 587     Total Time: %.3fms\n\
 588     Max Pause: %.3fms\n\
 589 ";
 590   char buffer[1024];
 591   SprintfLiteral(buffer, format, t(total), t(longest));
 592   return DuplicateString(buffer);
 593 }
 594
 595 void Statistics::formatJsonSlice(size_t sliceNum, JSONPrinter& json) const {
 596   /*
 597    * We number each of the slice properties to keep the code in
 598    * GCTelemetry.jsm in sync.  See MAX_SLICE_KEYS.
 599    */
 600   json.beginObject();
 601   formatJsonSliceDescription(sliceNum, slices_[sliceNum], json);  // # 1-11
 602
 603   json.beginObjectProperty("times");  // # 12
 604   formatJsonPhaseTimes(slices_[sliceNum].phaseTimes, json);
 605   json.endObject();
 606
 607   json.endObject();
 608 }
 609
 610 UniqueChars Statistics::renderJsonSlice(size_t sliceNum) const {
 611   Sprinter printer(nullptr, false);
 612   if (!printer.init()) {
 613     return UniqueChars(nullptr);
 614   }
 615   JSONPrinter json(printer, false);
 616
 617   formatJsonSlice(sliceNum, json);
 618   return printer.release();
 619 }
 620
 621 UniqueChars Statistics::renderNurseryJson() const {
 622   Sprinter printer(nullptr, false);
 623   if (!printer.init()) {
 624     return UniqueChars(nullptr);
 625   }
 626   JSONPrinter json(printer, false);
 627   gc->nursery().renderProfileJSON(json);
 628   return printer.release();
 629 }
 630
 631 #ifdef DEBUG
 632 void Statistics::log(const char* fmt, ...) {
 633   va_list args;
 634   va_start(args, fmt);
 635   if (gcDebugFile) {
 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");
 641     fflush(gcDebugFile);
 642   }
 643   va_end(args);
 644 }
 645 #endif
 646
 647 UniqueChars Statistics::renderJsonMessage() const {
 648   /*
 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
 652    *
 653    * All the properties listed here are created within the timings property
 654    * of the GCMajor marker.
 655    */
 656   if (aborted) {
 657     return DuplicateString("{status:\"aborted\"}");  // May return nullptr
 658   }
 659
 660   Sprinter printer(nullptr, false);
 661   if (!printer.init()) {
 662     return UniqueChars(nullptr);
 663   }
 664   JSONPrinter json(printer, false);
 665
 666   json.beginObject();
 667   json.property("status", "completed");
 668   formatJsonDescription(json);
 669
 670   json.beginObjectProperty("totals");
 671   formatJsonPhaseTimes(phaseTimes, json);
 672   json.endObject();
 673
 674   json.endObject();
 675
 676   return printer.release();
 677 }
 678
 679 void Statistics::formatJsonDescription(JSONPrinter& json) const {
 680   // If you change JSON properties here, please update:
 681   // Firefox Profiler:
 682   //   https://github.com/firefox-devtools/profiler
 683
 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);
 700   }
 701   json.property("slices", slices_.length());
 702
 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));
 707
 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);
 712
 713   if (nonincrementalReason_ != GCAbortReason::None) {
 714     json.property("nonincremental_reason",
 715                   ExplainAbortReason(nonincrementalReason_));
 716   }
 717   json.property("allocated_bytes", preTotalHeapBytes);
 718   json.property("post_heap_size", postTotalHeapBytes);
 719
 720   uint32_t addedChunks = getCount(COUNT_NEW_CHUNK);
 721   if (addedChunks) {
 722     json.property("added_chunks", addedChunks);
 723   }
 724   uint32_t removedChunks = getCount(COUNT_DESTROY_CHUNK);
 725   if (removedChunks) {
 726     json.property("removed_chunks", removedChunks);
 727   }
 728   json.property("major_gc_number", startingMajorGCNumber);
 729   json.property("minor_gc_number", startingMinorGCNumber);
 730   json.property("slice_number", startingSliceNumber);
 731 }
 732
 733 void Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice,
 734                                             JSONPrinter& json) const {
 735   // If you change JSON properties here, please update:
 736   // Firefox Profiler:
 737   //   https://github.com/firefox-devtools/profiler
 738   //
 739   char budgetDescription[200];
 740   slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
 741   TimeStamp originTime = TimeStamp::ProcessCreation();
 742
 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);
 750   if (slice.trigger) {
 751     Trigger trigger = slice.trigger.value();
 752     json.property("trigger_amount", trigger.amount);
 753     json.property("trigger_threshold", trigger.threshold);
 754   }
 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);
 759   }
 760   json.property("start_timestamp", TimeBetween(originTime, slice.start),
 761                 JSONPrinter::SECONDS);
 762 }
 763
 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);
 770     }
 771   }
 772 }
 773
 774 Statistics::Statistics(GCRuntime* gc)
 775     : gc(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),
 788       nurseryCollectionCallback(nullptr),
 789       aborted(false),
 790       enableProfiling_(false),
 791       sliceCount_(0) {
 792   for (auto& count : counts) {
 793     count = 0;
 794   }
 795
 796   for (auto& stat : stats) {
 797     stat = 0;
 798   }
 799
 800 #ifdef DEBUG
 801   for (const auto& duration : totalTimes_) {
 802     using ElementType = std::remove_reference_t<decltype(duration)>;
 803     static_assert(!std::is_trivially_constructible_v<ElementType>,
 804                   "Statistics::Statistics will only initialize "
 805                   "totalTimes_'s elements if their default constructor is "
 806                   "non-trivial");
 807     MOZ_ASSERT(duration.IsZero(),
 808                "totalTimes_ default-initialization should have "
 809                "default-initialized every element of totalTimes_ to zero");
 810   }
 811 #endif
 812
 813   MOZ_ALWAYS_TRUE(phaseStack.reserve(MAX_PHASE_NESTING));
 814   MOZ_ALWAYS_TRUE(suspendedPhases.reserve(MAX_SUSPENDED_PHASES));
 815
 816   gcTimerFile = MaybeOpenFileFromEnv("MOZ_GCTIMER");
 817   gcDebugFile = MaybeOpenFileFromEnv("JS_GC_DEBUG");
 818   gcProfileFile = MaybeOpenFileFromEnv("JS_GC_PROFILE_FILE", stderr);
 819
 820   gc::ReadProfileEnv("JS_GC_PROFILE",
 821                      "Report major GCs taking more than N milliseconds for "
 822                      "all or just the main runtime\n",
 823                      &enableProfiling_, &profileWorkers_, &profileThreshold_);
 824 }
 825
 826 Statistics::~Statistics() {
 827   if (gcTimerFile && gcTimerFile != stdout && gcTimerFile != stderr) {
 828     fclose(gcTimerFile);
 829   }
 830   if (gcDebugFile && gcDebugFile != stdout && gcDebugFile != stderr) {
 831     fclose(gcDebugFile);
 832   }
 833 }
 834
 835 /* static */
 836 bool Statistics::initialize() {
 837 #ifdef DEBUG
 838   // Sanity check generated tables.
 839   for (auto i : AllPhases()) {
 840     auto parent = phases[i].parent;
 841     if (parent != Phase::NONE) {
 842       MOZ_ASSERT(phases[i].depth == phases[parent].depth + 1);
 843     }
 844     auto firstChild = phases[i].firstChild;
 845     if (firstChild != Phase::NONE) {
 846       MOZ_ASSERT(i == phases[firstChild].parent);
 847       MOZ_ASSERT(phases[i].depth == phases[firstChild].depth - 1);
 848     }
 849     auto nextSibling = phases[i].nextSibling;
 850     if (nextSibling != Phase::NONE) {
 851       MOZ_ASSERT(parent == phases[nextSibling].parent);
 852       MOZ_ASSERT(phases[i].depth == phases[nextSibling].depth);
 853     }
 854     auto nextWithPhaseKind = phases[i].nextWithPhaseKind;
 855     if (nextWithPhaseKind != Phase::NONE) {
 856       MOZ_ASSERT(phases[i].phaseKind == phases[nextWithPhaseKind].phaseKind);
 857       MOZ_ASSERT(parent != phases[nextWithPhaseKind].parent);
 858     }
 859   }
 860   for (auto i : AllPhaseKinds()) {
 861     MOZ_ASSERT(phases[phaseKinds[i].firstPhase].phaseKind == i);
 862     for (auto j : AllPhaseKinds()) {
 863       MOZ_ASSERT_IF(i != j, phaseKinds[i].telemetryBucket !=
 864                                 phaseKinds[j].telemetryBucket);
 865     }
 866   }
 867 #endif
 868
 869   return true;
 870 }
 871
 872 JS::GCSliceCallback Statistics::setSliceCallback(
 873     JS::GCSliceCallback newCallback) {
 874   JS::GCSliceCallback oldCallback = sliceCallback;
 875   sliceCallback = newCallback;
 876   return oldCallback;
 877 }
 878
 879 JS::GCNurseryCollectionCallback Statistics::setNurseryCollectionCallback(
 880     JS::GCNurseryCollectionCallback newCallback) {
 881   auto oldCallback = nurseryCollectionCallback;
 882   nurseryCollectionCallback = newCallback;
 883   return oldCallback;
 884 }
 885
 886 TimeDuration Statistics::clearMaxGCPauseAccumulator() {
 887   TimeDuration prior = maxPauseInInterval;
 888   maxPauseInInterval = TimeDuration::Zero();
 889   return prior;
 890 }
 891
 892 TimeDuration Statistics::getMaxGCPauseSinceClear() {
 893   return maxPauseInInterval;
 894 }
 895
 896 // Sum up the time for a phase, including instances of the phase with different
 897 // parents.
 898 static TimeDuration SumPhase(PhaseKind phaseKind,
 899                              const Statistics::PhaseTimes& times) {
 900   TimeDuration sum;
 901   for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
 902     sum += times[phase];
 903   }
 904   return sum;
 905 }
 906
 907 static bool CheckSelfTime(Phase parent, Phase child,
 908                           const Statistics::PhaseTimes& times,
 909                           const Statistics::PhaseTimes& selfTimes,
 910                           TimeDuration childTime) {
 911   if (selfTimes[parent] < childTime) {
 912     fprintf(
 913         stderr,
 914         "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
 915         phases[parent].name, times[parent].ToMilliseconds(),
 916         selfTimes[parent].ToMilliseconds(), phases[child].name,
 917         childTime.ToMilliseconds());
 918     fflush(stderr);
 919     return false;
 920   }
 921
 922   return true;
 923 }
 924
 925 static PhaseKind FindLongestPhaseKind(const Statistics::PhaseKindTimes& times) {
 926   TimeDuration longestTime;
 927   PhaseKind phaseKind = PhaseKind::NONE;
 928   for (auto i : MajorGCPhaseKinds()) {
 929     if (times[i] > longestTime) {
 930       longestTime = times[i];
 931       phaseKind = i;
 932     }
 933   }
 934
 935   return phaseKind;
 936 }
 937
 938 static PhaseKind LongestPhaseSelfTimeInMajorGC(
 939     const Statistics::PhaseTimes& times) {
 940   // Start with total times per expanded phase, including children's times.
 941   Statistics::PhaseTimes selfTimes(times);
 942
 943   // We have the total time spent in each phase, including descendant times.
 944   // Loop over the children and subtract their times from their parent's self
 945   // time.
 946   for (auto i : AllPhases()) {
 947     Phase parent = phases[i].parent;
 948     if (parent != Phase::NONE) {
 949       bool ok = CheckSelfTime(parent, i, times, selfTimes, times[i]);
 950
 951       // This happens very occasionally in release builds and frequently
 952       // in Windows debug builds. Skip collecting longest phase telemetry
 953       // if it does.
 954 #ifndef XP_WIN
 955       MOZ_ASSERT(ok, "Inconsistent time data; see bug 1400153");
 956 #endif
 957       if (!ok) {
 958         return PhaseKind::NONE;
 959       }
 960
 961       selfTimes[parent] -= times[i];
 962     }
 963   }
 964
 965   // Sum expanded phases corresponding to the same phase.
 966   Statistics::PhaseKindTimes phaseKindTimes;
 967   for (auto i : AllPhaseKinds()) {
 968     phaseKindTimes[i] = SumPhase(i, selfTimes);
 969   }
 970
 971   return FindLongestPhaseKind(phaseKindTimes);
 972 }
 973
 974 void Statistics::printStats() {
 975   if (aborted) {
 976     fprintf(gcTimerFile,
 977             "OOM during GC statistics collection. The report is unavailable "
 978             "for this GC.\n");
 979   } else {
 980     UniqueChars msg = formatDetailedMessage();
 981     if (msg) {
 982       double secSinceStart =
 983           TimeBetween(TimeStamp::ProcessCreation(), slices_[0].start)
 984               .ToSeconds();
 985       fprintf(gcTimerFile, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
 986     }
 987   }
 988   fflush(gcTimerFile);
 989 }
 990
 991 void Statistics::beginGC(JS::GCOptions options, const TimeStamp& currentTime) {
 992   slices_.clearAndFree();
 993   sccTimes.clearAndFree();
 994   gcOptions = options;
 995   nonincrementalReason_ = GCAbortReason::None;
 996
 997   preTotalHeapBytes = gc->heapSize.bytes();
 998
 999   preCollectedHeapBytes = 0;
1000
1001   startingMajorGCNumber = gc->majorGCCount();
1002   startingSliceNumber = gc->gcNumber();
1003
1004   if (gc->lastGCEndTime()) {
1005     timeSinceLastGC = TimeBetween(gc->lastGCEndTime(), currentTime);
1006   }
1007
1008   totalGCTime_ = TimeDuration::Zero();
1009 }
1010
1011 void Statistics::measureInitialHeapSize() {
1012   MOZ_ASSERT(preCollectedHeapBytes == 0);
1013   for (GCZonesIter zone(gc); !zone.done(); zone.next()) {
1014     preCollectedHeapBytes += zone->gcHeapSize.bytes();
1015   }
1016 }
1017
1018 void Statistics::endGC() {
1019   postTotalHeapBytes = gc->heapSize.bytes();
1020
1021   sendGCTelemetry();
1022 }
1023
1024 TimeDuration Statistics::sumTotalParallelTime(PhaseKind phaseKind) const {
1025   TimeDuration total;
1026   for (const SliceData& slice : slices_) {
1027     total += slice.totalParallelTimes[phaseKind];
1028   }
1029   return total;
1030 }
1031
1032 void Statistics::sendGCTelemetry() {
1033   JSRuntime* runtime = gc->rt;
1034   // NOTE: "Compartmental" is term that was deprecated with the
1035   // introduction of zone-based GC, but the old telemetry probe
1036   // continues to be used.
1037   runtime->metrics().GC_IS_COMPARTMENTAL(!gc->fullGCRequested);
1038   runtime->metrics().GC_ZONE_COUNT(zoneStats.zoneCount);
1039   runtime->metrics().GC_ZONES_COLLECTED(zoneStats.collectedZoneCount);
1040
1041   TimeDuration prepareTotal = phaseTimes[Phase::PREPARE];
1042   TimeDuration markTotal = SumPhase(PhaseKind::MARK, phaseTimes);
1043   TimeDuration markRootsTotal = SumPhase(PhaseKind::MARK_ROOTS, phaseTimes);
1044
1045   // Gray and weak marking time is counted under MARK_WEAK and not MARK_GRAY.
1046   TimeDuration markWeakTotal = SumPhase(PhaseKind::MARK_WEAK, phaseTimes);
1047   TimeDuration markGrayNotWeak =
1048       SumPhase(PhaseKind::MARK_GRAY, phaseTimes) +
1049       SumPhase(PhaseKind::MARK_INCOMING_GRAY, phaseTimes);
1050   TimeDuration markGrayWeak = SumPhase(PhaseKind::MARK_GRAY_WEAK, phaseTimes);
1051   TimeDuration markGrayTotal = markGrayNotWeak + markGrayWeak;
1052   TimeDuration markNotGrayOrWeak = markTotal - markGrayNotWeak - markWeakTotal;
1053   if (markNotGrayOrWeak < TimeDuration::FromMilliseconds(0)) {
1054     markNotGrayOrWeak = TimeDuration::Zero();
1055   }
1056
1057   size_t markCount = getCount(COUNT_CELLS_MARKED);
1058
1059   runtime->metrics().GC_PREPARE_MS(prepareTotal);
1060   runtime->metrics().GC_MARK_MS(markNotGrayOrWeak);
1061   if (markTotal >= TimeDuration::FromMicroseconds(1)) {
1062     double markRate = double(markCount) / t(markTotal);
1063     runtime->metrics().GC_MARK_RATE_2(uint32_t(markRate));
1064   }
1065   runtime->metrics().GC_SWEEP_MS(phaseTimes[Phase::SWEEP]);
1066   if (gc->didCompactZones()) {
1067     runtime->metrics().GC_COMPACT_MS(phaseTimes[Phase::COMPACT]);
1068   }
1069   runtime->metrics().GC_MARK_ROOTS_US(markRootsTotal);
1070   runtime->metrics().GC_MARK_GRAY_MS_2(markGrayTotal);
1071   runtime->metrics().GC_MARK_WEAK_MS(markWeakTotal);
1072   runtime->metrics().GC_NON_INCREMENTAL(nonincremental());
1073   if (nonincremental()) {
1074     runtime->metrics().GC_NON_INCREMENTAL_REASON(
1075         uint32_t(nonincrementalReason_));
1076   }
1077
1078 #ifdef DEBUG
1079   // Reset happens non-incrementally, so only the last slice can be reset.
1080   for (size_t i = 0; i < slices_.length() - 1; i++) {
1081     MOZ_ASSERT(!slices_[i].wasReset());
1082   }
1083 #endif
1084   const auto& lastSlice = slices_.back();
1085   runtime->metrics().GC_RESET(lastSlice.wasReset());
1086   if (lastSlice.wasReset()) {
1087     runtime->metrics().GC_RESET_REASON(uint32_t(lastSlice.resetReason));
1088   }
1089
1090   TimeDuration total, longest;
1091   gcDuration(&total, &longest);
1092
1093   runtime->metrics().GC_MS(total);
1094   runtime->metrics().GC_MAX_PAUSE_MS_2(longest);
1095
1096   const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
1097   runtime->metrics().GC_MMU_50(mmu50 * 100.0);
1098
1099   // Record scheduling telemetry for the main runtime but not for workers, which
1100   // are scheduled differently.
1101   if (!runtime->parentRuntime && timeSinceLastGC) {
1102     runtime->metrics().GC_TIME_BETWEEN_S(timeSinceLastGC);
1103     if (!nonincremental()) {
1104       runtime->metrics().GC_SLICE_COUNT(slices_.length());
1105     }
1106   }
1107
1108   if (!lastSlice.wasReset() && preCollectedHeapBytes != 0) {
1109     size_t bytesSurvived = 0;
1110     for (ZonesIter zone(runtime, WithAtoms); !zone.done(); zone.next()) {
1111       if (zone->wasCollected()) {
1112         bytesSurvived += zone->gcHeapSize.retainedBytes();
1113       }
1114     }
1115
1116     MOZ_ASSERT(preCollectedHeapBytes >= bytesSurvived);
1117     double survivalRate =
1118         100.0 * double(bytesSurvived) / double(preCollectedHeapBytes);
1119     runtime->metrics().GC_TENURED_SURVIVAL_RATE(survivalRate);
1120
1121     // Calculate 'effectiveness' in MB / second, on main thread only for now.
1122     if (!runtime->parentRuntime) {
1123       size_t bytesFreed = preCollectedHeapBytes - bytesSurvived;
1124       TimeDuration clampedTotal =
1125           TimeDuration::Max(total, TimeDuration::FromMilliseconds(1));
1126       double effectiveness =
1127           (double(bytesFreed) / BYTES_PER_MB) / clampedTotal.ToSeconds();
1128       runtime->metrics().GC_EFFECTIVENESS(uint32_t(effectiveness));
1129     }
1130   }
1131
1132   // Parallel marking stats.
1133   if (gc->isParallelMarkingEnabled()) {
1134     TimeDuration wallTime = SumPhase(PhaseKind::PARALLEL_MARK, phaseTimes);
1135     TimeDuration parallelRunTime =
1136         sumTotalParallelTime(PhaseKind::PARALLEL_MARK) -
1137         sumTotalParallelTime(PhaseKind::PARALLEL_MARK_WAIT);
1138     TimeDuration parallelMarkTime =
1139         sumTotalParallelTime(PhaseKind::PARALLEL_MARK_MARK);
1140     if (wallTime && parallelMarkTime) {
1141       uint32_t threadCount = gc->markers.length();
1142       double speedup = parallelMarkTime / wallTime;
1143       double utilization = parallelRunTime / (wallTime * threadCount);
1144       MOZ_ASSERT(utilization <= 1.0);
1145       runtime->metrics().GC_PARALLEL_MARK_SPEEDUP(uint32_t(speedup * 100.0));
1146       runtime->metrics().GC_PARALLEL_MARK_UTILIZATION(
1147           std::clamp(utilization * 100.0, 0.0, 100.0));
1148       runtime->metrics().GC_PARALLEL_MARK_INTERRUPTIONS(
1149           getCount(COUNT_PARALLEL_MARK_INTERRUPTIONS));
1150     }
1151   }
1152 }
1153
1154 void Statistics::beginNurseryCollection(JS::GCReason reason) {
1155   count(COUNT_MINOR_GC);
1156   startingMinorGCNumber = gc->minorGCCount();
1157   if (nurseryCollectionCallback) {
1158     (*nurseryCollectionCallback)(
1159         context(), JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START, reason);
1160   }
1161 }
1162
1163 void Statistics::endNurseryCollection(JS::GCReason reason) {
1164   if (nurseryCollectionCallback) {
1165     (*nurseryCollectionCallback)(
1166         context(), JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END, reason);
1167   }
1168
1169   tenuredAllocsSinceMinorGC = 0;
1170 }
1171
1172 Statistics::SliceData::SliceData(const SliceBudget& budget,
1173                                  Maybe<Trigger> trigger, JS::GCReason reason,
1174                                  TimeStamp start, size_t startFaults,
1175                                  gc::State initialState)
1176     : budget(budget),
1177       reason(reason),
1178       trigger(trigger),
1179       initialState(initialState),
1180       start(start),
1181       startFaults(startFaults) {}
1182
1183 TimeDuration Statistics::SliceData::duration() const {
1184   return TimeBetween(start, end);
1185 }
1186
1187 void Statistics::beginSlice(const ZoneGCStats& zoneStats, JS::GCOptions options,
1188                             const SliceBudget& budget, JS::GCReason reason,
1189                             bool budgetWasIncreased) {
1190   MOZ_ASSERT(phaseStack.empty() ||
1191              (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
1192
1193   this->zoneStats = zoneStats;
1194
1195   TimeStamp currentTime = TimeStamp::Now();
1196
1197   bool first = !gc->isIncrementalGCInProgress();
1198   if (first) {
1199     beginGC(options, currentTime);
1200   }
1201
1202   JSRuntime* runtime = gc->rt;
1203   if (!runtime->parentRuntime && !slices_.empty()) {
1204     TimeDuration timeSinceLastSlice =
1205         TimeBetween(slices_.back().end, currentTime);
1206     runtime->metrics().GC_TIME_BETWEEN_SLICES_MS(timeSinceLastSlice);
1207   }
1208
1209   Maybe<Trigger> trigger = recordedTrigger;
1210   recordedTrigger.reset();
1211
1212   if (!slices_.emplaceBack(budget, trigger, reason, currentTime,
1213                            GetPageFaultCount(), gc->state())) {
1214     // If we are OOM, set a flag to indicate we have missing slice data.
1215     aborted = true;
1216     return;
1217   }
1218
1219   runtime->metrics().GC_REASON_2(uint32_t(reason));
1220   runtime->metrics().GC_BUDGET_WAS_INCREASED(budgetWasIncreased);
1221
1222   // Slice callbacks should only fire for the outermost level.
1223   if (sliceCallback) {
1224     JSContext* cx = context();
1225     JS::GCDescription desc(!gc->fullGCRequested, false, options, reason);
1226     if (first) {
1227       (*sliceCallback)(cx, JS::GC_CYCLE_BEGIN, desc);
1228     }
1229     (*sliceCallback)(cx, JS::GC_SLICE_BEGIN, desc);
1230   }
1231
1232   log("begin slice");
1233 }
1234
1235 void Statistics::endSlice() {
1236   MOZ_ASSERT(phaseStack.empty() ||
1237              (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
1238
1239   if (!aborted) {
1240     auto& slice = slices_.back();
1241     slice.end = TimeStamp::Now();
1242     slice.endFaults = GetPageFaultCount();
1243     slice.finalState = gc->state();
1244
1245     log("end slice");
1246
1247     sendSliceTelemetry(slice);
1248
1249     sliceCount_++;
1250
1251     totalGCTime_ += slice.duration();
1252   }
1253
1254   bool last = !gc->isIncrementalGCInProgress();
1255   if (last) {
1256     if (gcTimerFile) {
1257       printStats();
1258     }
1259
1260     if (!aborted) {
1261       endGC();
1262     }
1263   }
1264
1265   if (!aborted &&
1266       ShouldPrintProfile(gc->rt, enableProfiling_, profileWorkers_,
1267                          profileThreshold_, slices_.back().duration())) {
1268     printSliceProfile();
1269   }
1270
1271   // Slice callbacks should only fire for the outermost level.
1272   if (!aborted) {
1273     if (sliceCallback) {
1274       JSContext* cx = context();
1275       JS::GCDescription desc(!gc->fullGCRequested, last, gcOptions,
1276                              slices_.back().reason);
1277       (*sliceCallback)(cx, JS::GC_SLICE_END, desc);
1278       if (last) {
1279         (*sliceCallback)(cx, JS::GC_CYCLE_END, desc);
1280       }
1281     }
1282   }
1283
1284   // Do this after the slice callback since it uses these values.
1285   if (last) {
1286     for (auto& count : counts) {
1287       count = 0;
1288     }
1289
1290     // Clear the timers at the end of a GC, preserving the data for
1291     // PhaseKind::MUTATOR.
1292     auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
1293     auto mutatorTime = phaseTimes[Phase::MUTATOR];
1294
1295     phaseStartTimes = PhaseTimeStamps();
1296 #ifdef DEBUG
1297     phaseEndTimes = PhaseTimeStamps();
1298 #endif
1299     phaseTimes = PhaseTimes();
1300
1301     phaseStartTimes[Phase::MUTATOR] = mutatorStartTime;
1302     phaseTimes[Phase::MUTATOR] = mutatorTime;
1303   }
1304
1305   aborted = false;
1306 }
1307
1308 void Statistics::sendSliceTelemetry(const SliceData& slice) {
1309   JSRuntime* runtime = gc->rt;
1310   TimeDuration sliceTime = slice.duration();
1311   runtime->metrics().GC_SLICE_MS(sliceTime);
1312
1313   if (slice.budget.isTimeBudget()) {
1314     TimeDuration budgetDuration = slice.budget.timeBudgetDuration();
1315     runtime->metrics().GC_BUDGET_MS_2(budgetDuration);
1316
1317     if (IsCurrentlyAnimating(runtime->lastAnimationTime, slice.end)) {
1318       runtime->metrics().GC_ANIMATION_MS(sliceTime);
1319     }
1320
1321     bool wasLongSlice = false;
1322     if (sliceTime > budgetDuration) {
1323       // Record how long we went over budget.
1324       TimeDuration overrun = sliceTime - budgetDuration;
1325       runtime->metrics().GC_BUDGET_OVERRUN(overrun);
1326
1327       // Long GC slices are those that go 50% or 5ms over their budget.
1328       wasLongSlice = (overrun > TimeDuration::FromMilliseconds(5)) ||
1329                      (overrun > (budgetDuration / int64_t(2)));
1330
1331       // Record the longest phase in any long slice.
1332       if (wasLongSlice) {
1333         PhaseKind longest = LongestPhaseSelfTimeInMajorGC(slice.phaseTimes);
1334         reportLongestPhaseInMajorGC(longest, [runtime](auto sample) {
1335           runtime->metrics().GC_SLOW_PHASE(sample);
1336         });
1337
1338         // If the longest phase was waiting for parallel tasks then record the
1339         // longest task.
1340         if (longest == PhaseKind::JOIN_PARALLEL_TASKS) {
1341           PhaseKind longestParallel =
1342               FindLongestPhaseKind(slice.maxParallelTimes);
1343           reportLongestPhaseInMajorGC(longestParallel, [runtime](auto sample) {
1344             runtime->metrics().GC_SLOW_TASK(sample);
1345           });
1346         }
1347       }
1348     }
1349
1350     // Record `wasLongSlice` for all TimeBudget slices.
1351     runtime->metrics().GC_SLICE_WAS_LONG(wasLongSlice);
1352   }
1353 }
1354
1355 template <typename Fn>
1356 void Statistics::reportLongestPhaseInMajorGC(PhaseKind longest, Fn reportFn) {
1357   if (longest != PhaseKind::NONE) {
1358     uint8_t bucket = phaseKinds[longest].telemetryBucket;
1359     reportFn(bucket);
1360   }
1361 }
1362
1363 bool Statistics::startTimingMutator() {
1364   if (phaseStack.length() != 0) {
1365     // Should only be called from outside of GC.
1366     MOZ_ASSERT(phaseStack.length() == 1);
1367     MOZ_ASSERT(phaseStack[0] == Phase::MUTATOR);
1368     return false;
1369   }
1370
1371   MOZ_ASSERT(suspendedPhases.empty());
1372
1373   timedGCTime = TimeDuration::Zero();
1374   phaseStartTimes[Phase::MUTATOR] = TimeStamp();
1375   phaseTimes[Phase::MUTATOR] = TimeDuration::Zero();
1376   timedGCStart = TimeStamp();
1377
1378   beginPhase(PhaseKind::MUTATOR);
1379   return true;
1380 }
1381
1382 bool Statistics::stopTimingMutator(double& mutator_ms, double& gc_ms) {
1383   // This should only be called from outside of GC, while timing the mutator.
1384   if (phaseStack.length() != 1 || phaseStack[0] != Phase::MUTATOR) {
1385     return false;
1386   }
1387
1388   endPhase(PhaseKind::MUTATOR);
1389   mutator_ms = t(phaseTimes[Phase::MUTATOR]);
1390   gc_ms = t(timedGCTime);
1391
1392   return true;
1393 }
1394
1395 void Statistics::suspendPhases(PhaseKind suspension) {
1396   MOZ_ASSERT(suspension == PhaseKind::EXPLICIT_SUSPENSION ||
1397              suspension == PhaseKind::IMPLICIT_SUSPENSION);
1398   while (!phaseStack.empty()) {
1399     MOZ_ASSERT(suspendedPhases.length() < MAX_SUSPENDED_PHASES);
1400     Phase parent = phaseStack.back();
1401     suspendedPhases.infallibleAppend(parent);
1402     recordPhaseEnd(parent);
1403   }
1404   suspendedPhases.infallibleAppend(lookupChildPhase(suspension));
1405 }
1406
1407 void Statistics::resumePhases() {
1408   MOZ_ASSERT(suspendedPhases.back() == Phase::EXPLICIT_SUSPENSION ||
1409              suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION);
1410   suspendedPhases.popBack();
1411
1412   while (!suspendedPhases.empty() &&
1413          suspendedPhases.back() != Phase::EXPLICIT_SUSPENSION &&
1414          suspendedPhases.back() != Phase::IMPLICIT_SUSPENSION) {
1415     Phase resumePhase = suspendedPhases.popCopy();
1416     if (resumePhase == Phase::MUTATOR) {
1417       timedGCTime += TimeBetween(timedGCStart, TimeStamp::Now());
1418     }
1419     recordPhaseBegin(resumePhase);
1420   }
1421 }
1422
1423 void Statistics::beginPhase(PhaseKind phaseKind) {
1424   // No longer timing these phases. We should never see these.
1425   MOZ_ASSERT(phaseKind != PhaseKind::GC_BEGIN &&
1426              phaseKind != PhaseKind::GC_END);
1427
1428   // PhaseKind::MUTATOR is suspended while performing GC.
1429   if (currentPhase() == Phase::MUTATOR) {
1430     suspendPhases(PhaseKind::IMPLICIT_SUSPENSION);
1431   }
1432
1433   recordPhaseBegin(lookupChildPhase(phaseKind));
1434 }
1435
1436 void Statistics::recordPhaseBegin(Phase phase) {
1437   MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
1438
1439   // Guard against any other re-entry.
1440   MOZ_ASSERT(!phaseStartTimes[phase]);
1441
1442   MOZ_ASSERT(phaseStack.length() < MAX_PHASE_NESTING);
1443
1444   Phase current = currentPhase();
1445   MOZ_ASSERT(phases[phase].parent == current);
1446
1447   TimeStamp now = TimeStamp::Now();
1448
1449   if (current != Phase::NONE) {
1450     MOZ_ASSERT(now >= phaseStartTimes[currentPhase()],
1451                "Inconsistent time data; see bug 1400153");
1452     if (now < phaseStartTimes[currentPhase()]) {
1453       now = phaseStartTimes[currentPhase()];
1454       aborted = true;
1455     }
1456   }
1457
1458   phaseStack.infallibleAppend(phase);
1459   phaseStartTimes[phase] = now;
1460   log("begin: %s", phases[phase].path);
1461 }
1462
1463 void Statistics::recordPhaseEnd(Phase phase) {
1464   MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
1465
1466   MOZ_ASSERT(phaseStartTimes[phase]);
1467
1468   TimeStamp now = TimeStamp::Now();
1469
1470   // Make sure this phase ends after it starts.
1471   MOZ_ASSERT(now >= phaseStartTimes[phase],
1472              "Inconsistent time data; see bug 1400153");
1473
1474 #ifdef DEBUG
1475   // Make sure this phase ends after all of its children. Note that some
1476   // children might not have run in this instance, in which case they will
1477   // have run in a previous instance of this parent or not at all.
1478   for (Phase kid = phases[phase].firstChild; kid != Phase::NONE;
1479        kid = phases[kid].nextSibling) {
1480     if (phaseEndTimes[kid].IsNull()) {
1481       continue;
1482     }
1483     if (phaseEndTimes[kid] > now) {
1484       fprintf(stderr,
1485               "Parent %s ended at %.3fms, before child %s ended at %.3fms?\n",
1486               phases[phase].name,
1487               t(TimeBetween(TimeStamp::FirstTimeStamp(), now)),
1488               phases[kid].name,
1489               t(TimeBetween(TimeStamp::FirstTimeStamp(), phaseEndTimes[kid])));
1490     }
1491     MOZ_ASSERT(phaseEndTimes[kid] <= now,
1492                "Inconsistent time data; see bug 1400153");
1493   }
1494 #endif
1495
1496   if (now < phaseStartTimes[phase]) {
1497     now = phaseStartTimes[phase];
1498     aborted = true;
1499   }
1500
1501   if (phase == Phase::MUTATOR) {
1502     timedGCStart = now;
1503   }
1504
1505   phaseStack.popBack();
1506
1507   TimeDuration t = TimeBetween(phaseStartTimes[phase], now);
1508   if (!slices_.empty()) {
1509     slices_.back().phaseTimes[phase] += t;
1510   }
1511   phaseTimes[phase] += t;
1512   phaseStartTimes[phase] = TimeStamp();
1513
1514 #ifdef DEBUG
1515   phaseEndTimes[phase] = now;
1516   log("end: %s", phases[phase].path);
1517 #endif
1518 }
1519
1520 void Statistics::endPhase(PhaseKind phaseKind) {
1521   Phase phase = currentPhase();
1522   MOZ_ASSERT(phase != Phase::NONE);
1523   MOZ_ASSERT(phases[phase].phaseKind == phaseKind);
1524
1525   recordPhaseEnd(phase);
1526
1527   // When emptying the stack, we may need to return to timing the mutator
1528   // (PhaseKind::MUTATOR).
1529   if (phaseStack.empty() && !suspendedPhases.empty() &&
1530       suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION) {
1531     resumePhases();
1532   }
1533 }
1534
1535 void Statistics::recordParallelPhase(PhaseKind phaseKind,
1536                                      TimeDuration duration) {
1537   MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
1538
1539   if (aborted) {
1540     return;
1541   }
1542
1543   slices_.back().totalParallelTimes[phaseKind] += duration;
1544
1545   // Also record the maximum task time for each phase. Don't record times for
1546   // parent phases.
1547   TimeDuration& maxTime = slices_.back().maxParallelTimes[phaseKind];
1548   maxTime = std::max(maxTime, duration);
1549 }
1550
1551 TimeStamp Statistics::beginSCC() { return TimeStamp::Now(); }
1552
1553 void Statistics::endSCC(unsigned scc, TimeStamp start) {
1554   if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1)) {
1555     return;
1556   }
1557
1558   sccTimes[scc] += TimeBetween(start, TimeStamp::Now());
1559 }
1560
1561 /*
1562  * Calculate minimum mutator utilization for previous incremental GC.
1563  *
1564  * MMU (minimum mutator utilization) is a measure of how much garbage collection
1565  * is affecting the responsiveness of the system. MMU measurements are given
1566  * with respect to a certain window size. If we report MMU(50ms) = 80%, then
1567  * that means that, for any 50ms window of time, at least 80% of the window is
1568  * devoted to the mutator. In other words, the GC is running for at most 20% of
1569  * the window, or 10ms. The GC can run multiple slices during the 50ms window
1570  * as long as the total time it spends is at most 10ms.
1571  */
1572 double Statistics::computeMMU(TimeDuration window) const {
1573   MOZ_ASSERT(!slices_.empty());
1574
1575   TimeDuration gc = slices_[0].duration();
1576   TimeDuration gcMax = gc;
1577
1578   if (gc >= window) {
1579     return 0.0;
1580   }
1581
1582   int startIndex = 0;
1583   for (size_t endIndex = 1; endIndex < slices_.length(); endIndex++) {
1584     const auto* startSlice = &slices_[startIndex];
1585     const auto& endSlice = slices_[endIndex];
1586     gc += endSlice.duration();
1587
1588     while (TimeBetween(startSlice->end, endSlice.end) >= window) {
1589       gc -= startSlice->duration();
1590       startSlice = &slices_[++startIndex];
1591     }
1592
1593     TimeDuration cur = gc;
1594     TimeDuration sliceRange = TimeBetween(startSlice->start, endSlice.end);
1595     if (sliceRange > window) {
1596       cur -= (sliceRange - window);
1597     }
1598
1599     if (cur > gcMax) {
1600       gcMax = cur;
1601     }
1602   }
1603
1604   MOZ_ASSERT(gcMax > TimeDuration::Zero());
1605   MOZ_ASSERT(gcMax <= window);
1606   return (window - gcMax) / window;
1607 }
1608
1609 void Statistics::maybePrintProfileHeaders() {
1610   static int printedHeader = 0;
1611   if ((printedHeader++ % 200) == 0) {
1612     printProfileHeader();
1613     if (gc->nursery().enableProfiling()) {
1614       gc->nursery().printProfileHeader();
1615     }
1616   }
1617 }
1618
1619 // The following macros define GC profile metadata fields that are printed
1620 // before the timing information defined by FOR_EACH_GC_PROFILE_TIME.
1621
1622 #define FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
1623   _("PID", 7, "%7zu", pid)                     \
1624   _("Runtime", 14, "0x%12p", runtime)
1625
1626 #define FOR_EACH_GC_PROFILE_SLICE_METADATA(_)         \
1627   _("Timestamp", 10, "%10.6f", timestamp.ToSeconds()) \
1628   _("Reason", 20, "%-20.20s", reason)                 \
1629   _("States", 6, "%6s", formatGCStates(slice))        \
1630   _("FSNR", 4, "%4s", formatGCFlags(slice))           \
1631   _("SizeKB", 8, "%8zu", sizeKB)                      \
1632   _("Zs", 3, "%3zu", zoneCount)                       \
1633   _("Cs", 3, "%3zu", compartmentCount)                \
1634   _("Rs", 3, "%3zu", realmCount)                      \
1635   _("Budget", 6, "%6s", formatBudget(slice))
1636
1637 #define FOR_EACH_GC_PROFILE_METADATA(_)  \
1638   FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
1639   FOR_EACH_GC_PROFILE_SLICE_METADATA(_)
1640
1641 void Statistics::printProfileHeader() {
1642   if (!enableProfiling_) {
1643     return;
1644   }
1645
1646   Sprinter sprinter;
1647   if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
1648     return;
1649   }
1650
1651 #define PRINT_METADATA_NAME(name, width, _1, _2)  \
1652   if (!sprinter.jsprintf(" %-*s", width, name)) { \
1653     return;                                       \
1654   }
1655   FOR_EACH_GC_PROFILE_METADATA(PRINT_METADATA_NAME)
1656 #undef PRINT_METADATA_NAME
1657
1658 #define PRINT_PROFILE_NAME(_1, text, _2)     \
1659   if (!sprinter.jsprintf(" %-6.6s", text)) { \
1660     return;                                  \
1661   }
1662   FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_NAME)
1663 #undef PRINT_PROFILE_NAME
1664
1665   if (!sprinter.put("\n")) {
1666     return;
1667   }
1668
1669   fputs(sprinter.string(), profileFile());
1670 }
1671
1672 static TimeDuration SumAllPhaseKinds(const Statistics::PhaseKindTimes& times) {
1673   TimeDuration sum;
1674   for (PhaseKind kind : AllPhaseKinds()) {
1675     sum += times[kind];
1676   }
1677   return sum;
1678 }
1679
1680 void Statistics::printSliceProfile() {
1681   maybePrintProfileHeaders();
1682
1683   const SliceData& slice = slices_.back();
1684   ProfileDurations times = getProfileTimes(slice);
1685   updateTotalProfileTimes(times);
1686
1687   Sprinter sprinter;
1688   if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
1689     return;
1690   }
1691
1692   size_t pid = getpid();
1693   JSRuntime* runtime = gc->rt;
1694   TimeDuration timestamp = TimeBetween(creationTime(), slice.end);
1695   const char* reason = ExplainGCReason(slice.reason);
1696   size_t sizeKB = gc->heapSize.bytes() / 1024;
1697   size_t zoneCount = zoneStats.zoneCount;
1698   size_t compartmentCount = zoneStats.compartmentCount;
1699   size_t realmCount = zoneStats.realmCount;
1700
1701 #define PRINT_FIELD_VALUE(_1, _2, format, value) \
1702   if (!sprinter.jsprintf(" " format, value)) {   \
1703     return;                                      \
1704   }
1705   FOR_EACH_GC_PROFILE_METADATA(PRINT_FIELD_VALUE)
1706 #undef PRINT_FIELD_VALUE
1707
1708   if (!printProfileTimes(times, sprinter)) {
1709     return;
1710   }
1711
1712   fputs(sprinter.string(), profileFile());
1713 }
1714
1715 Statistics::ProfileDurations Statistics::getProfileTimes(
1716     const SliceData& slice) const {
1717   ProfileDurations times;
1718
1719   times[ProfileKey::Total] = slice.duration();
1720   times[ProfileKey::Background] = SumAllPhaseKinds(slice.totalParallelTimes);
1721
1722 #define GET_PROFILE_TIME(name, text, phase)                      \
1723   if (phase != PhaseKind::NONE) {                                \
1724     times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
1725   }
1726   FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
1727 #undef GET_PROFILE_TIME
1728
1729   return times;
1730 }
1731
1732 void Statistics::updateTotalProfileTimes(const ProfileDurations& times) {
1733 #define UPDATE_PROFILE_TIME(name, _, phase) \
1734   totalTimes_[ProfileKey::name] += times[ProfileKey::name];
1735   FOR_EACH_GC_PROFILE_TIME(UPDATE_PROFILE_TIME)
1736 #undef UPDATE_PROFILE_TIME
1737 }
1738
1739 const char* Statistics::formatGCStates(const SliceData& slice) {
1740   DebugOnly<int> r =
1741       SprintfLiteral(formatBuffer_, "%1d -> %1d", int(slice.initialState),
1742                      int(slice.finalState));
1743   MOZ_ASSERT(r > 0 && r < FormatBufferLength);
1744   return formatBuffer_;
1745 }
1746
1747 const char* Statistics::formatGCFlags(const SliceData& slice) {
1748   bool fullGC = gc->fullGCRequested;
1749   bool shrinkingGC = gcOptions == JS::GCOptions::Shrink;
1750   bool nonIncrementalGC = nonincrementalReason_ != GCAbortReason::None;
1751   bool wasReset = slice.resetReason != GCAbortReason::None;
1752
1753   MOZ_ASSERT(FormatBufferLength >= 5);
1754   formatBuffer_[0] = fullGC ? 'F' : ' ';
1755   formatBuffer_[1] = shrinkingGC ? 'S' : ' ';
1756   formatBuffer_[2] = nonIncrementalGC ? 'N' : ' ';
1757   formatBuffer_[3] = wasReset ? 'R' : ' ';
1758   formatBuffer_[4] = '\0';
1759
1760   return formatBuffer_;
1761 }
1762
1763 const char* Statistics::formatBudget(const SliceData& slice) {
1764   if (nonincrementalReason_ != GCAbortReason::None ||
1765       !slice.budget.isTimeBudget()) {
1766     formatBuffer_[0] = '\0';
1767     return formatBuffer_;
1768   }
1769
1770   DebugOnly<int> r =
1771       SprintfLiteral(formatBuffer_, "%6" PRIi64, slice.budget.timeBudget());
1772   MOZ_ASSERT(r > 0 && r < FormatBufferLength);
1773   return formatBuffer_;
1774 }
1775
1776 /* static */
1777 bool Statistics::printProfileTimes(const ProfileDurations& times,
1778                                    Sprinter& sprinter) {
1779   for (auto time : times) {
1780     int64_t millis = int64_t(time.ToMilliseconds());
1781     if (!sprinter.jsprintf(" %6" PRIi64, millis)) {
1782       return false;
1783     }
1784   }
1785
1786   return sprinter.put("\n");
1787 }
1788
1789 constexpr size_t SliceMetadataFormatWidth() {
1790   size_t fieldCount = 0;
1791   size_t totalWidth = 0;
1792
1793 #define UPDATE_COUNT_AND_WIDTH(_1, width, _2, _3) \
1794   fieldCount++;                                   \
1795   totalWidth += width;
1796   FOR_EACH_GC_PROFILE_SLICE_METADATA(UPDATE_COUNT_AND_WIDTH)
1797 #undef UPDATE_COUNT_AND_WIDTH
1798
1799   // Add padding between fields.
1800   totalWidth += fieldCount - 1;
1801
1802   return totalWidth;
1803 }
1804
1805 void Statistics::printTotalProfileTimes() {
1806   if (!enableProfiling_) {
1807     return;
1808   }
1809
1810   Sprinter sprinter;
1811   if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
1812     return;
1813   }
1814
1815   size_t pid = getpid();
1816   JSRuntime* runtime = gc->rt;
1817
1818 #define PRINT_FIELD_VALUE(_1, _2, format, value) \
1819   if (!sprinter.jsprintf(" " format, value)) {   \
1820     return;                                      \
1821   }
1822   FOR_EACH_GC_PROFILE_COMMON_METADATA(PRINT_FIELD_VALUE)
1823 #undef PRINT_FIELD_VALUE
1824
1825   // Use whole width of per-slice metadata to print total slices so the profile
1826   // totals that follow line up.
1827   size_t width = SliceMetadataFormatWidth();
1828   if (!sprinter.jsprintf(" %-*s", int(width), formatTotalSlices())) {
1829     return;
1830   }
1831
1832   if (!printProfileTimes(totalTimes_, sprinter)) {
1833     return;
1834   }
1835
1836   fputs(sprinter.string(), profileFile());
1837 }
1838
1839 const char* Statistics::formatTotalSlices() {
1840   DebugOnly<int> r = SprintfLiteral(
1841       formatBuffer_, "TOTALS: %7" PRIu64 " slices:", sliceCount_);
1842   MOZ_ASSERT(r > 0 && r < FormatBufferLength);
1843   return formatBuffer_;
1844 }