src/gc/Statistics.cpp

/* -*- Mode: C++; tab-width: 8; indent-tabs-mode: nil; c-basic-offset: 2 -*-
 * vim: set ts=8 sts=2 et sw=2 tw=80:
 * This Source Code Form is subject to the terms of the Mozilla Public
 * License, v. 2.0. If a copy of the MPL was not distributed with this
 * file, You can obtain one at http://mozilla.org/MPL/2.0/. */

#include "gc/Statistics.h"

#include "mozilla/ArrayUtils.h"
#include "mozilla/DebugOnly.h"
#include "mozilla/Sprintf.h"
#include "mozilla/TimeStamp.h"

#include <algorithm>
#include <stdarg.h>
#include <stdio.h>
#include <type_traits>

#include "debugger/DebugAPI.h"
#include "gc/GC.h"
#include "gc/Memory.h"
#include "util/Text.h"
#include "vm/HelperThreads.h"
#include "vm/Runtime.h"
#include "vm/Time.h"

#include "gc/PrivateIterators-inl.h"

using namespace js;
using namespace js::gc;
using namespace js::gcstats;

using mozilla::DebugOnly;
using mozilla::EnumeratedArray;
using mozilla::Maybe;
using mozilla::TimeDuration;
using mozilla::TimeStamp;

static const size_t BYTES_PER_MB = 1024 * 1024;

/*
 * If this fails, then you can either delete this assertion and allow all
 * larger-numbered reasons to pile up in the last telemetry bucket, or switch
 * to GC_REASON_3 and bump the max value.
 */
static_assert(JS::GCReason::NUM_TELEMETRY_REASONS >= JS::GCReason::NUM_REASONS);

static inline auto AllPhaseKinds() {
  return mozilla::MakeEnumeratedRange(PhaseKind::FIRST, PhaseKind::LIMIT);
}

static inline auto MajorGCPhaseKinds() {
  return mozilla::MakeEnumeratedRange(PhaseKind::GC_BEGIN,
                                      PhaseKind(size_t(PhaseKind::GC_END) + 1));
}

const char* js::gcstats::ExplainInvocationKind(JSGCInvocationKind gckind) {
  MOZ_ASSERT(gckind == GC_NORMAL || gckind == GC_SHRINK);
  if (gckind == GC_NORMAL) {
    return "Normal";
  } else {
    return "Shrinking";
  }
}

JS_PUBLIC_API const char* JS::ExplainGCReason(JS::GCReason reason) {
  switch (reason) {
#define SWITCH_REASON(name, _) \
  case JS::GCReason::name:     \
    return #name;
    GCREASONS(SWITCH_REASON)
#undef SWITCH_REASON

    case JS::GCReason::NO_REASON:
      return "NO_REASON";

    default:
      MOZ_CRASH("bad GC reason");
  }
}

JS_PUBLIC_API bool JS::InternalGCReason(JS::GCReason reason) {
  return reason < JS::GCReason::FIRST_FIREFOX_REASON;
}

const char* js::gcstats::ExplainAbortReason(gc::AbortReason reason) {
  switch (reason) {
#define SWITCH_REASON(name, _) \
  case gc::AbortReason::name:  \
    return #name;
    GC_ABORT_REASONS(SWITCH_REASON)

    default:
      MOZ_CRASH("bad GC abort reason");
#undef SWITCH_REASON
  }
}

static FILE* MaybeOpenFileFromEnv(const char* env) {
  FILE* file;
  const char* value = getenv(env);

  if (!value) {
    return nullptr;
  }

  if (strcmp(value, "none") == 0) {
    file = nullptr;
  } else if (strcmp(value, "stdout") == 0) {
    file = stdout;
  } else if (strcmp(value, "stderr") == 0) {
    file = stderr;
  } else {
    char path[300];
    if (value[0] != '/') {
      const char* dir = getenv("MOZ_UPLOAD_DIR");
      if (dir) {
        SprintfLiteral(path, "%s/%s", dir, value);
        value = path;
      }
    }

    file = fopen(value, "a");
    if (!file) {
      perror("opening log file");
      MOZ_CRASH("Failed to open log file.");
    }
  }

  return file;
}

struct PhaseKindInfo {
  Phase firstPhase;
  uint8_t telemetryBucket;
};

// PhaseInfo objects form a tree.
struct PhaseInfo {
  Phase parent;
  Phase firstChild;
  Phase nextSibling;
  Phase nextWithPhaseKind;
  PhaseKind phaseKind;
  uint8_t depth;
  const char* name;
  const char* path;
};

// A table of PhaseInfo indexed by Phase.
using PhaseTable = EnumeratedArray<Phase, Phase::LIMIT, PhaseInfo>;

// A table of PhaseKindInfo indexed by PhaseKind.
using PhaseKindTable =
    EnumeratedArray<PhaseKind, PhaseKind::LIMIT, PhaseKindInfo>;

#include "gc/StatsPhasesGenerated.inc"

// Iterate the phases in a phase kind.
class PhaseIter {
  Phase phase;

 public:
  explicit PhaseIter(PhaseKind kind) : phase(phaseKinds[kind].firstPhase) {}
  bool done() const { return phase == Phase::NONE; }
  void next() { phase = phases[phase].nextWithPhaseKind; }
  Phase get() const { return phase; }
  operator Phase() const { return phase; }
};

static double t(TimeDuration duration) { return duration.ToMilliseconds(); }

inline JSContext* Statistics::context() {
  return gc->rt->mainContextFromOwnThread();
}

inline Phase Statistics::currentPhase() const {
  return phaseStack.empty() ? Phase::NONE : phaseStack.back();
}

PhaseKind Statistics::currentPhaseKind() const {
  // Public API to get the current phase kind, suppressing the synthetic
  // PhaseKind::MUTATOR phase.

  Phase phase = currentPhase();
  MOZ_ASSERT_IF(phase == Phase::MUTATOR, phaseStack.length() == 1);
  if (phase == Phase::NONE || phase == Phase::MUTATOR) {
    return PhaseKind::NONE;
  }

  return phases[phase].phaseKind;
}

static Phase LookupPhaseWithParent(PhaseKind phaseKind, Phase parentPhase) {
  for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
    if (phases[phase].parent == parentPhase) {
      return phase;
    }
  }

  return Phase::NONE;
}

Phase Statistics::lookupChildPhase(PhaseKind phaseKind) const {
  if (phaseKind == PhaseKind::IMPLICIT_SUSPENSION) {
    return Phase::IMPLICIT_SUSPENSION;
  }
  if (phaseKind == PhaseKind::EXPLICIT_SUSPENSION) {
    return Phase::EXPLICIT_SUSPENSION;
  }

  MOZ_ASSERT(phaseKind < PhaseKind::LIMIT);

  // Search all expanded phases that correspond to the required
  // phase to find the one whose parent is the current expanded phase.
  Phase phase = LookupPhaseWithParent(phaseKind, currentPhase());

  if (phase == Phase::NONE) {
    MOZ_CRASH_UNSAFE_PRINTF(
        "Child phase kind %u not found under current phase kind %u",
        unsigned(phaseKind), unsigned(currentPhaseKind()));
  }

  return phase;
}

inline auto AllPhases() {
  return mozilla::MakeEnumeratedRange(Phase::FIRST, Phase::LIMIT);
}

void Statistics::gcDuration(TimeDuration* total, TimeDuration* maxPause) const {
  *total = *maxPause = 0;
  for (auto& slice : slices_) {
    *total += slice.duration();
    if (slice.duration() > *maxPause) {
      *maxPause = slice.duration();
    }
  }
  if (*maxPause > maxPauseInInterval) {
    maxPauseInInterval = *maxPause;
  }
}

