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