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       aborted(false),
 789       enableProfiling_(false),
 790       sliceCount_(0) {
 791   for (auto& count : counts) {
 792     count = 0;
 793   }
 794
 795   for (auto& stat : stats) {
 796     stat = 0;
 797   }
 798
 799 #ifdef DEBUG
 800   for (const auto& duration : totalTimes_) {
 801     using ElementType = std::remove_reference_t<decltype(duration)>;
 802     static_assert(!std::is_trivially_constructible_v<ElementType>,
 803                   "Statistics::Statistics will only initialize "
 804                   "totalTimes_'s elements if their default constructor is "
 805                   "non-trivial");
 806     MOZ_ASSERT(duration.IsZero(),
 807                "totalTimes_ default-initialization should have "
 808                "default-initialized every element of totalTimes_ to zero");
 809   }
 810 #endif
 811
 812   MOZ_ALWAYS_TRUE(phaseStack.reserve(MAX_PHASE_NESTING));
 813   MOZ_ALWAYS_TRUE(suspendedPhases.reserve(MAX_SUSPENDED_PHASES));
 814
 815   gcTimerFile = MaybeOpenFileFromEnv("MOZ_GCTIMER");
 816   gcDebugFile = MaybeOpenFileFromEnv("JS_GC_DEBUG");
 817   gcProfileFile = MaybeOpenFileFromEnv("JS_GC_PROFILE_FILE", stderr);
 818
 819   gc::ReadProfileEnv("JS_GC_PROFILE",
 820                      "Report major GCs taking more than N milliseconds for "
 821                      "all or just the main runtime\n",
 822                      &enableProfiling_, &profileWorkers_, &profileThreshold_);
 823 }
 824
 825 Statistics::~Statistics() {
 826   if (gcTimerFile && gcTimerFile != stdout && gcTimerFile != stderr) {
 827     fclose(gcTimerFile);
 828   }
 829   if (gcDebugFile && gcDebugFile != stdout && gcDebugFile != stderr) {
 830     fclose(gcDebugFile);
 831   }
 832 }
 833
 834 /* static */
 835 bool Statistics::initialize() {
 836 #ifdef DEBUG
 837   // Sanity check generated tables.
 838   for (auto i : AllPhases()) {
 839     auto parent = phases[i].parent;
 840     if (parent != Phase::NONE) {
 841       MOZ_ASSERT(phases[i].depth == phases[parent].depth + 1);
 842     }
 843     auto firstChild = phases[i].firstChild;
 844     if (firstChild != Phase::NONE) {
 845       MOZ_ASSERT(i == phases[firstChild].parent);
 846       MOZ_ASSERT(phases[i].depth == phases[firstChild].depth - 1);
 847     }
 848     auto nextSibling = phases[i].nextSibling;
 849     if (nextSibling != Phase::NONE) {
 850       MOZ_ASSERT(parent == phases[nextSibling].parent);
 851       MOZ_ASSERT(phases[i].depth == phases[nextSibling].depth);
 852     }
 853     auto nextWithPhaseKind = phases[i].nextWithPhaseKind;
 854     if (nextWithPhaseKind != Phase::NONE) {
 855       MOZ_ASSERT(phases[i].phaseKind == phases[nextWithPhaseKind].phaseKind);
 856       MOZ_ASSERT(parent != phases[nextWithPhaseKind].parent);
 857     }
 858   }
 859   for (auto i : AllPhaseKinds()) {
 860     MOZ_ASSERT(phases[phaseKinds[i].firstPhase].phaseKind == i);
 861     for (auto j : AllPhaseKinds()) {
 862       MOZ_ASSERT_IF(i != j, phaseKinds[i].telemetryBucket !=
 863                                 phaseKinds[j].telemetryBucket);
 864     }
 865   }
 866 #endif
 867
 868   return true;
 869 }
 870
 871 JS::GCSliceCallback Statistics::setSliceCallback(
 872     JS::GCSliceCallback newCallback) {
 873   JS::GCSliceCallback oldCallback = sliceCallback;
 874   sliceCallback = newCallback;
 875   return oldCallback;
 876 }
 877
 878 TimeDuration Statistics::clearMaxGCPauseAccumulator() {
 879   TimeDuration prior = maxPauseInInterval;
 880   maxPauseInInterval = TimeDuration::Zero();
 881   return prior;
 882 }
 883
 884 TimeDuration Statistics::getMaxGCPauseSinceClear() {
 885   return maxPauseInInterval;
 886 }
 887
 888 // Sum up the time for a phase, including instances of the phase with different
 889 // parents.
 890 static TimeDuration SumPhase(PhaseKind phaseKind,
 891                              const Statistics::PhaseTimes& times) {
 892   TimeDuration sum;
 893   for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
 894     sum += times[phase];
 895   }
 896   return sum;
 897 }
 898
 899 static bool CheckSelfTime(Phase parent, Phase child,
 900                           const Statistics::PhaseTimes& times,
 901                           const Statistics::PhaseTimes& selfTimes,
 902                           TimeDuration childTime) {
 903   if (selfTimes[parent] < childTime) {
 904     fprintf(
 905         stderr,
 906         "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
 907         phases[parent].name, times[parent].ToMilliseconds(),
 908         selfTimes[parent].ToMilliseconds(), phases[child].name,
 909         childTime.ToMilliseconds());
 910     fflush(stderr);
 911     return false;
 912   }
 913
 914   return true;
 915 }
 916
 917 static PhaseKind FindLongestPhaseKind(const Statistics::PhaseKindTimes& times) {
 918   TimeDuration longestTime;
 919   PhaseKind phaseKind = PhaseKind::NONE;
 920   for (auto i : MajorGCPhaseKinds()) {
 921     if (times[i] > longestTime) {
 922       longestTime = times[i];
 923       phaseKind = i;
 924     }
 925   }
 926
 927   return phaseKind;
 928 }
 929
 930 static PhaseKind LongestPhaseSelfTimeInMajorGC(
 931     const Statistics::PhaseTimes& times) {
 932   // Start with total times per expanded phase, including children's times.
 933   Statistics::PhaseTimes selfTimes(times);
 934
 935   // We have the total time spent in each phase, including descendant times.
 936   // Loop over the children and subtract their times from their parent's self
 937   // time.
 938   for (auto i : AllPhases()) {
 939     Phase parent = phases[i].parent;
 940     if (parent != Phase::NONE) {
 941       bool ok = CheckSelfTime(parent, i, times, selfTimes, times[i]);
 942
 943       // This happens very occasionally in release builds and frequently
 944       // in Windows debug builds. Skip collecting longest phase telemetry
 945       // if it does.
 946 #ifndef XP_WIN
 947       MOZ_ASSERT(ok, "Inconsistent time data; see bug 1400153");
 948 #endif
 949       if (!ok) {
 950         return PhaseKind::NONE;
 951       }
 952
 953       selfTimes[parent] -= times[i];
 954     }
 955   }
 956
 957   // Sum expanded phases corresponding to the same phase.
 958   Statistics::PhaseKindTimes phaseKindTimes;
 959   for (auto i : AllPhaseKinds()) {
 960     phaseKindTimes[i] = SumPhase(i, selfTimes);
 961   }
 962
 963   return FindLongestPhaseKind(phaseKindTimes);
 964 }
 965
 966 void Statistics::printStats() {
 967   if (aborted) {
 968     fprintf(gcTimerFile,
 969             "OOM during GC statistics collection. The report is unavailable "
 970             "for this GC.\n");
 971   } else {
 972     UniqueChars msg = formatDetailedMessage();
 973     if (msg) {
 974       double secSinceStart =
 975           TimeBetween(TimeStamp::ProcessCreation(), slices_[0].start)
 976               .ToSeconds();
 977       fprintf(gcTimerFile, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
 978     }
 979   }
 980   fflush(gcTimerFile);
 981 }
 982
 983 void Statistics::beginGC(JS::GCOptions options, const TimeStamp& currentTime) {
 984   slices_.clearAndFree();
 985   sccTimes.clearAndFree();
 986   gcOptions = options;
 987   nonincrementalReason_ = GCAbortReason::None;
 988
 989   preTotalHeapBytes = gc->heapSize.bytes();
 990
 991   preCollectedHeapBytes = 0;
 992
 993   startingMajorGCNumber = gc->majorGCCount();
 994   startingSliceNumber = gc->gcNumber();
 995
 996   if (gc->lastGCEndTime()) {
 997     timeSinceLastGC = TimeBetween(gc->lastGCEndTime(), currentTime);
 998   }
 999
1000   totalGCTime_ = TimeDuration::Zero();
1001 }
1002
1003 void Statistics::measureInitialHeapSize() {
1004   MOZ_ASSERT(preCollectedHeapBytes == 0);
1005   for (GCZonesIter zone(gc); !zone.done(); zone.next()) {
1006     preCollectedHeapBytes += zone->gcHeapSize.bytes();
1007   }
1008 }
1009
1010 void Statistics::endGC() {
1011   postTotalHeapBytes = gc->heapSize.bytes();
1012
1013   sendGCTelemetry();
1014 }
1015
1016 TimeDuration Statistics::sumTotalParallelTime(PhaseKind phaseKind) const {
1017   TimeDuration total;
1018   for (const SliceData& slice : slices_) {
1019     total += slice.totalParallelTimes[phaseKind];
1020   }
1021   return total;
1022 }
1023
1024 void Statistics::sendGCTelemetry() {
1025   JSRuntime* runtime = gc->rt;
1026   // NOTE: "Compartmental" is term that was deprecated with the
1027   // introduction of zone-based GC, but the old telemetry probe
1028   // continues to be used.
1029   runtime->metrics().GC_IS_COMPARTMENTAL(!gc->fullGCRequested);
1030   runtime->metrics().GC_ZONE_COUNT(zoneStats.zoneCount);
1031   runtime->metrics().GC_ZONES_COLLECTED(zoneStats.collectedZoneCount);
1032
1033   TimeDuration prepareTotal = phaseTimes[Phase::PREPARE];
1034   TimeDuration markTotal = SumPhase(PhaseKind::MARK, phaseTimes);
1035   TimeDuration markRootsTotal = SumPhase(PhaseKind::MARK_ROOTS, phaseTimes);
1036
1037   // Gray and weak marking time is counted under MARK_WEAK and not MARK_GRAY.
1038   TimeDuration markWeakTotal = SumPhase(PhaseKind::MARK_WEAK, phaseTimes);
1039   TimeDuration markGrayNotWeak =
1040       SumPhase(PhaseKind::MARK_GRAY, phaseTimes) +
1041       SumPhase(PhaseKind::MARK_INCOMING_GRAY, phaseTimes);
1042   TimeDuration markGrayWeak = SumPhase(PhaseKind::MARK_GRAY_WEAK, phaseTimes);
1043   TimeDuration markGrayTotal = markGrayNotWeak + markGrayWeak;
1044   TimeDuration markNotGrayOrWeak = markTotal - markGrayNotWeak - markWeakTotal;
1045   if (markNotGrayOrWeak < TimeDuration::FromMilliseconds(0)) {
1046     markNotGrayOrWeak = TimeDuration::Zero();
1047   }
1048
1049   size_t markCount = getCount(COUNT_CELLS_MARKED);
1050
1051   runtime->metrics().GC_PREPARE_MS(prepareTotal);
1052   runtime->metrics().GC_MARK_MS(markNotGrayOrWeak);
1053   if (markTotal >= TimeDuration::FromMicroseconds(1)) {
1054     double markRate = double(markCount) / t(markTotal);
1055     runtime->metrics().GC_MARK_RATE_2(uint32_t(markRate));
1056   }
1057   runtime->metrics().GC_SWEEP_MS(phaseTimes[Phase::SWEEP]);
1058   if (gc->didCompactZones()) {
1059     runtime->metrics().GC_COMPACT_MS(phaseTimes[Phase::COMPACT]);
1060   }
1061   runtime->metrics().GC_MARK_ROOTS_US(markRootsTotal);
1062   runtime->metrics().GC_MARK_GRAY_MS_2(markGrayTotal);
1063   runtime->metrics().GC_MARK_WEAK_MS(markWeakTotal);
1064   runtime->metrics().GC_NON_INCREMENTAL(nonincremental());
1065   if (nonincremental()) {
1066     runtime->metrics().GC_NON_INCREMENTAL_REASON(
1067         uint32_t(nonincrementalReason_));
1068   }
1069
1070 #ifdef DEBUG
1071   // Reset happens non-incrementally, so only the last slice can be reset.
1072   for (size_t i = 0; i < slices_.length() - 1; i++) {
1073     MOZ_ASSERT(!slices_[i].wasReset());
1074   }
1075 #endif
1076   const auto& lastSlice = slices_.back();
1077   runtime->metrics().GC_RESET(lastSlice.wasReset());
1078   if (lastSlice.wasReset()) {
1079     runtime->metrics().GC_RESET_REASON(uint32_t(lastSlice.resetReason));
1080   }
1081
1082   TimeDuration total, longest;
1083   gcDuration(&total, &longest);
1084
1085   runtime->metrics().GC_MS(total);
1086   runtime->metrics().GC_MAX_PAUSE_MS_2(longest);
1087
1088   const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
1089   runtime->metrics().GC_MMU_50(mmu50 * 100.0);
1090
1091   // Record scheduling telemetry for the main runtime but not for workers, which
1092   // are scheduled differently.
1093   if (!runtime->parentRuntime && timeSinceLastGC) {
1094     runtime->metrics().GC_TIME_BETWEEN_S(timeSinceLastGC);
1095     if (!nonincremental()) {
1096       runtime->metrics().GC_SLICE_COUNT(slices_.length());
1097     }
1098   }
1099
1100   if (!lastSlice.wasReset() && preCollectedHeapBytes != 0) {
1101     size_t bytesSurvived = 0;
1102     for (ZonesIter zone(runtime, WithAtoms); !zone.done(); zone.next()) {
1103       if (zone->wasCollected()) {
1104         bytesSurvived += zone->gcHeapSize.retainedBytes();
1105       }
1106     }
1107
1108     MOZ_ASSERT(preCollectedHeapBytes >= bytesSurvived);
1109     double survivalRate =
1110         100.0 * double(bytesSurvived) / double(preCollectedHeapBytes);
1111     runtime->metrics().GC_TENURED_SURVIVAL_RATE(survivalRate);
1112
1113     // Calculate 'effectiveness' in MB / second, on main thread only for now.
1114     if (!runtime->parentRuntime) {
1115       size_t bytesFreed = preCollectedHeapBytes - bytesSurvived;
1116       TimeDuration clampedTotal =
1117           TimeDuration::Max(total, TimeDuration::FromMilliseconds(1));
1118       double effectiveness =
1119           (double(bytesFreed) / BYTES_PER_MB) / clampedTotal.ToSeconds();
1120       runtime->metrics().GC_EFFECTIVENESS(uint32_t(effectiveness));
1121     }
1122   }
1123
1124   // Parallel marking stats.
1125   if (gc->isParallelMarkingEnabled()) {
1126     TimeDuration wallTime = SumPhase(PhaseKind::PARALLEL_MARK, phaseTimes);
1127     TimeDuration parallelMarkTime =
1128         sumTotalParallelTime(PhaseKind::PARALLEL_MARK_MARK);
1129     TimeDuration parallelRunTime =
1130         parallelMarkTime + sumTotalParallelTime(PhaseKind::PARALLEL_MARK_OTHER);
1131     if (wallTime && parallelMarkTime) {
1132       uint32_t threadCount = gc->markers.length();
1133       double speedup = parallelMarkTime / wallTime;
1134       double utilization = parallelRunTime / (wallTime * threadCount);
1135       MOZ_ASSERT(utilization <= 1.0);
1136       runtime->metrics().GC_PARALLEL_MARK_SPEEDUP(uint32_t(speedup * 100.0));
1137       runtime->metrics().GC_PARALLEL_MARK_UTILIZATION(
1138           std::clamp(utilization * 100.0, 0.0, 100.0));
1139       runtime->metrics().GC_PARALLEL_MARK_INTERRUPTIONS(
1140           getCount(COUNT_PARALLEL_MARK_INTERRUPTIONS));
1141     }
1142   }
1143 }
1144
1145 void Statistics::beginNurseryCollection() {
1146   count(COUNT_MINOR_GC);
1147   startingMinorGCNumber = gc->minorGCCount();
1148 }
1149
1150 void Statistics::endNurseryCollection() { tenuredAllocsSinceMinorGC = 0; }
1151
1152 Statistics::SliceData::SliceData(const SliceBudget& budget,
1153                                  Maybe<Trigger> trigger, JS::GCReason reason,
1154                                  TimeStamp start, size_t startFaults,
1155                                  gc::State initialState)
1156     : budget(budget),
1157       reason(reason),
1158       trigger(trigger),
1159       initialState(initialState),
1160       start(start),
1161       startFaults(startFaults) {}
1162
1163 TimeDuration Statistics::SliceData::duration() const {
1164   return TimeBetween(start, end);
1165 }
1166
1167 void Statistics::beginSlice(const ZoneGCStats& zoneStats, JS::GCOptions options,
1168                             const SliceBudget& budget, JS::GCReason reason,
1169                             bool budgetWasIncreased) {
1170   MOZ_ASSERT(phaseStack.empty() ||
1171              (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
1172
1173   this->zoneStats = zoneStats;
1174
1175   TimeStamp currentTime = TimeStamp::Now();
1176
1177   bool first = !gc->isIncrementalGCInProgress();
1178   if (first) {
1179     beginGC(options, currentTime);
1180   }
1181
1182   JSRuntime* runtime = gc->rt;
1183   if (!runtime->parentRuntime && !slices_.empty()) {
1184     TimeDuration timeSinceLastSlice =
1185         TimeBetween(slices_.back().end, currentTime);
1186     runtime->metrics().GC_TIME_BETWEEN_SLICES_MS(timeSinceLastSlice);
1187   }
1188
1189   Maybe<Trigger> trigger = recordedTrigger;
1190   recordedTrigger.reset();
1191
1192   if (!slices_.emplaceBack(budget, trigger, reason, currentTime,
1193                            GetPageFaultCount(), gc->state())) {
1194     // If we are OOM, set a flag to indicate we have missing slice data.
1195     aborted = true;
1196     return;
1197   }
1198
1199   runtime->metrics().GC_REASON_2(uint32_t(reason));
1200   runtime->metrics().GC_BUDGET_WAS_INCREASED(budgetWasIncreased);
1201
1202   // Slice callbacks should only fire for the outermost level.
1203   if (sliceCallback) {
1204     JSContext* cx = context();
1205     JS::GCDescription desc(!gc->fullGCRequested, false, options, reason);
1206     if (first) {
1207       (*sliceCallback)(cx, JS::GC_CYCLE_BEGIN, desc);
1208     }
1209     (*sliceCallback)(cx, JS::GC_SLICE_BEGIN, desc);
1210   }
1211
1212   log("begin slice");
1213 }
1214
1215 void Statistics::endSlice() {
1216   MOZ_ASSERT(phaseStack.empty() ||
1217              (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));
1218
1219   if (!aborted) {
1220     auto& slice = slices_.back();
1221     slice.end = TimeStamp::Now();
1222     slice.endFaults = GetPageFaultCount();
1223     slice.finalState = gc->state();
1224
1225     log("end slice");
1226
1227     sendSliceTelemetry(slice);
1228
1229     sliceCount_++;
1230
1231     totalGCTime_ += slice.duration();
1232   }
1233
1234   bool last = !gc->isIncrementalGCInProgress();
1235   if (last) {
1236     if (gcTimerFile) {
1237       printStats();
1238     }
1239
1240     if (!aborted) {
1241       endGC();
1242     }
1243   }
1244
1245   if (!aborted &&
1246       ShouldPrintProfile(gc->rt, enableProfiling_, profileWorkers_,
1247                          profileThreshold_, slices_.back().duration())) {
1248     printSliceProfile();
1249   }
1250
1251   // Slice callbacks should only fire for the outermost level.
1252   if (!aborted) {
1253     if (sliceCallback) {
1254       JSContext* cx = context();
1255       JS::GCDescription desc(!gc->fullGCRequested, last, gcOptions,
1256                              slices_.back().reason);
1257       (*sliceCallback)(cx, JS::GC_SLICE_END, desc);
1258       if (last) {
1259         (*sliceCallback)(cx, JS::GC_CYCLE_END, desc);
1260       }
1261     }
1262   }
1263
1264   // Do this after the slice callback since it uses these values.
1265   if (last) {
1266     for (auto& count : counts) {
1267       count = 0;
1268     }
1269
1270     // Clear the timers at the end of a GC, preserving the data for
1271     // PhaseKind::MUTATOR.
1272     auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
1273     auto mutatorTime = phaseTimes[Phase::MUTATOR];
1274
1275     phaseStartTimes = PhaseTimeStamps();
1276 #ifdef DEBUG
1277     phaseEndTimes = PhaseTimeStamps();
1278 #endif
1279     phaseTimes = PhaseTimes();
1280
1281     phaseStartTimes[Phase::MUTATOR] = mutatorStartTime;
1282     phaseTimes[Phase::MUTATOR] = mutatorTime;
1283   }
1284
1285   aborted = false;
1286 }
1287
1288 void Statistics::sendSliceTelemetry(const SliceData& slice) {
1289   JSRuntime* runtime = gc->rt;
1290   TimeDuration sliceTime = slice.duration();
1291   runtime->metrics().GC_SLICE_MS(sliceTime);
1292
1293   if (slice.budget.isTimeBudget()) {
1294     TimeDuration budgetDuration = slice.budget.timeBudgetDuration();
1295     runtime->metrics().GC_BUDGET_MS_2(budgetDuration);
1296
1297     if (IsCurrentlyAnimating(runtime->lastAnimationTime, slice.end)) {
1298       runtime->metrics().GC_ANIMATION_MS(sliceTime);
1299     }
1300
1301     bool wasLongSlice = false;
1302     if (sliceTime > budgetDuration) {
1303       // Record how long we went over budget.
1304       TimeDuration overrun = sliceTime - budgetDuration;
1305       runtime->metrics().GC_BUDGET_OVERRUN(overrun);
1306
1307       // Long GC slices are those that go 50% or 5ms over their budget.
1308       wasLongSlice = (overrun > TimeDuration::FromMilliseconds(5)) ||
1309                      (overrun > (budgetDuration / int64_t(2)));
1310
1311       // Record the longest phase in any long slice.
1312       if (wasLongSlice) {
1313         PhaseKind longest = LongestPhaseSelfTimeInMajorGC(slice.phaseTimes);
1314         reportLongestPhaseInMajorGC(longest, [runtime](auto sample) {
1315           runtime->metrics().GC_SLOW_PHASE(sample);
1316         });
1317
1318         // If the longest phase was waiting for parallel tasks then record the
1319         // longest task.
1320         if (longest == PhaseKind::JOIN_PARALLEL_TASKS) {
1321           PhaseKind longestParallel =
1322               FindLongestPhaseKind(slice.maxParallelTimes);
1323           reportLongestPhaseInMajorGC(longestParallel, [runtime](auto sample) {
1324             runtime->metrics().GC_SLOW_TASK(sample);
1325           });
1326         }
1327       }
1328     }
1329
1330     // Record `wasLongSlice` for all TimeBudget slices.
1331     runtime->metrics().GC_SLICE_WAS_LONG(wasLongSlice);
1332   }
1333 }
1334
1335 template <typename Fn>
1336 void Statistics::reportLongestPhaseInMajorGC(PhaseKind longest, Fn reportFn) {
1337   if (longest != PhaseKind::NONE) {
1338     uint8_t bucket = phaseKinds[longest].telemetryBucket;
1339     reportFn(bucket);
1340   }
1341 }
1342
1343 bool Statistics::startTimingMutator() {
1344   if (phaseStack.length() != 0) {
1345     // Should only be called from outside of GC.
1346     MOZ_ASSERT(phaseStack.length() == 1);
1347     MOZ_ASSERT(phaseStack[0] == Phase::MUTATOR);
1348     return false;
1349   }
1350
1351   MOZ_ASSERT(suspendedPhases.empty());
1352
1353   timedGCTime = TimeDuration::Zero();
1354   phaseStartTimes[Phase::MUTATOR] = TimeStamp();
1355   phaseTimes[Phase::MUTATOR] = TimeDuration::Zero();
1356   timedGCStart = TimeStamp();
1357
1358   beginPhase(PhaseKind::MUTATOR);
1359   return true;
1360 }
1361
1362 bool Statistics::stopTimingMutator(double& mutator_ms, double& gc_ms) {
1363   // This should only be called from outside of GC, while timing the mutator.
1364   if (phaseStack.length() != 1 || phaseStack[0] != Phase::MUTATOR) {
1365     return false;
1366   }
1367
1368   endPhase(PhaseKind::MUTATOR);
1369   mutator_ms = t(phaseTimes[Phase::MUTATOR]);
1370   gc_ms = t(timedGCTime);
1371
1372   return true;
1373 }
1374
1375 void Statistics::suspendPhases(PhaseKind suspension) {
1376   MOZ_ASSERT(suspension == PhaseKind::EXPLICIT_SUSPENSION ||
1377              suspension == PhaseKind::IMPLICIT_SUSPENSION);
1378   while (!phaseStack.empty()) {
1379     MOZ_ASSERT(suspendedPhases.length() < MAX_SUSPENDED_PHASES);
1380     Phase parent = phaseStack.back();
1381     suspendedPhases.infallibleAppend(parent);
1382     recordPhaseEnd(parent);
1383   }
1384   suspendedPhases.infallibleAppend(lookupChildPhase(suspension));
1385 }
1386
1387 void Statistics::resumePhases() {
1388   MOZ_ASSERT(suspendedPhases.back() == Phase::EXPLICIT_SUSPENSION ||
1389              suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION);
1390   suspendedPhases.popBack();
1391
1392   while (!suspendedPhases.empty() &&
1393          suspendedPhases.back() != Phase::EXPLICIT_SUSPENSION &&
1394          suspendedPhases.back() != Phase::IMPLICIT_SUSPENSION) {
1395     Phase resumePhase = suspendedPhases.popCopy();
1396     if (resumePhase == Phase::MUTATOR) {
1397       timedGCTime += TimeBetween(timedGCStart, TimeStamp::Now());
1398     }
1399     recordPhaseBegin(resumePhase);
1400   }
1401 }
1402
1403 void Statistics::beginPhase(PhaseKind phaseKind) {
1404   // No longer timing these phases. We should never see these.
1405   MOZ_ASSERT(phaseKind != PhaseKind::GC_BEGIN &&
1406              phaseKind != PhaseKind::GC_END);
1407
1408   // PhaseKind::MUTATOR is suspended while performing GC.
1409   if (currentPhase() == Phase::MUTATOR) {
1410     suspendPhases(PhaseKind::IMPLICIT_SUSPENSION);
1411   }
1412
1413   recordPhaseBegin(lookupChildPhase(phaseKind));
1414 }
1415
1416 void Statistics::recordPhaseBegin(Phase phase) {
1417   MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
1418
1419   // Guard against any other re-entry.
1420   MOZ_ASSERT(!phaseStartTimes[phase]);
1421
1422   MOZ_ASSERT(phaseStack.length() < MAX_PHASE_NESTING);
1423
1424   Phase current = currentPhase();
1425   MOZ_ASSERT(phases[phase].parent == current);
1426
1427   TimeStamp now = TimeStamp::Now();
1428
1429   if (current != Phase::NONE) {
1430     MOZ_ASSERT(now >= phaseStartTimes[currentPhase()],
1431                "Inconsistent time data; see bug 1400153");
1432     if (now < phaseStartTimes[currentPhase()]) {
1433       now = phaseStartTimes[currentPhase()];
1434       aborted = true;
1435     }
1436   }
1437
1438   phaseStack.infallibleAppend(phase);
1439   phaseStartTimes[phase] = now;
1440   log("begin: %s", phases[phase].path);
1441 }
1442
1443 void Statistics::recordPhaseEnd(Phase phase) {
1444   MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
1445
1446   MOZ_ASSERT(phaseStartTimes[phase]);
1447
1448   TimeStamp now = TimeStamp::Now();
1449
1450   // Make sure this phase ends after it starts.
1451   MOZ_ASSERT(now >= phaseStartTimes[phase],
1452              "Inconsistent time data; see bug 1400153");
1453
1454 #ifdef DEBUG
1455   // Make sure this phase ends after all of its children. Note that some
1456   // children might not have run in this instance, in which case they will
1457   // have run in a previous instance of this parent or not at all.
1458   for (Phase kid = phases[phase].firstChild; kid != Phase::NONE;
1459        kid = phases[kid].nextSibling) {
1460     if (phaseEndTimes[kid].IsNull()) {
1461       continue;
1462     }
1463     if (phaseEndTimes[kid] > now) {
1464       fprintf(stderr,
1465               "Parent %s ended at %.3fms, before child %s ended at %.3fms?\n",
1466               phases[phase].name,
1467               t(TimeBetween(TimeStamp::FirstTimeStamp(), now)),
1468               phases[kid].name,
1469               t(TimeBetween(TimeStamp::FirstTimeStamp(), phaseEndTimes[kid])));
1470     }
1471     MOZ_ASSERT(phaseEndTimes[kid] <= now,
1472                "Inconsistent time data; see bug 1400153");
1473   }
1474 #endif
1475
1476   if (now < phaseStartTimes[phase]) {
1477     now = phaseStartTimes[phase];
1478     aborted = true;
1479   }
1480
1481   if (phase == Phase::MUTATOR) {
1482     timedGCStart = now;
1483   }
1484
1485   phaseStack.popBack();
1486
1487   TimeDuration t = TimeBetween(phaseStartTimes[phase], now);
1488   if (!slices_.empty()) {
1489     slices_.back().phaseTimes[phase] += t;
1490   }
1491   phaseTimes[phase] += t;
1492   phaseStartTimes[phase] = TimeStamp();
1493
1494 #ifdef DEBUG
1495   phaseEndTimes[phase] = now;
1496   log("end: %s", phases[phase].path);
1497 #endif
1498 }
1499
1500 void Statistics::endPhase(PhaseKind phaseKind) {
1501   Phase phase = currentPhase();
1502   MOZ_ASSERT(phase != Phase::NONE);
1503   MOZ_ASSERT(phases[phase].phaseKind == phaseKind);
1504
1505   recordPhaseEnd(phase);
1506
1507   // When emptying the stack, we may need to return to timing the mutator
1508   // (PhaseKind::MUTATOR).
1509   if (phaseStack.empty() && !suspendedPhases.empty() &&
1510       suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION) {
1511     resumePhases();
1512   }
1513 }
1514
1515 void Statistics::recordParallelPhase(PhaseKind phaseKind,
1516                                      TimeDuration duration) {
1517   MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));
1518
1519   if (aborted) {
1520     return;
1521   }
1522
1523   slices_.back().totalParallelTimes[phaseKind] += duration;
1524
1525   // Also record the maximum task time for each phase. Don't record times for
1526   // parent phases.
1527   TimeDuration& maxTime = slices_.back().maxParallelTimes[phaseKind];
1528   maxTime = std::max(maxTime, duration);
1529 }
1530
1531 TimeStamp Statistics::beginSCC() { return TimeStamp::Now(); }
1532
1533 void Statistics::endSCC(unsigned scc, TimeStamp start) {
1534   if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1)) {
1535     return;
1536   }
1537
1538   sccTimes[scc] += TimeBetween(start, TimeStamp::Now());
1539 }
1540
1541 /*
1542  * Calculate minimum mutator utilization for previous incremental GC.
1543  *
1544  * MMU (minimum mutator utilization) is a measure of how much garbage collection
1545  * is affecting the responsiveness of the system. MMU measurements are given
1546  * with respect to a certain window size. If we report MMU(50ms) = 80%, then
1547  * that means that, for any 50ms window of time, at least 80% of the window is
1548  * devoted to the mutator. In other words, the GC is running for at most 20% of
1549  * the window, or 10ms. The GC can run multiple slices during the 50ms window
1550  * as long as the total time it spends is at most 10ms.
1551  */
1552 double Statistics::computeMMU(TimeDuration window) const {
1553   MOZ_ASSERT(window > TimeDuration::Zero());
1554   MOZ_ASSERT(!slices().empty());
1555
1556   // Examine all ranges of slices from |startIndex| to |endIndex| inclusive
1557   // whose timestamps span less than the window duration. The time spent in GC
1558   // in each range is stored in |gcInRange| by maintaining a running total. The
1559   // maximum value of this after adjustment to the window size is recorded in
1560   // |maxGCInWindow|.
1561
1562   size_t startIndex = 0;
1563   const SliceData* startSlice = &sliceAt(startIndex);
1564   TimeDuration gcInRange = startSlice->duration();
1565   if (gcInRange >= window) {
1566     return 0.0;
1567   }
1568
1569   TimeDuration maxGCInWindow = gcInRange;
1570
1571   for (size_t endIndex = 1; endIndex < slices().length(); endIndex++) {
1572     const SliceData* endSlice = &sliceAt(endIndex);
1573     if (endSlice->duration() >= window) {
1574       return 0.0;
1575     }
1576
1577     gcInRange += endSlice->duration();
1578
1579     while (TimeBetween(startSlice->end, endSlice->end) >= window) {
1580       gcInRange -= startSlice->duration();
1581       ++startIndex;
1582       MOZ_ASSERT(startIndex <= endIndex);
1583       startSlice = &sliceAt(startIndex);
1584     }
1585
1586     TimeDuration totalInRange = TimeBetween(startSlice->start, endSlice->end);
1587     MOZ_ASSERT(gcInRange <= totalInRange);
1588
1589     TimeDuration gcInWindow = gcInRange;
1590     if (totalInRange > window) {
1591       gcInWindow -= (totalInRange - window);
1592     }
1593     MOZ_ASSERT(gcInWindow <= window);
1594
1595     if (gcInWindow > maxGCInWindow) {
1596       maxGCInWindow = gcInWindow;
1597     }
1598   }
1599
1600   MOZ_ASSERT(maxGCInWindow >= TimeDuration::Zero());
1601   MOZ_ASSERT(maxGCInWindow <= window);
1602   return (window - maxGCInWindow) / window;
1603 }
1604
1605 void Statistics::maybePrintProfileHeaders() {
1606   static int printedHeader = 0;
1607   if ((printedHeader++ % 200) == 0) {
1608     printProfileHeader();
1609     if (gc->nursery().enableProfiling()) {
1610       gc->nursery().printProfileHeader();
1611     }
1612   }
1613 }
1614
1615 // The following macros define GC profile metadata fields that are printed
1616 // before the timing information defined by FOR_EACH_GC_PROFILE_TIME.
1617
1618 #define FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
1619   _("PID", 7, "%7zu", pid)                     \
1620   _("Runtime", 14, "0x%12p", runtime)
1621
1622 #define FOR_EACH_GC_PROFILE_SLICE_METADATA(_)         \
1623   _("Timestamp", 10, "%10.6f", timestamp.ToSeconds()) \
1624   _("Reason", 20, "%-20.20s", reason)                 \
1625   _("States", 6, "%6s", formatGCStates(slice))        \
1626   _("FSNR", 4, "%4s", formatGCFlags(slice))           \
1627   _("SizeKB", 8, "%8zu", sizeKB)                      \
1628   _("Zs", 3, "%3zu", zoneCount)                       \
1629   _("Cs", 3, "%3zu", compartmentCount)                \
1630   _("Rs", 3, "%3zu", realmCount)                      \
1631   _("Budget", 6, "%6s", formatBudget(slice))
1632
1633 #define FOR_EACH_GC_PROFILE_METADATA(_)  \
1634   FOR_EACH_GC_PROFILE_COMMON_METADATA(_) \
1635   FOR_EACH_GC_PROFILE_SLICE_METADATA(_)
1636
1637 void Statistics::printProfileHeader() {
1638   if (!enableProfiling_) {
1639     return;
1640   }
1641
1642   Sprinter sprinter;
1643   if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
1644     return;
1645   }
1646
1647 #define PRINT_METADATA_NAME(name, width, _1, _2)  \
1648   if (!sprinter.jsprintf(" %-*s", width, name)) { \
1649     return;                                       \
1650   }
1651   FOR_EACH_GC_PROFILE_METADATA(PRINT_METADATA_NAME)
1652 #undef PRINT_METADATA_NAME
1653
1654 #define PRINT_PROFILE_NAME(_1, text, _2)     \
1655   if (!sprinter.jsprintf(" %-6.6s", text)) { \
1656     return;                                  \
1657   }
1658   FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_NAME)
1659 #undef PRINT_PROFILE_NAME
1660
1661   if (!sprinter.put("\n")) {
1662     return;
1663   }
1664
1665   fputs(sprinter.string(), profileFile());
1666 }
1667
1668 static TimeDuration SumAllPhaseKinds(const Statistics::PhaseKindTimes& times) {
1669   TimeDuration sum;
1670   for (PhaseKind kind : AllPhaseKinds()) {
1671     sum += times[kind];
1672   }
1673   return sum;
1674 }
1675
1676 void Statistics::printSliceProfile() {
1677   maybePrintProfileHeaders();
1678
1679   const SliceData& slice = slices_.back();
1680   ProfileDurations times = getProfileTimes(slice);
1681   updateTotalProfileTimes(times);
1682
1683   Sprinter sprinter;
1684   if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
1685     return;
1686   }
1687
1688   size_t pid = getpid();
1689   JSRuntime* runtime = gc->rt;
1690   TimeDuration timestamp = TimeBetween(creationTime(), slice.end);
1691   const char* reason = ExplainGCReason(slice.reason);
1692   size_t sizeKB = gc->heapSize.bytes() / 1024;
1693   size_t zoneCount = zoneStats.zoneCount;
1694   size_t compartmentCount = zoneStats.compartmentCount;
1695   size_t realmCount = zoneStats.realmCount;
1696
1697 #define PRINT_FIELD_VALUE(_1, _2, format, value) \
1698   if (!sprinter.jsprintf(" " format, value)) {   \
1699     return;                                      \
1700   }
1701   FOR_EACH_GC_PROFILE_METADATA(PRINT_FIELD_VALUE)
1702 #undef PRINT_FIELD_VALUE
1703
1704   if (!printProfileTimes(times, sprinter)) {
1705     return;
1706   }
1707
1708   fputs(sprinter.string(), profileFile());
1709 }
1710
1711 Statistics::ProfileDurations Statistics::getProfileTimes(
1712     const SliceData& slice) const {
1713   ProfileDurations times;
1714
1715   times[ProfileKey::Total] = slice.duration();
1716   times[ProfileKey::Background] = SumAllPhaseKinds(slice.totalParallelTimes);
1717
1718 #define GET_PROFILE_TIME(name, text, phase)                      \
1719   if (phase != PhaseKind::NONE) {                                \
1720     times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
1721   }
1722   FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
1723 #undef GET_PROFILE_TIME
1724
1725   return times;
1726 }
1727
1728 void Statistics::updateTotalProfileTimes(const ProfileDurations& times) {
1729 #define UPDATE_PROFILE_TIME(name, _, phase) \
1730   totalTimes_[ProfileKey::name] += times[ProfileKey::name];
1731   FOR_EACH_GC_PROFILE_TIME(UPDATE_PROFILE_TIME)
1732 #undef UPDATE_PROFILE_TIME
1733 }
1734
1735 const char* Statistics::formatGCStates(const SliceData& slice) {
1736   DebugOnly<int> r =
1737       SprintfLiteral(formatBuffer_, "%1d -> %1d", int(slice.initialState),
1738                      int(slice.finalState));
1739   MOZ_ASSERT(r > 0 && r < FormatBufferLength);
1740   return formatBuffer_;
1741 }
1742
1743 const char* Statistics::formatGCFlags(const SliceData& slice) {
1744   bool fullGC = gc->fullGCRequested;
1745   bool shrinkingGC = gcOptions == JS::GCOptions::Shrink;
1746   bool nonIncrementalGC = nonincrementalReason_ != GCAbortReason::None;
1747   bool wasReset = slice.resetReason != GCAbortReason::None;
1748
1749   MOZ_ASSERT(FormatBufferLength >= 5);
1750   formatBuffer_[0] = fullGC ? 'F' : ' ';
1751   formatBuffer_[1] = shrinkingGC ? 'S' : ' ';
1752   formatBuffer_[2] = nonIncrementalGC ? 'N' : ' ';
1753   formatBuffer_[3] = wasReset ? 'R' : ' ';
1754   formatBuffer_[4] = '\0';
1755
1756   return formatBuffer_;
1757 }
1758
1759 const char* Statistics::formatBudget(const SliceData& slice) {
1760   if (nonincrementalReason_ != GCAbortReason::None ||
1761       !slice.budget.isTimeBudget()) {
1762     formatBuffer_[0] = '\0';
1763     return formatBuffer_;
1764   }
1765
1766   DebugOnly<int> r =
1767       SprintfLiteral(formatBuffer_, "%6" PRIi64, slice.budget.timeBudget());
1768   MOZ_ASSERT(r > 0 && r < FormatBufferLength);
1769   return formatBuffer_;
1770 }
1771
1772 /* static */
1773 bool Statistics::printProfileTimes(const ProfileDurations& times,
1774                                    Sprinter& sprinter) {
1775   for (auto time : times) {
1776     int64_t millis = int64_t(time.ToMilliseconds());
1777     if (!sprinter.jsprintf(" %6" PRIi64, millis)) {
1778       return false;
1779     }
1780   }
1781
1782   return sprinter.put("\n");
1783 }
1784
1785 constexpr size_t SliceMetadataFormatWidth() {
1786   size_t fieldCount = 0;
1787   size_t totalWidth = 0;
1788
1789 #define UPDATE_COUNT_AND_WIDTH(_1, width, _2, _3) \
1790   fieldCount++;                                   \
1791   totalWidth += width;
1792   FOR_EACH_GC_PROFILE_SLICE_METADATA(UPDATE_COUNT_AND_WIDTH)
1793 #undef UPDATE_COUNT_AND_WIDTH
1794
1795   // Add padding between fields.
1796   totalWidth += fieldCount - 1;
1797
1798   return totalWidth;
1799 }
1800
1801 void Statistics::printTotalProfileTimes() {
1802   if (!enableProfiling_) {
1803     return;
1804   }
1805
1806   Sprinter sprinter;
1807   if (!sprinter.init() || !sprinter.put(MajorGCProfilePrefix)) {
1808     return;
1809   }
1810
1811   size_t pid = getpid();
1812   JSRuntime* runtime = gc->rt;
1813
1814 #define PRINT_FIELD_VALUE(_1, _2, format, value) \
1815   if (!sprinter.jsprintf(" " format, value)) {   \
1816     return;                                      \
1817   }
1818   FOR_EACH_GC_PROFILE_COMMON_METADATA(PRINT_FIELD_VALUE)
1819 #undef PRINT_FIELD_VALUE
1820
1821   // Use whole width of per-slice metadata to print total slices so the profile
1822   // totals that follow line up.
1823   size_t width = SliceMetadataFormatWidth();
1824   if (!sprinter.jsprintf(" %-*s", int(width), formatTotalSlices())) {
1825     return;
1826   }
1827
1828   if (!printProfileTimes(totalTimes_, sprinter)) {
1829     return;
1830   }
1831
1832   fputs(sprinter.string(), profileFile());
1833 }
1834
1835 const char* Statistics::formatTotalSlices() {
1836   DebugOnly<int> r = SprintfLiteral(
1837       formatBuffer_, "TOTALS: %7" PRIu64 " slices:", sliceCount_);
1838   MOZ_ASSERT(r > 0 && r < FormatBufferLength);
1839   return formatBuffer_;
1840 }