void Statistics::sccDurations(TimeDuration* total,
                              TimeDuration* maxPause) const {
  *total = *maxPause = 0;
  for (size_t i = 0; i < sccTimes.length(); i++) {
    *total += sccTimes[i];
    *maxPause = std::max(*maxPause, sccTimes[i]);
  }
}

typedef Vector<UniqueChars, 8, SystemAllocPolicy> FragmentVector;

static UniqueChars Join(const FragmentVector& fragments,
                        const char* separator = "") {
  const size_t separatorLength = strlen(separator);
  size_t length = 0;
  for (size_t i = 0; i < fragments.length(); ++i) {
    length += fragments[i] ? strlen(fragments[i].get()) : 0;
    if (i < (fragments.length() - 1)) {
      length += separatorLength;
    }
  }

  char* joined = js_pod_malloc<char>(length + 1);
  if (!joined) {
    return UniqueChars();
  }

  joined[length] = '\0';
  char* cursor = joined;
  for (size_t i = 0; i < fragments.length(); ++i) {
    if (fragments[i]) {
      strcpy(cursor, fragments[i].get());
    }
    cursor += fragments[i] ? strlen(fragments[i].get()) : 0;
    if (i < (fragments.length() - 1)) {
      if (separatorLength) {
        strcpy(cursor, separator);
      }
      cursor += separatorLength;
    }
  }

  return UniqueChars(joined);
}

static TimeDuration SumChildTimes(
    Phase phase, const Statistics::PhaseTimeTable& phaseTimes) {
  TimeDuration total = 0;
  for (phase = phases[phase].firstChild; phase != Phase::NONE;
       phase = phases[phase].nextSibling) {
    total += phaseTimes[phase];
  }
  return total;
}

UniqueChars Statistics::formatCompactSliceMessage() const {
  // Skip if we OOM'ed.
  if (slices_.length() == 0) {
    return UniqueChars(nullptr);
  }

  const size_t index = slices_.length() - 1;
  const SliceData& slice = slices_.back();

  char budgetDescription[200];
  slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);

  const char* format =
      "GC Slice %u - Pause: %.3fms of %s budget (@ %.3fms); Reason: %s; Reset: "
      "%s%s; Times: ";
  char buffer[1024];
  SprintfLiteral(buffer, format, index, t(slice.duration()), budgetDescription,
                 t(slice.start - slices_[0].start),
                 ExplainGCReason(slice.reason),
                 slice.wasReset() ? "yes - " : "no",
                 slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "");

  FragmentVector fragments;
  if (!fragments.append(DuplicateString(buffer)) ||
      !fragments.append(
          formatCompactSlicePhaseTimes(slices_[index].phaseTimes))) {
    return UniqueChars(nullptr);
  }
  return Join(fragments);
}

UniqueChars Statistics::formatCompactSummaryMessage() const {
  FragmentVector fragments;
  if (!fragments.append(DuplicateString("Summary - "))) {
    return UniqueChars(nullptr);
  }

  TimeDuration total, longest;
  gcDuration(&total, &longest);

  const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
  const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));

  char buffer[1024];
  if (!nonincremental()) {
    SprintfLiteral(buffer,
                   "Max Pause: %.3fms; MMU 20ms: %.1f%%; MMU 50ms: %.1f%%; "
                   "Total: %.3fms; ",
                   t(longest), mmu20 * 100., mmu50 * 100., t(total));
  } else {
    SprintfLiteral(buffer, "Non-Incremental: %.3fms (%s); ", t(total),
                   ExplainAbortReason(nonincrementalReason_));
  }
  if (!fragments.append(DuplicateString(buffer))) {
    return UniqueChars(nullptr);
  }

  SprintfLiteral(buffer,
                 "Zones: %d of %d (-%d); Compartments: %d of %d (-%d); "
                 "HeapSize: %.3f MiB; "
                 "HeapChange (abs): %+d (%u); ",
                 zoneStats.collectedZoneCount, zoneStats.zoneCount,
                 zoneStats.sweptZoneCount, zoneStats.collectedCompartmentCount,
                 zoneStats.compartmentCount, zoneStats.sweptCompartmentCount,
                 double(preTotalHeapBytes) / BYTES_PER_MB,
                 int32_t(counts[COUNT_NEW_CHUNK] - counts[COUNT_DESTROY_CHUNK]),
                 counts[COUNT_NEW_CHUNK] + counts[COUNT_DESTROY_CHUNK]);
  if (!fragments.append(DuplicateString(buffer))) {
    return UniqueChars(nullptr);
  }

  MOZ_ASSERT_IF(counts[COUNT_ARENA_RELOCATED], gckind == GC_SHRINK);
  if (gckind == GC_SHRINK) {
    SprintfLiteral(
        buffer, "Kind: %s; Relocated: %.3f MiB; ",
        ExplainInvocationKind(gckind),
        double(ArenaSize * counts[COUNT_ARENA_RELOCATED]) / BYTES_PER_MB);
    if (!fragments.append(DuplicateString(buffer))) {
      return UniqueChars(nullptr);
    }
  }

  return Join(fragments);
}

UniqueChars Statistics::formatCompactSlicePhaseTimes(
    const PhaseTimeTable& phaseTimes) const {
  static const TimeDuration MaxUnaccountedTime =
      TimeDuration::FromMicroseconds(100);

  FragmentVector fragments;
  char buffer[128];
  for (auto phase : AllPhases()) {
    DebugOnly<uint8_t> level = phases[phase].depth;
    MOZ_ASSERT(level < 4);

    TimeDuration ownTime = phaseTimes[phase];
    TimeDuration childTime = SumChildTimes(phase, phaseTimes);
    if (ownTime > MaxUnaccountedTime) {
      SprintfLiteral(buffer, "%s: %.3fms", phases[phase].name, t(ownTime));
      if (!fragments.append(DuplicateString(buffer))) {
        return UniqueChars(nullptr);
      }

      if (childTime && (ownTime - childTime) > MaxUnaccountedTime) {
        MOZ_ASSERT(level < 3);
        SprintfLiteral(buffer, "%s: %.3fms", "Other", t(ownTime - childTime));
        if (!fragments.append(DuplicateString(buffer))) {
          return UniqueChars(nullptr);
        }
      }
    }
  }
  return Join(fragments, ", ");
}

UniqueChars Statistics::formatDetailedMessage() const {
  FragmentVector fragments;

  if (!fragments.append(formatDetailedDescription())) {
    return UniqueChars(nullptr);
  }

  if (!slices_.empty()) {
    for (unsigned i = 0; i < slices_.length(); i++) {
      if (!fragments.append(formatDetailedSliceDescription(i, slices_[i]))) {
        return UniqueChars(nullptr);
      }
      if (!fragments.append(formatDetailedPhaseTimes(slices_[i].phaseTimes))) {
        return UniqueChars(nullptr);
      }
    }
  }
  if (!fragments.append(formatDetailedTotals())) {
    return UniqueChars(nullptr);
  }
  if (!fragments.append(formatDetailedPhaseTimes(phaseTimes))) {
    return UniqueChars(nullptr);
  }

  return Join(fragments);
}

