[ tor-browser ].git.dasho

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