js/src/gc/Statistics.h

   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 #ifndef gc_Statistics_h
   8 #define gc_Statistics_h
   9
  10 #include "mozilla/Array.h"
  11 #include "mozilla/Atomics.h"
  12 #include "mozilla/EnumeratedArray.h"
  13 #include "mozilla/Maybe.h"
  14 #include "mozilla/TimeStamp.h"
  15
  16 #include "jspubtd.h"
  17 #include "NamespaceImports.h"
  18
  19 #include "gc/GCEnum.h"
  20 #include "js/AllocPolicy.h"
  21 #include "js/GCAPI.h"
  22 #include "js/SliceBudget.h"
  23 #include "js/Vector.h"
  24
  25 namespace js {
  26
  27 class JS_PUBLIC_API Sprinter;
  28 class JSONPrinter;
  29
  30 namespace gcstats {
  31
  32 // Phase data is generated by a script. If you need to add phases, edit
  33 // js/src/gc/GenerateStatsPhases.py
  34
  35 #include "gc/StatsPhasesGenerated.h"
  36
  37 // Counts can be incremented with Statistics::count(). They're reset at the end
  38 // of a Major GC.
  39 enum Count {
  40   COUNT_NEW_CHUNK,
  41   COUNT_DESTROY_CHUNK,
  42   COUNT_MINOR_GC,
  43
  44   // Number of times a 'put' into a storebuffer overflowed, triggering a
  45   // compaction
  46   COUNT_STOREBUFFER_OVERFLOW,
  47
  48   // Number of arenas relocated by compacting GC.
  49   COUNT_ARENA_RELOCATED,
  50
  51   // Number of cells marked during the marking phase. Excludes atoms marked when
  52   // not collecting the atoms zone.
  53   COUNT_CELLS_MARKED,
  54
  55   // Number of times work was donated to a requesting thread during parallel
  56   // marking.
  57   COUNT_PARALLEL_MARK_INTERRUPTIONS,
  58
  59   COUNT_LIMIT
  60 };
  61
  62 // Stats can be set with Statistics::setStat(). They're not reset automatically.
  63 enum Stat {
  64   // Number of strings tenured.
  65   STAT_STRINGS_TENURED,
  66
  67   // Number of strings deduplicated.
  68   STAT_STRINGS_DEDUPLICATED,
  69
  70   // Number of BigInts tenured.
  71   STAT_BIGINTS_TENURED,
  72
  73   STAT_LIMIT
  74 };
  75
  76 struct ZoneGCStats {
  77   /* Number of zones collected in this GC. */
  78   size_t collectedZoneCount = 0;
  79
  80   /* Total number of zones in the Runtime at the start of this GC. */
  81   size_t zoneCount = 0;
  82
  83   /* Number of zones swept in this GC. */
  84   size_t sweptZoneCount = 0;
  85
  86   /* Total number of compartments in all zones collected. */
  87   size_t collectedCompartmentCount = 0;
  88
  89   /* Total number of compartments in the Runtime at the start of this GC. */
  90   size_t compartmentCount = 0;
  91
  92   /* Total number of compartments swept by this GC. */
  93   size_t sweptCompartmentCount = 0;
  94
  95   /* Total number of realms in the Runtime at the start of this GC. */
  96   size_t realmCount = 0;
  97
  98   ZoneGCStats() = default;
  99 };
 100
 101 struct Trigger {
 102   size_t amount = 0;
 103   size_t threshold = 0;
 104 };
 105
 106 #define FOR_EACH_GC_PROFILE_TIME(_)                                 \
 107   _(Total, "total", PhaseKind::NONE)                                \
 108   _(Background, "bgwrk", PhaseKind::NONE)                           \
 109   _(MinorForMajor, "evct4m", PhaseKind::EVICT_NURSERY_FOR_MAJOR_GC) \
 110   _(WaitBgThread, "waitBG", PhaseKind::WAIT_BACKGROUND_THREAD)      \
 111   _(Prepare, "prep", PhaseKind::PREPARE)                            \
 112   _(Mark, "mark", PhaseKind::MARK)                                  \
 113   _(Sweep, "sweep", PhaseKind::SWEEP)                               \
 114   _(Compact, "cmpct", PhaseKind::COMPACT)                           \
 115   _(Decommit, "dcmmt", PhaseKind::DECOMMIT)
 116
 117 static const char* const MajorGCProfilePrefix = "MajorGC:";
 118 static const char* const MinorGCProfilePrefix = "MinorGC:";
 119
 120 const char* ExplainAbortReason(GCAbortReason reason);
 121
 122 /*
 123  * Struct for collecting timing statistics on a "phase tree". The tree is
 124  * specified as a limited DAG, but the timings are collected for the whole tree
 125  * that you would get by expanding out the DAG by duplicating subtrees rooted
 126  * at nodes with multiple parents.
 127  *
 128  * During execution, a child phase can be activated multiple times, and the
 129  * total time will be accumulated. (So for example, you can start and end
 130  * PhaseKind::MARK_ROOTS multiple times before completing the parent phase.)
 131  *
 132  * Incremental GC is represented by recording separate timing results for each
 133  * slice within the overall GC.
 134  */
 135 struct Statistics {
 136   template <typename T, size_t Length>
 137   using Array = mozilla::Array<T, Length>;
 138
 139   template <typename IndexType, IndexType SizeAsEnumValue, typename ValueType>
 140   using EnumeratedArray =
 141       mozilla::EnumeratedArray<IndexType, SizeAsEnumValue, ValueType>;
 142
 143   using TimeDuration = mozilla::TimeDuration;
 144   using TimeStamp = mozilla::TimeStamp;
 145
 146   // Create types for tables of times, by phase and phase kind.
 147   using PhaseTimes = EnumeratedArray<Phase, Phase::LIMIT, TimeDuration>;
 148   using PhaseKindTimes =
 149       EnumeratedArray<PhaseKind, PhaseKind::LIMIT, TimeDuration>;
 150
 151   using PhaseTimeStamps = EnumeratedArray<Phase, Phase::LIMIT, TimeStamp>;
 152
 153   [[nodiscard]] static bool initialize();
 154
 155   explicit Statistics(gc::GCRuntime* gc);
 156   ~Statistics();
 157
 158   Statistics(const Statistics&) = delete;
 159   Statistics& operator=(const Statistics&) = delete;
 160
 161   void beginPhase(PhaseKind phaseKind);
 162   void endPhase(PhaseKind phaseKind);
 163   void recordParallelPhase(PhaseKind phaseKind, TimeDuration duration);
 164
 165   // Occasionally, we may be in the middle of something that is tracked by
 166   // this class, and we need to do something unusual (eg evict the nursery)
 167   // that doesn't normally nest within the current phase. Suspend the
 168   // currently tracked phase stack, at which time the caller is free to do
 169   // other tracked operations.
 170   //
 171   // This also happens internally with the PhaseKind::MUTATOR "phase". While in
 172   // this phase, any beginPhase will automatically suspend the non-GC phase,
 173   // until that inner stack is complete, at which time it will automatically
 174   // resume the non-GC phase. Explicit suspensions do not get auto-resumed.
 175   void suspendPhases(PhaseKind suspension = PhaseKind::EXPLICIT_SUSPENSION);
 176
 177   // Resume a suspended stack of phases.
 178   void resumePhases();
 179
 180   void beginSlice(const ZoneGCStats& zoneStats, JS::GCOptions options,
 181                   const SliceBudget& budget, JS::GCReason reason,
 182                   bool budgetWasIncreased);
 183   void endSlice();
 184
 185   [[nodiscard]] bool startTimingMutator();
 186   [[nodiscard]] bool stopTimingMutator(double& mutator_ms, double& gc_ms);
 187
 188   // Note when we sweep a zone or compartment.
 189   void sweptZone() { ++zoneStats.sweptZoneCount; }
 190   void sweptCompartment() { ++zoneStats.sweptCompartmentCount; }
 191
 192   void reset(GCAbortReason reason) {
 193     MOZ_ASSERT(reason != GCAbortReason::None);
 194     if (!aborted) {
 195       slices_.back().resetReason = reason;
 196     }
 197   }
 198
 199   void measureInitialHeapSize();
 200
 201   void nonincremental(GCAbortReason reason) {
 202     MOZ_ASSERT(reason != GCAbortReason::None);
 203     nonincrementalReason_ = reason;
 204     log("Non-incremental reason: %s", nonincrementalReason());
 205   }
 206
 207   bool nonincremental() const {
 208     return nonincrementalReason_ != GCAbortReason::None;
 209   }
 210
 211   const char* nonincrementalReason() const {
 212     return ExplainAbortReason(nonincrementalReason_);
 213   }
 214
 215   void count(Count s) { counts[s]++; }
 216   void addCount(Count s, uint32_t count) { counts[s] += count; }
 217
 218   uint32_t getCount(Count s) const { return uint32_t(counts[s]); }
 219
 220   void setStat(Stat s, uint32_t value) { stats[s] = value; }
 221
 222   uint32_t getStat(Stat s) const { return stats[s]; }
 223
 224   void recordTrigger(size_t amount, size_t threshold) {
 225     recordedTrigger = mozilla::Some(Trigger{amount, threshold});
 226   }
 227   bool hasTrigger() const { return recordedTrigger.isSome(); }
 228
 229   // tenured allocs don't include nursery evictions.
 230   void setAllocsSinceMinorGCTenured(uint32_t allocs) {
 231     tenuredAllocsSinceMinorGC = allocs;
 232   }
 233
 234   uint32_t allocsSinceMinorGCTenured() { return tenuredAllocsSinceMinorGC; }
 235
 236   void beginNurseryCollection();
 237   void endNurseryCollection();
 238
 239   TimeStamp beginSCC();
 240   void endSCC(unsigned scc, TimeStamp start);
 241
 242   UniqueChars formatCompactSliceMessage() const;
 243   UniqueChars formatCompactSummaryMessage() const;
 244   UniqueChars formatDetailedMessage() const;
 245
 246   JS::GCSliceCallback setSliceCallback(JS::GCSliceCallback callback);
 247
 248   TimeDuration clearMaxGCPauseAccumulator();
 249   TimeDuration getMaxGCPauseSinceClear();
 250
 251   PhaseKind currentPhaseKind() const;
 252
 253   static const size_t MAX_SUSPENDED_PHASES = MAX_PHASE_NESTING * 3;
 254
 255   struct SliceData {
 256     SliceData(const SliceBudget& budget, mozilla::Maybe<Trigger> trigger,
 257               JS::GCReason reason, TimeStamp start, size_t startFaults,
 258               gc::State initialState);
 259
 260     SliceBudget budget;
 261     JS::GCReason reason = JS::GCReason::NO_REASON;
 262     mozilla::Maybe<Trigger> trigger;
 263     gc::State initialState = gc::State::NotActive;
 264     gc::State finalState = gc::State::NotActive;
 265     GCAbortReason resetReason = GCAbortReason::None;
 266     TimeStamp start;
 267     TimeStamp end;
 268     size_t startFaults = 0;
 269     size_t endFaults = 0;
 270     PhaseTimes phaseTimes;
 271     PhaseKindTimes totalParallelTimes;
 272     PhaseKindTimes maxParallelTimes;
 273
 274     TimeDuration duration() const;
 275     bool wasReset() const { return resetReason != GCAbortReason::None; }
 276   };
 277
 278   using SliceDataVector = Vector<SliceData, 8, SystemAllocPolicy>;
 279
 280   const SliceDataVector& slices() const { return slices_; }
 281   const SliceData& sliceAt(size_t index) const { return slices_[index]; }
 282
 283   const SliceData* lastSlice() const {
 284     if (slices_.length() == 0) {
 285       return nullptr;
 286     }
 287
 288     return &slices_.back();
 289   }
 290
 291   TimeStamp start() const { return slices_[0].start; }
 292
 293   TimeStamp end() const { return slices_.back().end; }
 294
 295   TimeStamp creationTime() const { return creationTime_; }
 296
 297   TimeDuration totalGCTime() const { return totalGCTime_; }
 298   size_t initialCollectedBytes() const { return preCollectedHeapBytes; }
 299
 300   // File to write profiling information to, either stderr or file specified
 301   // with JS_GC_PROFILE_FILE.
 302   FILE* profileFile() const { return gcProfileFile; }
 303
 304   // Occasionally print header lines for profiling information.
 305   void maybePrintProfileHeaders();
 306
 307   // Print header line for profile times.
 308   void printProfileHeader();
 309
 310   // Print total profile times on shutdown.
 311   void printTotalProfileTimes();
 312
 313   // These JSON strings are used by the firefox profiler to display the GC
 314   // markers.
 315
 316   // Return JSON for a whole major GC
 317   UniqueChars renderJsonMessage() const;
 318
 319   // Return JSON for the timings of just the given slice.
 320   UniqueChars renderJsonSlice(size_t sliceNum) const;
 321
 322   // Return JSON for the previous nursery collection.
 323   UniqueChars renderNurseryJson() const;
 324
 325 #ifdef DEBUG
 326   // Print a logging message.
 327   void log(const char* fmt, ...);
 328 #else
 329   void log(const char* fmt, ...){};
 330 #endif
 331
 332  private:
 333   gc::GCRuntime* const gc;
 334
 335   /* File used for MOZ_GCTIMER output. */
 336   FILE* gcTimerFile;
 337
 338   /* File used for JS_GC_DEBUG output. */
 339   FILE* gcDebugFile;
 340
 341   /* File used for JS_GC_PROFILE output. */
 342   FILE* gcProfileFile;
 343
 344   ZoneGCStats zoneStats;
 345
 346   JS::GCOptions gcOptions = JS::GCOptions::Normal;
 347
 348   GCAbortReason nonincrementalReason_;
 349
 350   SliceDataVector slices_;
 351
 352   /* Most recent time when the given phase started. */
 353   PhaseTimeStamps phaseStartTimes;
 354
 355 #ifdef DEBUG
 356   /* Most recent time when the given phase ended. */
 357   PhaseTimeStamps phaseEndTimes;
 358 #endif
 359
 360   TimeStamp creationTime_;
 361
 362   /* Bookkeeping for GC timings when timingMutator is true */
 363   TimeStamp timedGCStart;
 364   TimeDuration timedGCTime;
 365
 366   /* Total main thread time in a given phase for this GC. */
 367   PhaseTimes phaseTimes;
 368
 369   /* Total main thread time for this GC. */
 370   TimeDuration totalGCTime_;
 371
 372   /* Number of events of this type for this GC. */
 373   EnumeratedArray<Count, COUNT_LIMIT,
 374                   mozilla::Atomic<uint32_t, mozilla::ReleaseAcquire>>
 375       counts;
 376
 377   /* Other GC statistics. */
 378   EnumeratedArray<Stat, STAT_LIMIT, uint32_t> stats;
 379
 380   /*
 381    * These events cannot be kept in the above array, we need to take their
 382    * address.
 383    */
 384   uint32_t tenuredAllocsSinceMinorGC;
 385
 386   /* Total GC heap size before and after the GC ran. */
 387   size_t preTotalHeapBytes;
 388   size_t postTotalHeapBytes;
 389
 390   /* GC heap size for collected zones before GC ran. */
 391   size_t preCollectedHeapBytes;
 392
 393   /*
 394    * If a GC slice was triggered by exceeding some threshold, record the
 395    * threshold and the value that exceeded it. This happens before the slice
 396    * starts so this is recorded here first and then transferred to SliceData.
 397    */
 398   mozilla::Maybe<Trigger> recordedTrigger;
 399
 400   /* GC numbers as of the beginning of the collection. */
 401   uint64_t startingMinorGCNumber;
 402   uint64_t startingMajorGCNumber;
 403   uint64_t startingSliceNumber;
 404
 405   /* Records the maximum GC pause in an API-controlled interval. */
 406   mutable TimeDuration maxPauseInInterval;
 407
 408   /* Phases that are currently on stack. */
 409   Vector<Phase, MAX_PHASE_NESTING, SystemAllocPolicy> phaseStack;
 410
 411   /*
 412    * Certain phases can interrupt the phase stack, eg callback phases. When
 413    * this happens, we move the suspended phases over to a sepearate list,
 414    * terminated by a dummy PhaseKind::SUSPENSION phase (so that we can nest
 415    * suspensions by suspending multiple stacks with a PhaseKind::SUSPENSION in
 416    * between).
 417    */
 418   Vector<Phase, MAX_SUSPENDED_PHASES, SystemAllocPolicy> suspendedPhases;
 419
 420   /* Sweep times for SCCs of compartments. */
 421   Vector<TimeDuration, 0, SystemAllocPolicy> sccTimes;
 422
 423   TimeDuration timeSinceLastGC;
 424
 425   JS::GCSliceCallback sliceCallback;
 426
 427   /*
 428    * True if we saw an OOM while allocating slices or we saw an impossible
 429    * timestamp. The statistics for this GC will be invalid.
 430    */
 431   bool aborted;
 432
 433   /* Profiling data. */
 434
 435   enum class ProfileKey {
 436 #define DEFINE_PROFILE_KEY(name, _1, _2) name,
 437     FOR_EACH_GC_PROFILE_TIME(DEFINE_PROFILE_KEY)
 438 #undef DEFINE_PROFILE_KEY
 439         KeyCount
 440   };
 441
 442   using ProfileDurations =
 443       EnumeratedArray<ProfileKey, ProfileKey::KeyCount, TimeDuration>;
 444
 445   bool enableProfiling_ = false;
 446   bool profileWorkers_ = false;
 447   TimeDuration profileThreshold_;
 448   ProfileDurations totalTimes_;
 449   uint64_t sliceCount_;
 450
 451   char formatBuffer_[32];
 452   static constexpr int FormatBufferLength = sizeof(formatBuffer_);
 453
 454   JSContext* context();
 455
 456   Phase currentPhase() const;
 457   Phase lookupChildPhase(PhaseKind phaseKind) const;
 458
 459   void beginGC(JS::GCOptions options, const TimeStamp& currentTime);
 460   void endGC();
 461
 462   void sendGCTelemetry();
 463   void sendSliceTelemetry(const SliceData& slice);
 464
 465   TimeDuration sumTotalParallelTime(PhaseKind phaseKind) const;
 466
 467   void recordPhaseBegin(Phase phase);
 468   void recordPhaseEnd(Phase phase);
 469
 470   void gcDuration(TimeDuration* total, TimeDuration* maxPause) const;
 471   void sccDurations(TimeDuration* total, TimeDuration* maxPause) const;
 472   void printStats();
 473
 474   template <typename Fn>
 475   void reportLongestPhaseInMajorGC(PhaseKind longest, Fn reportFn);
 476
 477   UniqueChars formatCompactSlicePhaseTimes(const PhaseTimes& phaseTimes) const;
 478
 479   UniqueChars formatDetailedDescription() const;
 480   UniqueChars formatDetailedSliceDescription(unsigned i,
 481                                              const SliceData& slice) const;
 482   UniqueChars formatDetailedPhaseTimes(const PhaseTimes& phaseTimes) const;
 483   UniqueChars formatDetailedTotals() const;
 484
 485   void formatJsonDescription(JSONPrinter&) const;
 486   void formatJsonSliceDescription(unsigned i, const SliceData& slice,
 487                                   JSONPrinter&) const;
 488   void formatJsonPhaseTimes(const PhaseTimes& phaseTimes, JSONPrinter&) const;
 489   void formatJsonSlice(size_t sliceNum, JSONPrinter&) const;
 490
 491   double computeMMU(TimeDuration window) const;
 492
 493   void printSliceProfile();
 494   ProfileDurations getProfileTimes(const SliceData& slice) const;
 495   void updateTotalProfileTimes(const ProfileDurations& times);
 496   const char* formatGCStates(const SliceData& slice);
 497   const char* formatGCFlags(const SliceData& slice);
 498   const char* formatBudget(const SliceData& slice);
 499   const char* formatTotalSlices();
 500   static bool printProfileTimes(const ProfileDurations& times,
 501                                 Sprinter& sprinter);
 502 };
 503
 504 struct MOZ_RAII AutoGCSlice {
 505   AutoGCSlice(Statistics& stats, const ZoneGCStats& zoneStats,
 506               JS::GCOptions options, const SliceBudget& budget,
 507               JS::GCReason reason, bool budgetWasIncreased)
 508       : stats(stats) {
 509     stats.beginSlice(zoneStats, options, budget, reason, budgetWasIncreased);
 510   }
 511   ~AutoGCSlice() { stats.endSlice(); }
 512
 513   Statistics& stats;
 514 };
 515
 516 struct MOZ_RAII AutoPhase {
 517   AutoPhase(Statistics& stats, PhaseKind phaseKind)
 518       : stats(stats), phaseKind(phaseKind), enabled(true) {
 519     stats.beginPhase(phaseKind);
 520   }
 521
 522   AutoPhase(Statistics& stats, bool condition, PhaseKind phaseKind)
 523       : stats(stats), phaseKind(phaseKind), enabled(condition) {
 524     if (enabled) {
 525       stats.beginPhase(phaseKind);
 526     }
 527   }
 528
 529   ~AutoPhase() {
 530     if (enabled) {
 531       stats.endPhase(phaseKind);
 532     }
 533   }
 534
 535   Statistics& stats;
 536   PhaseKind phaseKind;
 537   bool enabled;
 538 };
 539
 540 struct MOZ_RAII AutoSCC {
 541   AutoSCC(Statistics& stats, unsigned scc) : stats(stats), scc(scc) {
 542     start = stats.beginSCC();
 543   }
 544   ~AutoSCC() { stats.endSCC(scc, start); }
 545
 546   Statistics& stats;
 547   unsigned scc;
 548   mozilla::TimeStamp start;
 549 };
 550
 551 void ReadProfileEnv(const char* envName, const char* helpText, bool* enableOut,
 552                     bool* workersOut, mozilla::TimeDuration* thresholdOut);
 553
 554 } /* namespace gcstats */
 555
 556 struct StringStats {
 557   // number of strings that were deduplicated, and their sizes in characters
 558   // and bytes
 559   uint64_t deduplicatedStrings = 0;
 560   uint64_t deduplicatedChars = 0;
 561   uint64_t deduplicatedBytes = 0;
 562
 563   // number of live nursery strings at the start of a nursery collection
 564   uint64_t liveNurseryStrings = 0;
 565
 566   // number of new strings added to the tenured heap
 567   uint64_t tenuredStrings = 0;
 568
 569   // Currently, liveNurseryStrings = tenuredStrings + deduplicatedStrings (but
 570   // in the future we may do more transformation during tenuring, eg
 571   // atomizing.)
 572
 573   // number of malloced bytes associated with tenured strings (the actual
 574   // malloc will have happened when the strings were allocated in the nursery;
 575   // the ownership of the bytes will be transferred to the tenured strings)
 576   uint64_t tenuredBytes = 0;
 577
 578   StringStats& operator+=(const StringStats& other) {
 579     deduplicatedStrings += other.deduplicatedStrings;
 580     deduplicatedChars += other.deduplicatedChars;
 581     deduplicatedBytes += other.deduplicatedBytes;
 582     liveNurseryStrings += other.liveNurseryStrings;
 583     tenuredStrings += other.tenuredStrings;
 584     tenuredBytes += other.tenuredBytes;
 585     return *this;
 586   }
 587
 588   void noteTenured(size_t mallocBytes) {
 589     liveNurseryStrings++;
 590     tenuredStrings++;
 591     tenuredBytes += mallocBytes;
 592   }
 593
 594   void noteDeduplicated(size_t numChars, size_t mallocBytes) {
 595     liveNurseryStrings++;
 596     deduplicatedStrings++;
 597     deduplicatedChars += numChars;
 598     deduplicatedBytes += mallocBytes;
 599   }
 600 };
 601
 602 } /* namespace js */
 603
 604 #endif /* gc_Statistics_h */