UniqueChars Statistics::formatDetailedDescription() const {
  TimeDuration sccTotal, sccLongest;
  sccDurations(&sccTotal, &sccLongest);

  const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
  const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));

  const char* format =
      "=================================================================\n\
  Invocation Kind: %s\n\
  Reason: %s\n\
  Incremental: %s%s\n\
  Zones Collected: %d of %d (-%d)\n\
  Compartments Collected: %d of %d (-%d)\n\
  MinorGCs since last GC: %d\n\
  Store Buffer Overflows: %d\n\
  MMU 20ms:%.1f%%; 50ms:%.1f%%\n\
  SCC Sweep Total (MaxPause): %.3fms (%.3fms)\n\
  HeapSize: %.3f MiB\n\
  Chunk Delta (magnitude): %+d  (%d)\n\
  Arenas Relocated: %.3f MiB\n\
";

  char buffer[1024];
  SprintfLiteral(
      buffer, format, ExplainInvocationKind(gckind),
      ExplainGCReason(slices_[0].reason), nonincremental() ? "no - " : "yes",
      nonincremental() ? ExplainAbortReason(nonincrementalReason_) : "",
      zoneStats.collectedZoneCount, zoneStats.zoneCount,
      zoneStats.sweptZoneCount, zoneStats.collectedCompartmentCount,
      zoneStats.compartmentCount, zoneStats.sweptCompartmentCount,
      getCount(COUNT_MINOR_GC), getCount(COUNT_STOREBUFFER_OVERFLOW),
      mmu20 * 100., mmu50 * 100., t(sccTotal), t(sccLongest),
      double(preTotalHeapBytes) / BYTES_PER_MB,
      getCount(COUNT_NEW_CHUNK) - getCount(COUNT_DESTROY_CHUNK),
      getCount(COUNT_NEW_CHUNK) + getCount(COUNT_DESTROY_CHUNK),
      double(ArenaSize * getCount(COUNT_ARENA_RELOCATED)) / BYTES_PER_MB);

  return DuplicateString(buffer);
}

UniqueChars Statistics::formatDetailedSliceDescription(
    unsigned i, const SliceData& slice) const {
  char budgetDescription[200];
  slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);

  const char* format =
      "\
  ---- Slice %u ----\n\
    Reason: %s\n\
    Trigger: %s\n\
    Reset: %s%s\n\
    State: %s -> %s\n\
    Page Faults: %" PRIu64
      "\n\
    Pause: %.3fms of %s budget (@ %.3fms)\n\
";

  char triggerBuffer[100] = "n/a";
  if (slice.trigger) {
    Trigger trigger = slice.trigger.value();
    SprintfLiteral(triggerBuffer, "%.3f MiB of %.3f MiB threshold\n",
                   double(trigger.amount) / BYTES_PER_MB,
                   double(trigger.threshold) / BYTES_PER_MB);
  }

  char buffer[1024];
  SprintfLiteral(
      buffer, format, i, ExplainGCReason(slice.reason), triggerBuffer,
      slice.wasReset() ? "yes - " : "no",
      slice.wasReset() ? ExplainAbortReason(slice.resetReason) : "",
      gc::StateName(slice.initialState), gc::StateName(slice.finalState),
      uint64_t(slice.endFaults - slice.startFaults), t(slice.duration()),
      budgetDescription, t(slice.start - slices_[0].start));
  return DuplicateString(buffer);
}

static bool IncludePhase(TimeDuration duration) {
  // Don't include durations that will print as "0.000ms".
  return duration.ToMilliseconds() >= 0.001;
}

UniqueChars Statistics::formatDetailedPhaseTimes(
    const PhaseTimeTable& phaseTimes) const {
  static const TimeDuration MaxUnaccountedChildTime =
      TimeDuration::FromMicroseconds(50);

  FragmentVector fragments;
  char buffer[128];
  for (auto phase : AllPhases()) {
    uint8_t level = phases[phase].depth;
    TimeDuration ownTime = phaseTimes[phase];
    TimeDuration childTime = SumChildTimes(phase, phaseTimes);
    if (IncludePhase(ownTime)) {
      SprintfLiteral(buffer, "      %*s%s: %.3fms\n", level * 2, "",
                     phases[phase].name, t(ownTime));
      if (!fragments.append(DuplicateString(buffer))) {
        return UniqueChars(nullptr);
      }

      if (childTime && (ownTime - childTime) > MaxUnaccountedChildTime) {
        SprintfLiteral(buffer, "      %*s%s: %.3fms\n", (level + 1) * 2, "",
                       "Other", t(ownTime - childTime));
        if (!fragments.append(DuplicateString(buffer))) {
          return UniqueChars(nullptr);
        }
      }
    }
  }
  return Join(fragments);
}

UniqueChars Statistics::formatDetailedTotals() const {
  TimeDuration total, longest;
  gcDuration(&total, &longest);

  const char* format =
      "\
  ---- Totals ----\n\
    Total Time: %.3fms\n\
    Max Pause: %.3fms\n\
";
  char buffer[1024];
  SprintfLiteral(buffer, format, t(total), t(longest));
  return DuplicateString(buffer);
}

void Statistics::formatJsonSlice(size_t sliceNum, JSONPrinter& json) const {
  /*
   * We number each of the slice properties to keep the code in
   * GCTelemetry.jsm in sync.  See MAX_SLICE_KEYS.
   */
  json.beginObject();
  formatJsonSliceDescription(sliceNum, slices_[sliceNum], json);  // # 1-11

  json.beginObjectProperty("times");  // # 12
  formatJsonPhaseTimes(slices_[sliceNum].phaseTimes, json);
  json.endObject();

  json.endObject();
}

UniqueChars Statistics::renderJsonSlice(size_t sliceNum) const {
  Sprinter printer(nullptr, false);
  if (!printer.init()) {
    return UniqueChars(nullptr);
  }
  JSONPrinter json(printer);

  formatJsonSlice(sliceNum, json);
  return printer.release();
}

UniqueChars Statistics::renderNurseryJson() const {
  Sprinter printer(nullptr, false);
  if (!printer.init()) {
    return UniqueChars(nullptr);
  }
  JSONPrinter json(printer);
  gc->nursery().renderProfileJSON(json);
  return printer.release();
}

#ifdef DEBUG
void Statistics::writeLogMessage(const char* fmt, ...) {
  va_list args;
  va_start(args, fmt);
  if (gcDebugFile) {
    TimeDuration sinceStart = TimeStamp::Now() - TimeStamp::ProcessCreation();
    fprintf(gcDebugFile, "%12.3f: ", sinceStart.ToMicroseconds());
    vfprintf(gcDebugFile, fmt, args);
    fprintf(gcDebugFile, "\n");
    fflush(gcDebugFile);
  }
  va_end(args);
}
#endif

UniqueChars Statistics::renderJsonMessage(uint64_t timestamp,
                                          Statistics::JSONUse use) const {
  /*
   * The format of the JSON message is specified by the GCMajorMarkerPayload
   * type in profiler.firefox.com
   * https://github.com/firefox-devtools/profiler/blob/master/src/types/markers.js#L62
   *
   * All the properties listed here are created within the timings property
   * of the GCMajor marker.
   */
  if (aborted) {
    return DuplicateString("{status:\"aborted\"}");  // May return nullptr
  }

  Sprinter printer(nullptr, false);
  if (!printer.init()) {
    return UniqueChars(nullptr);
  }
  JSONPrinter json(printer);

  json.beginObject();
  json.property("status", "completed");         // JSON Key #1
  formatJsonDescription(timestamp, json, use);  // #2-22

  if (use == Statistics::JSONUse::TELEMETRY) {
    json.beginListProperty("slices_list");  // #23
    for (unsigned i = 0; i < slices_.length(); i++) {
      formatJsonSlice(i, json);
    }
    json.endList();
  }

  json.beginObjectProperty("totals");  // #24
  formatJsonPhaseTimes(phaseTimes, json);
  json.endObject();

  json.endObject();

  return printer.release();
}

void Statistics::formatJsonDescription(uint64_t timestamp, JSONPrinter& json,
                                       JSONUse use) const {
  // If you change JSON properties here, please update:
  // Telemetry ping code:
  //   toolkit/components/telemetry/other/GCTelemetry.jsm
  // Telemetry documentation:
  //   toolkit/components/telemetry/docs/data/main-ping.rst
  // Telemetry tests:
  //   toolkit/components/telemetry/tests/browser/browser_TelemetryGC.js,
  //   toolkit/components/telemetry/tests/unit/test_TelemetryGC.js
  // Firefox Profiler:
  //   https://github.com/firefox-devtools/profiler
  //
  // Please also number each property to help correctly maintain the Telemetry
  // ping code

  json.property("timestamp", timestamp);  // # JSON Key #2

  TimeDuration total, longest;
  gcDuration(&total, &longest);
  json.property("max_pause", longest, JSONPrinter::MILLISECONDS);  // #3
  json.property("total_time", total, JSONPrinter::MILLISECONDS);   // #4
  // We might be able to omit reason if profiler.firefox.com was able to retrive
  // it from the first slice.  But it doesn't do this yet.
  json.property("reason", ExplainGCReason(slices_[0].reason));      // #5
  json.property("zones_collected", zoneStats.collectedZoneCount);   // #6
  json.property("total_zones", zoneStats.zoneCount);                // #7
  json.property("total_compartments", zoneStats.compartmentCount);  // #8
  json.property("minor_gcs", getCount(COUNT_MINOR_GC));             // #9
  uint32_t storebufferOverflows = getCount(COUNT_STOREBUFFER_OVERFLOW);
  if (storebufferOverflows) {
    json.property("store_buffer_overflows", storebufferOverflows);  // #10
  }
  json.property("slices", slices_.length());  // #11

  const double mmu20 = computeMMU(TimeDuration::FromMilliseconds(20));
  const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
  json.property("mmu_20ms", int(mmu20 * 100));  // #12
  json.property("mmu_50ms", int(mmu50 * 100));  // #13

  TimeDuration sccTotal, sccLongest;
  sccDurations(&sccTotal, &sccLongest);
  json.property("scc_sweep_total", sccTotal, JSONPrinter::MILLISECONDS);  // #14
  json.property("scc_sweep_max_pause", sccLongest,
                JSONPrinter::MILLISECONDS);  // #15

  if (nonincrementalReason_ != AbortReason::None) {
    json.property("nonincremental_reason",
                  ExplainAbortReason(nonincrementalReason_));  // #16
  }
  json.property("allocated_bytes", preTotalHeapBytes);  // #17
  if (use == Statistics::JSONUse::PROFILER) {
    json.property("post_heap_size", postTotalHeapBytes);
  }

  uint32_t addedChunks = getCount(COUNT_NEW_CHUNK);
  if (addedChunks) {
    json.property("added_chunks", addedChunks);  // #18
  }
  uint32_t removedChunks = getCount(COUNT_DESTROY_CHUNK);
  if (removedChunks) {
    json.property("removed_chunks", removedChunks);  // #19
  }
  json.property("major_gc_number", startingMajorGCNumber);  // #20
  json.property("minor_gc_number", startingMinorGCNumber);  // #21
  json.property("slice_number", startingSliceNumber);       // #22
}

void Statistics::formatJsonSliceDescription(unsigned i, const SliceData& slice,
                                            JSONPrinter& json) const {
  // If you change JSON properties here, please update:
  // Telemetry ping code:
  //   toolkit/components/telemetry/other/GCTelemetry.jsm
  // Telemetry documentation:
  //   toolkit/components/telemetry/docs/data/main-ping.rst
  // Telemetry tests:
  //   toolkit/components/telemetry/tests/browser/browser_TelemetryGC.js,
  //   toolkit/components/telemetry/tests/unit/test_TelemetryGC.js
  // Firefox Profiler:
  //   https://github.com/firefox-devtools/profiler
  //
  char budgetDescription[200];
  slice.budget.describe(budgetDescription, sizeof(budgetDescription) - 1);
  TimeStamp originTime = TimeStamp::ProcessCreation();

  json.property("slice", i);  // JSON Property #1
  json.property("pause", slice.duration(), JSONPrinter::MILLISECONDS);  // #2
  json.property("reason", ExplainGCReason(slice.reason));               // #3
  json.property("initial_state", gc::StateName(slice.initialState));    // #4
  json.property("final_state", gc::StateName(slice.finalState));        // #5
  json.property("budget", budgetDescription);                           // #6
  json.property("major_gc_number", startingMajorGCNumber);              // #7
  if (slice.trigger) {
    Trigger trigger = slice.trigger.value();
    json.property("trigger_amount", trigger.amount);        // #8
    json.property("trigger_threshold", trigger.threshold);  // #9
  }
  int64_t numFaults = slice.endFaults - slice.startFaults;
  if (numFaults != 0) {
    json.property("page_faults", numFaults);  // #10
  }
  json.property("start_timestamp", slice.start - originTime,
                JSONPrinter::SECONDS);  // #11
}

void Statistics::formatJsonPhaseTimes(const PhaseTimeTable& phaseTimes,
                                      JSONPrinter& json) const {
  for (auto phase : AllPhases()) {
    TimeDuration ownTime = phaseTimes[phase];
    if (!ownTime.IsZero()) {
      json.property(phases[phase].path, ownTime, JSONPrinter::MILLISECONDS);
    }
  }
}

Statistics::Statistics(GCRuntime* gc)
    : gc(gc),
      gcTimerFile(nullptr),
      gcDebugFile(nullptr),
      nonincrementalReason_(gc::AbortReason::None),
      allocsSinceMinorGC({0, 0}),
      preTotalHeapBytes(0),
      postTotalHeapBytes(0),
      preCollectedHeapBytes(0),
      startingMinorGCNumber(0),
      startingMajorGCNumber(0),
      startingSliceNumber(0),
      maxPauseInInterval(0),
      sliceCallback(nullptr),
      nurseryCollectionCallback(nullptr),
      aborted(false),
      enableProfiling_(false),
      sliceCount_(0) {
  for (auto& count : counts) {
    count = 0;
  }

  for (auto& stat : stats) {
    stat = 0;
  }

#ifdef DEBUG
  for (const auto& duration : totalTimes_) {
    using ElementType = std::remove_reference_t<decltype(duration)>;
    static_assert(!std::is_trivially_constructible_v<ElementType>,
                  "Statistics::Statistics will only initialize "
                  "totalTimes_'s elements if their default constructor is "
                  "non-trivial");
    MOZ_ASSERT(duration.IsZero(),
               "totalTimes_ default-initialization should have "
               "default-initialized every element of totalTimes_ to zero");
  }
#endif

  MOZ_ALWAYS_TRUE(phaseStack.reserve(MAX_PHASE_NESTING));
  MOZ_ALWAYS_TRUE(suspendedPhases.reserve(MAX_SUSPENDED_PHASES));

  gcTimerFile = MaybeOpenFileFromEnv("MOZ_GCTIMER");
  gcDebugFile = MaybeOpenFileFromEnv("JS_GC_DEBUG");

  const char* env = getenv("JS_GC_PROFILE");
  if (env) {
    if (0 == strcmp(env, "help")) {
      fprintf(stderr,
              "JS_GC_PROFILE=N\n"
              "\tReport major GC's taking more than N milliseconds.\n");
      exit(0);
    }
    enableProfiling_ = true;
    profileThreshold_ = TimeDuration::FromMilliseconds(atoi(env));
  }
}

Statistics::~Statistics() {
  if (gcTimerFile && gcTimerFile != stdout && gcTimerFile != stderr) {
    fclose(gcTimerFile);
  }
  if (gcDebugFile && gcDebugFile != stdout && gcDebugFile != stderr) {
    fclose(gcDebugFile);
  }
}

/* static */
bool Statistics::initialize() {
#ifdef DEBUG
  // Sanity check generated tables.
  for (auto i : AllPhases()) {
    auto parent = phases[i].parent;
    if (parent != Phase::NONE) {
      MOZ_ASSERT(phases[i].depth == phases[parent].depth + 1);
    }
    auto firstChild = phases[i].firstChild;
    if (firstChild != Phase::NONE) {
      MOZ_ASSERT(i == phases[firstChild].parent);
      MOZ_ASSERT(phases[i].depth == phases[firstChild].depth - 1);
    }
    auto nextSibling = phases[i].nextSibling;
    if (nextSibling != Phase::NONE) {
      MOZ_ASSERT(parent == phases[nextSibling].parent);
      MOZ_ASSERT(phases[i].depth == phases[nextSibling].depth);
    }
    auto nextWithPhaseKind = phases[i].nextWithPhaseKind;
    if (nextWithPhaseKind != Phase::NONE) {
      MOZ_ASSERT(phases[i].phaseKind == phases[nextWithPhaseKind].phaseKind);
      MOZ_ASSERT(parent != phases[nextWithPhaseKind].parent);
    }
  }
  for (auto i : AllPhaseKinds()) {
    MOZ_ASSERT(phases[phaseKinds[i].firstPhase].phaseKind == i);
    for (auto j : AllPhaseKinds()) {
      MOZ_ASSERT_IF(i != j, phaseKinds[i].telemetryBucket !=
                                phaseKinds[j].telemetryBucket);
    }
  }
#endif

  return true;
}

JS::GCSliceCallback Statistics::setSliceCallback(
    JS::GCSliceCallback newCallback) {
  JS::GCSliceCallback oldCallback = sliceCallback;
  sliceCallback = newCallback;
  return oldCallback;
}

JS::GCNurseryCollectionCallback Statistics::setNurseryCollectionCallback(
    JS::GCNurseryCollectionCallback newCallback) {
  auto oldCallback = nurseryCollectionCallback;
  nurseryCollectionCallback = newCallback;
  return oldCallback;
}

TimeDuration Statistics::clearMaxGCPauseAccumulator() {
  TimeDuration prior = maxPauseInInterval;
  maxPauseInInterval = 0;
  return prior;
}

TimeDuration Statistics::getMaxGCPauseSinceClear() {
  return maxPauseInInterval;
}

// Sum up the time for a phase, including instances of the phase with different
// parents.
static TimeDuration SumPhase(PhaseKind phaseKind,
                             const Statistics::PhaseTimeTable& times) {
  TimeDuration sum;
  for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
    sum += times[phase];
  }
  return sum;
}

static bool CheckSelfTime(Phase parent, Phase child,
                          const Statistics::PhaseTimeTable& times,
                          const Statistics::PhaseTimeTable& selfTimes,
                          TimeDuration childTime) {
  if (selfTimes[parent] < childTime) {
    fprintf(
        stderr,
        "Parent %s time = %.3fms with %.3fms remaining, child %s time %.3fms\n",
        phases[parent].name, times[parent].ToMilliseconds(),
        selfTimes[parent].ToMilliseconds(), phases[child].name,
        childTime.ToMilliseconds());
    fflush(stderr);
    return false;
  }

  return true;
}

using PhaseKindTimes =
    EnumeratedArray<PhaseKind, PhaseKind::LIMIT, TimeDuration>;

static PhaseKind FindLongestPhaseKind(const PhaseKindTimes& times) {
  TimeDuration longestTime;
  PhaseKind phaseKind = PhaseKind::NONE;
  for (auto i : MajorGCPhaseKinds()) {
    if (times[i] > longestTime) {
      longestTime = times[i];
      phaseKind = i;
    }
  }

  return phaseKind;
}

static PhaseKind LongestPhaseSelfTimeInMajorGC(
    const Statistics::PhaseTimeTable& times) {
  // Start with total times per expanded phase, including children's times.
  Statistics::PhaseTimeTable selfTimes(times);

  // We have the total time spent in each phase, including descendant times.
  // Loop over the children and subtract their times from their parent's self
  // time.
  for (auto i : AllPhases()) {
    Phase parent = phases[i].parent;
    if (parent != Phase::NONE) {
      bool ok = CheckSelfTime(parent, i, times, selfTimes, times[i]);

      // This happens very occasionally in release builds and frequently
      // in Windows debug builds. Skip collecting longest phase telemetry
      // if it does.
#ifndef XP_WIN
      MOZ_ASSERT(ok, "Inconsistent time data; see bug 1400153");
#endif
      if (!ok) {
        return PhaseKind::NONE;
      }

      selfTimes[parent] -= times[i];
    }
  }

  // Sum expanded phases corresponding to the same phase.
  PhaseKindTimes phaseKindTimes;
  for (auto i : AllPhaseKinds()) {
    phaseKindTimes[i] = SumPhase(i, selfTimes);
  }

  return FindLongestPhaseKind(phaseKindTimes);
}

static TimeDuration PhaseMax(PhaseKind phaseKind,
                             const Statistics::PhaseTimeTable& times) {
  TimeDuration max;
  for (PhaseIter phase(phaseKind); !phase.done(); phase.next()) {
    max = std::max(max, times[phase]);
  }

  return max;
}

static PhaseKind LongestParallelPhaseKind(
    const Statistics::PhaseTimeTable& times) {
  // Find longest time for each phase kind.
  PhaseKindTimes phaseKindTimes;
  for (auto i : AllPhaseKinds()) {
    phaseKindTimes[i] = PhaseMax(i, times);
  }

  return FindLongestPhaseKind(phaseKindTimes);
}

void Statistics::printStats() {
  if (aborted) {
    fprintf(gcTimerFile,
            "OOM during GC statistics collection. The report is unavailable "
            "for this GC.\n");
  } else {
    UniqueChars msg = formatDetailedMessage();
    if (msg) {
      double secSinceStart =
          (slices_[0].start - TimeStamp::ProcessCreation()).ToSeconds();
      fprintf(gcTimerFile, "GC(T+%.3fs) %s\n", secSinceStart, msg.get());
    }
  }
  fflush(gcTimerFile);
}

void Statistics::beginGC(JSGCInvocationKind kind,
                         const TimeStamp& currentTime) {
  slices_.clearAndFree();
  sccTimes.clearAndFree();
  gckind = kind;
  nonincrementalReason_ = gc::AbortReason::None;

  preTotalHeapBytes = gc->heapSize.bytes();

  preCollectedHeapBytes = 0;

  startingMajorGCNumber = gc->majorGCCount();
  startingSliceNumber = gc->gcNumber();

  if (gc->lastGCEndTime()) {
    timeSinceLastGC = currentTime - gc->lastGCEndTime();
  }
}

void Statistics::measureInitialHeapSize() {
  MOZ_ASSERT(preCollectedHeapBytes == 0);
  for (GCZonesIter zone(gc, WithAtoms); !zone.done(); zone.next()) {
    preCollectedHeapBytes += zone->gcHeapSize.bytes();
  }
}

void Statistics::adoptHeapSizeDuringIncrementalGC(Zone* mergedZone) {
  // A zone is being merged into a zone that's currently being collected so we
  // need to adjust our record of the total size of heap for collected zones.
  MOZ_ASSERT(gc->isIncrementalGCInProgress());
  preCollectedHeapBytes += mergedZone->gcHeapSize.bytes();
}

void Statistics::endGC() {
  postTotalHeapBytes = gc->heapSize.bytes();

  sendGCTelemetry();
}

void Statistics::sendGCTelemetry() {
  JSRuntime* runtime = gc->rt;
  runtime->addTelemetry(JS_TELEMETRY_GC_IS_ZONE_GC,
                        !zoneStats.isFullCollection());
  TimeDuration prepareTotal = SumPhase(PhaseKind::PREPARE, phaseTimes);
  TimeDuration markTotal = SumPhase(PhaseKind::MARK, phaseTimes);
  TimeDuration markRootsTotal = SumPhase(PhaseKind::MARK_ROOTS, phaseTimes);
  TimeDuration markWeakTotal = phaseTimes[Phase::SWEEP_MARK_WEAK] +
                               phaseTimes[Phase::SWEEP_MARK_GRAY_WEAK];
  TimeDuration markGrayTotal = phaseTimes[Phase::SWEEP_MARK_GRAY] +
                               phaseTimes[Phase::SWEEP_MARK_GRAY_WEAK];
  size_t markCount = gc->marker.getMarkCount();
  double markRate = markCount / t(markTotal);
  runtime->addTelemetry(JS_TELEMETRY_GC_PREPARE_MS, t(prepareTotal));
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_MS, t(markTotal));
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_RATE, markRate);
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_RATE_2, markRate);
  runtime->addTelemetry(JS_TELEMETRY_GC_SWEEP_MS, t(phaseTimes[Phase::SWEEP]));
  if (gc->didCompactZones()) {
    runtime->addTelemetry(JS_TELEMETRY_GC_COMPACT_MS,
                          t(phaseTimes[Phase::COMPACT]));
  }
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_ROOTS_MS, t(markRootsTotal));
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_ROOTS_US,
                        markRootsTotal.ToMicroseconds());
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_GRAY_MS, t(markGrayTotal));
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_GRAY_MS_2, t(markGrayTotal));
  runtime->addTelemetry(JS_TELEMETRY_GC_MARK_WEAK_MS, t(markWeakTotal));
  runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL, nonincremental());
  if (nonincremental()) {
    runtime->addTelemetry(JS_TELEMETRY_GC_NON_INCREMENTAL_REASON,
                          uint32_t(nonincrementalReason_));
  }

#ifdef DEBUG
  // Reset happens non-incrementally, so only the last slice can be reset.
  for (size_t i = 0; i < slices_.length() - 1; i++) {
    MOZ_ASSERT(!slices_[i].wasReset());
  }
#endif
  const auto& lastSlice = slices_.back();
  runtime->addTelemetry(JS_TELEMETRY_GC_RESET, lastSlice.wasReset());
  if (lastSlice.wasReset()) {
    runtime->addTelemetry(JS_TELEMETRY_GC_RESET_REASON,
                          uint32_t(lastSlice.resetReason));
  }

  TimeDuration total, longest;
  gcDuration(&total, &longest);

  runtime->addTelemetry(JS_TELEMETRY_GC_MS, t(total));
  runtime->addTelemetry(JS_TELEMETRY_GC_MAX_PAUSE_MS_2, t(longest));

  const double mmu50 = computeMMU(TimeDuration::FromMilliseconds(50));
  runtime->addTelemetry(JS_TELEMETRY_GC_MMU_50, mmu50 * 100);

  // Record scheduling telemetry for the main runtime but not for workers, which
  // are scheduled differently.
  if (!runtime->parentRuntime && timeSinceLastGC) {
    runtime->addTelemetry(JS_TELEMETRY_GC_TIME_BETWEEN_S,
                          timeSinceLastGC.ToSeconds());
    if (!nonincremental()) {
      runtime->addTelemetry(JS_TELEMETRY_GC_SLICE_COUNT, slices_.length());
    }
  }

  size_t bytesSurvived = 0;
  for (ZonesIter zone(runtime, WithAtoms); !zone.done(); zone.next()) {
    if (zone->wasCollected()) {
      bytesSurvived += zone->gcHeapSize.retainedBytes();
    }
  }

  MOZ_ASSERT(preCollectedHeapBytes >= bytesSurvived);
  double survialRate =
      100.0 * double(bytesSurvived) / double(preCollectedHeapBytes);
  runtime->addTelemetry(JS_TELEMETRY_GC_TENURED_SURVIVAL_RATE,
                        uint32_t(survialRate));

  // Calculate 'effectiveness' in MB / second, on main thread only for now.
  if (!runtime->parentRuntime) {
    size_t bytesFreed = preCollectedHeapBytes - bytesSurvived;
    TimeDuration clampedTotal =
        TimeDuration::Max(total, TimeDuration::FromMilliseconds(1));
    double effectiveness =
        (double(bytesFreed) / BYTES_PER_MB) / clampedTotal.ToSeconds();
    runtime->addTelemetry(JS_TELEMETRY_GC_EFFECTIVENESS,
                          uint32_t(effectiveness));
  }
}

void Statistics::beginNurseryCollection(JS::GCReason reason) {
  count(COUNT_MINOR_GC);
  startingMinorGCNumber = gc->minorGCCount();
  if (nurseryCollectionCallback) {
    (*nurseryCollectionCallback)(
        context(), JS::GCNurseryProgress::GC_NURSERY_COLLECTION_START, reason);
  }
}

void Statistics::endNurseryCollection(JS::GCReason reason) {
  if (nurseryCollectionCallback) {
    (*nurseryCollectionCallback)(
        context(), JS::GCNurseryProgress::GC_NURSERY_COLLECTION_END, reason);
  }

  allocsSinceMinorGC = {0, 0};
}

Statistics::SliceData::SliceData(SliceBudget budget, Maybe<Trigger> trigger,
                                 JS::GCReason reason, TimeStamp start,
                                 size_t startFaults, gc::State initialState)
    : budget(budget),
      reason(reason),
      trigger(trigger),
      initialState(initialState),
      start(start),
      startFaults(startFaults) {}

void Statistics::beginSlice(const ZoneGCStats& zoneStats,
                            JSGCInvocationKind gckind, SliceBudget budget,
                            JS::GCReason reason) {
  MOZ_ASSERT(phaseStack.empty() ||
             (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));

  this->zoneStats = zoneStats;

  TimeStamp currentTime = ReallyNow();

  bool first = !gc->isIncrementalGCInProgress();
  if (first) {
    beginGC(gckind, currentTime);
  }

  JSRuntime* runtime = gc->rt;
  if (!runtime->parentRuntime && !slices_.empty()) {
    TimeDuration timeSinceLastSlice = currentTime - slices_.back().end;
    runtime->addTelemetry(JS_TELEMETRY_GC_TIME_BETWEEN_SLICES_MS,
                          uint32_t(timeSinceLastSlice.ToMilliseconds()));
  }

  Maybe<Trigger> trigger = recordedTrigger;
  recordedTrigger.reset();

  if (!slices_.emplaceBack(budget, trigger, reason, currentTime,
                           GetPageFaultCount(), gc->state())) {
    // If we are OOM, set a flag to indicate we have missing slice data.
    aborted = true;
    return;
  }

  runtime->addTelemetry(JS_TELEMETRY_GC_REASON, uint32_t(reason));

  // Slice callbacks should only fire for the outermost level.
  bool wasFullGC = zoneStats.isFullCollection();
  if (sliceCallback) {
    JSContext* cx = context();
    JS::GCDescription desc(!wasFullGC, false, gckind, reason);
    if (first) {
      (*sliceCallback)(cx, JS::GC_CYCLE_BEGIN, desc);
    }
    (*sliceCallback)(cx, JS::GC_SLICE_BEGIN, desc);
  }

  writeLogMessage("begin slice");
}

void Statistics::endSlice() {
  MOZ_ASSERT(phaseStack.empty() ||
             (phaseStack.length() == 1 && phaseStack[0] == Phase::MUTATOR));

  if (!aborted) {
    auto& slice = slices_.back();
    slice.end = ReallyNow();
    slice.endFaults = GetPageFaultCount();
    slice.finalState = gc->state();

    writeLogMessage("end slice");

    sendSliceTelemetry(slice);

    sliceCount_++;
  }

  bool last = !gc->isIncrementalGCInProgress();
  if (last) {
    if (gcTimerFile) {
      printStats();
    }

    if (!aborted) {
      endGC();
    }
  }

  if (enableProfiling_ && !aborted &&
      slices_.back().duration() >= profileThreshold_) {
    printSliceProfile();
  }

  // Slice callbacks should only fire for the outermost level.
  if (!aborted) {
    bool wasFullGC = zoneStats.isFullCollection();
    if (sliceCallback) {
      JSContext* cx = context();
      JS::GCDescription desc(!wasFullGC, last, gckind, slices_.back().reason);
      (*sliceCallback)(cx, JS::GC_SLICE_END, desc);
      if (last) {
        (*sliceCallback)(cx, JS::GC_CYCLE_END, desc);
      }
    }
  }

  // Do this after the slice callback since it uses these values.
  if (last) {
    for (auto& count : counts) {
      count = 0;
    }

    // Clear the timers at the end of a GC, preserving the data for
    // PhaseKind::MUTATOR.
    auto mutatorStartTime = phaseStartTimes[Phase::MUTATOR];
    auto mutatorTime = phaseTimes[Phase::MUTATOR];

    for (mozilla::TimeStamp& t : phaseStartTimes) {
      t = TimeStamp();
    }
#ifdef DEBUG
    for (mozilla::TimeStamp& t : phaseEndTimes) {
      t = TimeStamp();
    }
#endif

    for (TimeDuration& duration : phaseTimes) {
      duration = TimeDuration();
      MOZ_ASSERT(duration.IsZero());
    }

    phaseStartTimes[Phase::MUTATOR] = mutatorStartTime;
    phaseTimes[Phase::MUTATOR] = mutatorTime;
  }

  aborted = false;
}

void Statistics::sendSliceTelemetry(const SliceData& slice) {
  JSRuntime* runtime = gc->rt;
  TimeDuration sliceTime = slice.end - slice.start;
  runtime->addTelemetry(JS_TELEMETRY_GC_SLICE_MS, t(sliceTime));

  if (slice.budget.isTimeBudget()) {
    int64_t budget_ms = slice.budget.timeBudget.budget;
    runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_MS, budget_ms);
    runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_MS_2, budget_ms);
    if (IsCurrentlyAnimating(runtime->lastAnimationTime, slice.end)) {
      runtime->addTelemetry(JS_TELEMETRY_GC_ANIMATION_MS, t(sliceTime));
    }

    // Record any phase that goes 1.5 times or 5ms over its budget.
    double longSliceThreshold = std::min(1.5 * budget_ms, budget_ms + 5.0);
    if (sliceTime.ToMilliseconds() > longSliceThreshold) {
      PhaseKind longest = LongestPhaseSelfTimeInMajorGC(slice.phaseTimes);
      reportLongestPhaseInMajorGC(longest, JS_TELEMETRY_GC_SLOW_PHASE);

      // If the longest phase was waiting for parallel tasks then record the
      // longest task.
      if (longest == PhaseKind::JOIN_PARALLEL_TASKS) {
        PhaseKind longestParallel =
            LongestParallelPhaseKind(slice.maxParallelTimes);
        reportLongestPhaseInMajorGC(longestParallel, JS_TELEMETRY_GC_SLOW_TASK);
      }
    }

    // Record how long we went over budget.
    int64_t overrun = int64_t(sliceTime.ToMicroseconds()) - (1000 * budget_ms);
    if (overrun > 0) {
      runtime->addTelemetry(JS_TELEMETRY_GC_BUDGET_OVERRUN, uint32_t(overrun));
    }
  }
}

void Statistics::reportLongestPhaseInMajorGC(PhaseKind longest,
                                             int telemetryId) {
  JSRuntime* runtime = gc->rt;
  if (longest != PhaseKind::NONE) {
    uint8_t bucket = phaseKinds[longest].telemetryBucket;
    runtime->addTelemetry(telemetryId, bucket);
  }
}

bool Statistics::startTimingMutator() {
  if (phaseStack.length() != 0) {
    // Should only be called from outside of GC.
    MOZ_ASSERT(phaseStack.length() == 1);
    MOZ_ASSERT(phaseStack[0] == Phase::MUTATOR);
    return false;
  }

  MOZ_ASSERT(suspendedPhases.empty());

  timedGCTime = 0;
  phaseStartTimes[Phase::MUTATOR] = TimeStamp();
  phaseTimes[Phase::MUTATOR] = 0;
  timedGCStart = TimeStamp();

  beginPhase(PhaseKind::MUTATOR);
  return true;
}

bool Statistics::stopTimingMutator(double& mutator_ms, double& gc_ms) {
  // This should only be called from outside of GC, while timing the mutator.
  if (phaseStack.length() != 1 || phaseStack[0] != Phase::MUTATOR) {
    return false;
  }

  endPhase(PhaseKind::MUTATOR);
  mutator_ms = t(phaseTimes[Phase::MUTATOR]);
  gc_ms = t(timedGCTime);

  return true;
}

void Statistics::suspendPhases(PhaseKind suspension) {
  MOZ_ASSERT(suspension == PhaseKind::EXPLICIT_SUSPENSION ||
             suspension == PhaseKind::IMPLICIT_SUSPENSION);
  while (!phaseStack.empty()) {
    MOZ_ASSERT(suspendedPhases.length() < MAX_SUSPENDED_PHASES);
    Phase parent = phaseStack.back();
    suspendedPhases.infallibleAppend(parent);
    recordPhaseEnd(parent);
  }
  suspendedPhases.infallibleAppend(lookupChildPhase(suspension));
}

void Statistics::resumePhases() {
  MOZ_ASSERT(suspendedPhases.back() == Phase::EXPLICIT_SUSPENSION ||
             suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION);
  suspendedPhases.popBack();

  while (!suspendedPhases.empty() &&
         suspendedPhases.back() != Phase::EXPLICIT_SUSPENSION &&
         suspendedPhases.back() != Phase::IMPLICIT_SUSPENSION) {
    Phase resumePhase = suspendedPhases.popCopy();
    if (resumePhase == Phase::MUTATOR) {
      timedGCTime += ReallyNow() - timedGCStart;
    }
    recordPhaseBegin(resumePhase);
  }
}

void Statistics::beginPhase(PhaseKind phaseKind) {
  // No longer timing these phases. We should never see these.
  MOZ_ASSERT(phaseKind != PhaseKind::GC_BEGIN &&
             phaseKind != PhaseKind::GC_END);

  // PhaseKind::MUTATOR is suspended while performing GC.
  if (currentPhase() == Phase::MUTATOR) {
    suspendPhases(PhaseKind::IMPLICIT_SUSPENSION);
  }

  recordPhaseBegin(lookupChildPhase(phaseKind));
}

void Statistics::recordPhaseBegin(Phase phase) {
  MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));

  // Guard against any other re-entry.
  MOZ_ASSERT(!phaseStartTimes[phase]);

  MOZ_ASSERT(phaseStack.length() < MAX_PHASE_NESTING);

  Phase current = currentPhase();
  MOZ_ASSERT(phases[phase].parent == current);

  TimeStamp now = ReallyNow();

  if (current != Phase::NONE) {
    MOZ_ASSERT(now >= phaseStartTimes[currentPhase()],
               "Inconsistent time data; see bug 1400153");
    if (now < phaseStartTimes[currentPhase()]) {
      now = phaseStartTimes[currentPhase()];
      aborted = true;
    }
  }

  phaseStack.infallibleAppend(phase);
  phaseStartTimes[phase] = now;
  writeLogMessage("begin: %s", phases[phase].path);
}

void Statistics::recordPhaseEnd(Phase phase) {
  MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));

  MOZ_ASSERT(phaseStartTimes[phase]);

  TimeStamp now = ReallyNow();

  // Make sure this phase ends after it starts.
  MOZ_ASSERT(now >= phaseStartTimes[phase],
             "Inconsistent time data; see bug 1400153");

#ifdef DEBUG
  // Make sure this phase ends after all of its children. Note that some
  // children might not have run in this instance, in which case they will
  // have run in a previous instance of this parent or not at all.
  for (Phase kid = phases[phase].firstChild; kid != Phase::NONE;
       kid = phases[kid].nextSibling) {
    if (phaseEndTimes[kid].IsNull()) {
      continue;
    }
    if (phaseEndTimes[kid] > now) {
      fprintf(stderr,
              "Parent %s ended at %.3fms, before child %s ended at %.3fms?\n",
              phases[phase].name, t(now - TimeStamp::ProcessCreation()),
              phases[kid].name,
              t(phaseEndTimes[kid] - TimeStamp::ProcessCreation()));
    }
    MOZ_ASSERT(phaseEndTimes[kid] <= now,
               "Inconsistent time data; see bug 1400153");
  }
#endif

  if (now < phaseStartTimes[phase]) {
    now = phaseStartTimes[phase];
    aborted = true;
  }

  if (phase == Phase::MUTATOR) {
    timedGCStart = now;
  }

  phaseStack.popBack();

  TimeDuration t = now - phaseStartTimes[phase];
  if (!slices_.empty()) {
    slices_.back().phaseTimes[phase] += t;
  }
  phaseTimes[phase] += t;
  phaseStartTimes[phase] = TimeStamp();

#ifdef DEBUG
  phaseEndTimes[phase] = now;
  writeLogMessage("end: %s", phases[phase].path);
#endif
}

void Statistics::endPhase(PhaseKind phaseKind) {
  Phase phase = currentPhase();
  MOZ_ASSERT(phase != Phase::NONE);
  MOZ_ASSERT(phases[phase].phaseKind == phaseKind);

  recordPhaseEnd(phase);

  // When emptying the stack, we may need to return to timing the mutator
  // (PhaseKind::MUTATOR).
  if (phaseStack.empty() && !suspendedPhases.empty() &&
      suspendedPhases.back() == Phase::IMPLICIT_SUSPENSION) {
    resumePhases();
  }
}

void Statistics::recordParallelPhase(PhaseKind phaseKind,
                                     TimeDuration duration) {
  MOZ_ASSERT(CurrentThreadCanAccessRuntime(gc->rt));

  if (aborted) {
    return;
  }

  // Record the maximum task time for each phase. Don't record times for parent
  // phases.
  Phase phase = lookupChildPhase(phaseKind);
  TimeDuration& time = slices_.back().maxParallelTimes[phase];
  time = std::max(time, duration);
}

TimeStamp Statistics::beginSCC() { return ReallyNow(); }

void Statistics::endSCC(unsigned scc, TimeStamp start) {
  if (scc >= sccTimes.length() && !sccTimes.resize(scc + 1)) {
    return;
  }

  sccTimes[scc] += ReallyNow() - start;
}

/*
 * MMU (minimum mutator utilization) is a measure of how much garbage collection
 * is affecting the responsiveness of the system. MMU measurements are given
 * with respect to a certain window size. If we report MMU(50ms) = 80%, then
 * that means that, for any 50ms window of time, at least 80% of the window is
 * devoted to the mutator. In other words, the GC is running for at most 20% of
 * the window, or 10ms. The GC can run multiple slices during the 50ms window
 * as long as the total time it spends is at most 10ms.
 */
double Statistics::computeMMU(TimeDuration window) const {
  MOZ_ASSERT(!slices_.empty());

  TimeDuration gc = slices_[0].end - slices_[0].start;
  TimeDuration gcMax = gc;

  if (gc >= window) {
    return 0.0;
  }

  int startIndex = 0;
  for (size_t endIndex = 1; endIndex < slices_.length(); endIndex++) {
    auto* startSlice = &slices_[startIndex];
    auto& endSlice = slices_[endIndex];
    gc += endSlice.end - endSlice.start;

    while (endSlice.end - startSlice->end >= window) {
      gc -= startSlice->end - startSlice->start;
      startSlice = &slices_[++startIndex];
    }

    TimeDuration cur = gc;
    if (endSlice.end - startSlice->start > window) {
      cur -= (endSlice.end - startSlice->start - window);
    }
    if (cur > gcMax) {
      gcMax = cur;
    }
  }

  return double((window - gcMax) / window);
}

void Statistics::maybePrintProfileHeaders() {
  static int printedHeader = 0;
  if ((printedHeader++ % 200) == 0) {
    printProfileHeader();
    if (gc->nursery().enableProfiling()) {
      Nursery::printProfileHeader();
    }
  }
}

void Statistics::printProfileHeader() {
  if (!enableProfiling_) {
    return;
  }

  fprintf(stderr, "MajorGC:               Reason States FSNR ");
  fprintf(stderr, " %6s", "budget");
  fprintf(stderr, " %6s", "total");
#define PRINT_PROFILE_HEADER(name, text, phase) fprintf(stderr, " %6s", text);
  FOR_EACH_GC_PROFILE_TIME(PRINT_PROFILE_HEADER)
#undef PRINT_PROFILE_HEADER
  fprintf(stderr, "\n");
}

/* static */
void Statistics::printProfileTimes(const ProfileDurations& times) {
  for (auto time : times) {
    fprintf(stderr, " %6" PRIi64, static_cast<int64_t>(time.ToMilliseconds()));
  }
  fprintf(stderr, "\n");
}

void Statistics::printSliceProfile() {
  const SliceData& slice = slices_.back();

  maybePrintProfileHeaders();

  bool shrinking = gckind == GC_SHRINK;
  bool reset = slice.resetReason != AbortReason::None;
  bool nonIncremental = nonincrementalReason_ != AbortReason::None;
  bool full = zoneStats.isFullCollection();

  fprintf(stderr, "MajorGC: %20s %1d -> %1d %1s%1s%1s%1s ",
          ExplainGCReason(slice.reason), int(slice.initialState),
          int(slice.finalState), full ? "F" : "", shrinking ? "S" : "",
          nonIncremental ? "N" : "", reset ? "R" : "");

  if (!nonIncremental && !slice.budget.isUnlimited() &&
      slice.budget.isTimeBudget()) {
    fprintf(stderr, " %6" PRIi64,
            static_cast<int64_t>(slice.budget.timeBudget.budget));
  } else {
    fprintf(stderr, "       ");
  }

  ProfileDurations times;
  times[ProfileKey::Total] = slice.duration();
  totalTimes_[ProfileKey::Total] += times[ProfileKey::Total];

#define GET_PROFILE_TIME(name, text, phase)                    \
  times[ProfileKey::name] = SumPhase(phase, slice.phaseTimes); \
  totalTimes_[ProfileKey::name] += times[ProfileKey::name];
  FOR_EACH_GC_PROFILE_TIME(GET_PROFILE_TIME)
#undef GET_PROFILE_TIME

  printProfileTimes(times);
}

void Statistics::printTotalProfileTimes() {
  if (enableProfiling_) {
    fprintf(stderr, "MajorGC TOTALS: %7" PRIu64 " slices:                  ",
            sliceCount_);
    printProfileTimes(totalTimes_);
  }
}