gc-tracer.h 17.9 KB
Newer Older
1 2 3 4
// Copyright 2014 the V8 project authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

5 6
#ifndef V8_HEAP_GC_TRACER_H_
#define V8_HEAP_GC_TRACER_H_
7

jfb's avatar
jfb committed
8
#include "src/base/compiler-specific.h"
9
#include "src/base/optional.h"
10
#include "src/base/platform/platform.h"
11
#include "src/base/platform/time.h"
12
#include "src/base/ring-buffer.h"
13
#include "src/common/globals.h"
14
#include "src/heap/heap.h"
15
#include "src/init/heap-symbols.h"
16
#include "src/logging/counters.h"
17
#include "testing/gtest/include/gtest/gtest_prod.h"  // nogncheck
18

19 20 21
namespace v8 {
namespace internal {

22
using BytesAndDuration = std::pair<uint64_t, double>;
23 24 25 26

inline BytesAndDuration MakeBytesAndDuration(uint64_t bytes, double duration) {
  return std::make_pair(bytes, duration);
}
27

28 29
enum ScavengeSpeedMode { kForAllObjects, kForSurvivedObjects };

30
#define TRACE_GC_CATEGORIES \
31
  "devtools.timeline," TRACE_DISABLED_BY_DEFAULT("v8.gc")
32

33 34 35 36
#define TRACE_GC(tracer, scope_id)                            \
  GCTracer::Scope::ScopeId gc_tracer_scope_id(scope_id);      \
  GCTracer::Scope gc_tracer_scope(tracer, gc_tracer_scope_id, \
                                  ThreadKind::kMain);         \
37
  TRACE_EVENT0(TRACE_GC_CATEGORIES, GCTracer::Scope::Name(gc_tracer_scope_id))
38

39 40 41 42
#define TRACE_GC1(tracer, scope_id, thread_kind)                            \
  GCTracer::Scope::ScopeId gc_tracer_scope_id(scope_id);                    \
  GCTracer::Scope gc_tracer_scope(tracer, gc_tracer_scope_id, thread_kind); \
  TRACE_EVENT0(TRACE_GC_CATEGORIES, GCTracer::Scope::Name(gc_tracer_scope_id))
43

44 45 46 47 48 49 50
#define TRACE_GC_EPOCH(tracer, scope_id, thread_kind)                          \
  GCTracer::Scope::ScopeId gc_tracer_scope_id(scope_id);                       \
  GCTracer::Scope gc_tracer_scope(tracer, gc_tracer_scope_id, thread_kind);    \
  CollectionEpoch gc_tracer_epoch = tracer->CurrentEpoch(scope_id);            \
  TRACE_EVENT1(TRACE_GC_CATEGORIES, GCTracer::Scope::Name(gc_tracer_scope_id), \
               "epoch", gc_tracer_epoch)

51 52
// GCTracer collects and prints ONE line after each garbage collector
// invocation IFF --trace_gc is used.
53
class V8_EXPORT_PRIVATE GCTracer {
54
 public:
55 56 57
  GCTracer(const GCTracer&) = delete;
  GCTracer& operator=(const GCTracer&) = delete;

58
  struct IncrementalMarkingInfos {
59
    IncrementalMarkingInfos() : duration(0), longest_step(0), steps(0) {}
60 61 62

    void Update(double duration) {
      steps++;
63
      this->duration += duration;
64 65 66 67 68 69
      if (duration > longest_step) {
        longest_step = duration;
      }
    }

    void ResetCurrentCycle() {
70
      duration = 0;
71 72 73 74
      longest_step = 0;
      steps = 0;
    }

75
    double duration;
76 77 78 79
    double longest_step;
    int steps;
  };

80
  class V8_EXPORT_PRIVATE V8_NODISCARD Scope {
81 82
   public:
    enum ScopeId {
83
#define DEFINE_SCOPE(scope) scope,
84
      TRACER_SCOPES(DEFINE_SCOPE) TRACER_BACKGROUND_SCOPES(DEFINE_SCOPE)
85
#undef DEFINE_SCOPE
86 87
          NUMBER_OF_SCOPES,

88
      FIRST_INCREMENTAL_SCOPE = MC_INCREMENTAL,
89
      LAST_INCREMENTAL_SCOPE = MC_INCREMENTAL_SWEEPING,
90
      FIRST_SCOPE = MC_INCREMENTAL,
91
      NUMBER_OF_INCREMENTAL_SCOPES =
92
          LAST_INCREMENTAL_SCOPE - FIRST_INCREMENTAL_SCOPE + 1,
93
      FIRST_GENERAL_BACKGROUND_SCOPE = BACKGROUND_YOUNG_ARRAY_BUFFER_SWEEP,
94
      LAST_GENERAL_BACKGROUND_SCOPE = BACKGROUND_UNMAPPER,
95 96
      FIRST_MC_BACKGROUND_SCOPE = MC_BACKGROUND_EVACUATE_COPY,
      LAST_MC_BACKGROUND_SCOPE = MC_BACKGROUND_SWEEPING,
97 98
      FIRST_TOP_MC_SCOPE = MC_CLEAR,
      LAST_TOP_MC_SCOPE = MC_SWEEP,
99
      FIRST_MINOR_GC_BACKGROUND_SCOPE = MINOR_MC_BACKGROUND_EVACUATE_COPY,
100 101
      LAST_MINOR_GC_BACKGROUND_SCOPE = SCAVENGER_BACKGROUND_SCAVENGE_PARALLEL,
      FIRST_BACKGROUND_SCOPE = FIRST_GENERAL_BACKGROUND_SCOPE
102 103
    };

104
    Scope(GCTracer* tracer, ScopeId scope, ThreadKind thread_kind);
105
    ~Scope();
106 107
    Scope(const Scope&) = delete;
    Scope& operator=(const Scope&) = delete;
108
    static const char* Name(ScopeId id);
109
    static bool NeedsYoungEpoch(ScopeId id);
110 111 112 113

   private:
    GCTracer* tracer_;
    ScopeId scope_;
114
    ThreadKind thread_kind_;
115
    double start_time_;
116
    RuntimeCallTimer timer_;
117
    RuntimeCallStats* runtime_stats_ = nullptr;
118
    base::Optional<WorkerThreadRuntimeCallStatsScope> runtime_call_stats_scope_;
119 120 121 122
  };

  class Event {
   public:
123 124 125 126
    enum Type {
      SCAVENGER = 0,
      MARK_COMPACTOR = 1,
      INCREMENTAL_MARK_COMPACTOR = 2,
127 128
      MINOR_MARK_COMPACTOR = 3,
      START = 4
129
    };
130

131 132
    Event(Type type, GarbageCollectionReason gc_reason,
          const char* collector_reason);
133 134 135 136 137 138 139

    // Returns a string describing the event type.
    const char* TypeName(bool short_name) const;

    // Type of event
    Type type;

140
    GarbageCollectionReason gc_reason;
141 142 143 144 145 146 147 148
    const char* collector_reason;

    // Timestamp set in the constructor.
    double start_time;

    // Timestamp set in the destructor.
    double end_time;

149 150 151
    // Memory reduction flag set.
    bool reduce_memory;

152
    // Size of objects in heap set in constructor.
ulan's avatar
ulan committed
153
    size_t start_object_size;
154 155

    // Size of objects in heap set in destructor.
ulan's avatar
ulan committed
156
    size_t end_object_size;
157 158

    // Size of memory allocated from OS set in constructor.
159
    size_t start_memory_size;
160 161

    // Size of memory allocated from OS set in destructor.
162
    size_t end_memory_size;
163 164 165

    // Total amount of space either wasted or contained in one of free lists
    // before the current GC.
ulan's avatar
ulan committed
166
    size_t start_holes_size;
167 168 169

    // Total amount of space either wasted or contained in one of free lists
    // after the current GC.
ulan's avatar
ulan committed
170
    size_t end_holes_size;
171

172 173
    // Size of young objects in constructor.
    size_t young_object_size;
174

175 176
    // Size of survived young objects in destructor.
    size_t survived_young_object_size;
177

178
    // Bytes marked incrementally for INCREMENTAL_MARK_COMPACTOR
ulan's avatar
ulan committed
179
    size_t incremental_marking_bytes;
180

181 182
    // Duration of incremental marking steps for INCREMENTAL_MARK_COMPACTOR.
    double incremental_marking_duration;
183

184 185
    // Amounts of time spent in different scopes during GC.
    double scopes[Scope::NUMBER_OF_SCOPES];
186 187 188 189

    // Holds details for incremental marking scopes.
    IncrementalMarkingInfos
        incremental_marking_scopes[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
190 191
  };

192
  static const int kThroughputTimeFrameMs = 5000;
193 194 195 196
  static constexpr double kConservativeSpeedInBytesPerMillisecond = 128 * KB;

  static double CombineSpeedsInBytesPerMillisecond(double default_speed,
                                                   double optional_speed);
197

198
  static RuntimeCallCounterId RCSCounterFromScope(Scope::ScopeId id);
199

200 201 202
  explicit GCTracer(Heap* heap);

  // Start collecting data.
203
  void Start(GarbageCollector collector, GarbageCollectionReason gc_reason,
204
             const char* collector_reason);
205
  void StartInSafepoint();
206 207

  // Stop collecting data and print results.
hpayer's avatar
hpayer committed
208
  void Stop(GarbageCollector collector);
209
  void StopInSafepoint();
210

211 212
  void NotifySweepingCompleted();

213 214 215
  void NotifyYoungGenerationHandling(
      YoungGenerationHandling young_generation_handling);

216
  // Sample and accumulate bytes allocated since the last GC.
217
  void SampleAllocation(double current_ms, size_t new_space_counter_bytes,
218 219
                        size_t old_generation_counter_bytes,
                        size_t embedder_counter_bytes);
220 221

  // Log the accumulated new space allocation bytes.
222
  void AddAllocation(double current_ms);
223

224 225
  void AddContextDisposalTime(double time);

ulan's avatar
ulan committed
226
  void AddCompactionEvent(double duration, size_t live_bytes_compacted);
227

228
  void AddSurvivalRatio(double survival_ratio);
229

230
  // Log an incremental marking step.
ulan's avatar
ulan committed
231
  void AddIncrementalMarkingStep(double duration, size_t bytes);
232

233
  // Compute the average incremental marking speed in bytes/millisecond.
234
  // Returns a conservative value if no events have been recorded.
235
  double IncrementalMarkingSpeedInBytesPerMillisecond() const;
236

237 238 239 240
  // Compute the average embedder speed in bytes/millisecond.
  // Returns a conservative value if no events have been recorded.
  double EmbedderSpeedInBytesPerMillisecond() const;

241 242
  // Compute the average scavenge speed in bytes/millisecond.
  // Returns 0 if no events have been recorded.
243
  double ScavengeSpeedInBytesPerMillisecond(
244
      ScavengeSpeedMode mode = kForAllObjects) const;
245

246 247
  // Compute the average compaction speed in bytes/millisecond.
  // Returns 0 if not enough events have been recorded.
248
  double CompactionSpeedInBytesPerMillisecond() const;
249

250
  // Compute the average mark-sweep speed in bytes/millisecond.
251
  // Returns 0 if no events have been recorded.
252
  double MarkCompactSpeedInBytesPerMillisecond() const;
253

254 255 256
  // Compute the average incremental mark-sweep finalize speed in
  // bytes/millisecond.
  // Returns 0 if no events have been recorded.
257
  double FinalIncrementalMarkCompactSpeedInBytesPerMillisecond() const;
258

259 260 261 262
  // Compute the overall mark compact speed including incremental steps
  // and the final mark-compact step.
  double CombinedMarkCompactSpeedInBytesPerMillisecond();

263
  // Allocation throughput in the new space in bytes/millisecond.
264
  // Returns 0 if no allocation events have been recorded.
265
  double NewSpaceAllocationThroughputInBytesPerMillisecond(
266 267 268 269 270
      double time_ms = 0) const;

  // Allocation throughput in the old generation in bytes/millisecond in the
  // last time_ms milliseconds.
  // Returns 0 if no allocation events have been recorded.
271
  double OldGenerationAllocationThroughputInBytesPerMillisecond(
272
      double time_ms = 0) const;
273

274 275 276 277 278 279
  // Allocation throughput in the embedder in bytes/millisecond in the
  // last time_ms milliseconds. Reported through v8::EmbedderHeapTracer.
  // Returns 0 if no allocation events have been recorded.
  double EmbedderAllocationThroughputInBytesPerMillisecond(
      double time_ms = 0) const;

280 281
  // Allocation throughput in heap in bytes/millisecond in the last time_ms
  // milliseconds.
282
  // Returns 0 if no allocation events have been recorded.
283
  double AllocationThroughputInBytesPerMillisecond(double time_ms) const;
284

285 286
  // Allocation throughput in heap in bytes/milliseconds in the last
  // kThroughputTimeFrameMs seconds.
287
  // Returns 0 if no allocation events have been recorded.
288
  double CurrentAllocationThroughputInBytesPerMillisecond() const;
289

290 291
  // Allocation throughput in old generation in bytes/milliseconds in the last
  // kThroughputTimeFrameMs seconds.
292
  // Returns 0 if no allocation events have been recorded.
293
  double CurrentOldGenerationAllocationThroughputInBytesPerMillisecond() const;
294

295 296 297 298 299
  // Allocation throughput in the embedder in bytes/milliseconds in the last
  // kThroughputTimeFrameMs seconds. Reported through v8::EmbedderHeapTracer.
  // Returns 0 if no allocation events have been recorded.
  double CurrentEmbedderAllocationThroughputInBytesPerMillisecond() const;

300
  // Computes the context disposal rate in milliseconds. It takes the time
301 302
  // frame of the first recorded context disposal to the current time and
  // divides it by the number of recorded events.
303 304 305
  // Returns 0 if no events have been recorded.
  double ContextDisposalRateInMilliseconds() const;

306
  // Computes the average survival ratio based on the last recorded survival
307 308
  // events.
  // Returns 0 if no events have been recorded.
309
  double AverageSurvivalRatio() const;
310 311 312 313

  // Returns true if at least one survival event was recorded.
  bool SurvivalEventsRecorded() const;

314 315 316
  // Discard all recorded survival events.
  void ResetSurvivalEvents();

317 318
  void NotifyIncrementalMarkingStart();

319 320 321 322 323
  // Returns average mutator utilization with respect to mark-compact
  // garbage collections. This ignores scavenger.
  double AverageMarkCompactMutatorUtilization() const;
  double CurrentMarkCompactMutatorUtilization() const;

324 325 326 327
  V8_INLINE void AddScopeSample(Scope::ScopeId scope, double duration) {
    DCHECK(scope < Scope::NUMBER_OF_SCOPES);
    if (scope >= Scope::FIRST_INCREMENTAL_SCOPE &&
        scope <= Scope::LAST_INCREMENTAL_SCOPE) {
328 329
      incremental_marking_scopes_[scope - Scope::FIRST_INCREMENTAL_SCOPE]
          .Update(duration);
330 331 332 333
    } else {
      current_.scopes[scope] += duration;
    }
  }
334

335
  void AddScopeSampleBackground(Scope::ScopeId scope, double duration);
336

337
  void RecordGCPhasesHistograms(TimedHistogram* gc_timer);
338

339 340
  void RecordEmbedderSpeed(size_t bytes, double duration);

341 342 343 344 345
  // Returns the average time between scheduling and invocation of an
  // incremental marking task.
  double AverageTimeToIncrementalMarkingTask() const;
  void RecordTimeToIncrementalMarkingTask(double time_to_task);

346 347
  WorkerThreadRuntimeCallStats* worker_thread_runtime_call_stats();

348 349
  CollectionEpoch CurrentEpoch(Scope::ScopeId id);

350 351 352
 private:
  FRIEND_TEST(GCTracer, AverageSpeed);
  FRIEND_TEST(GCTracerTest, AllocationThroughput);
353 354 355
  FRIEND_TEST(GCTracerTest, BackgroundScavengerScope);
  FRIEND_TEST(GCTracerTest, BackgroundMinorMCScope);
  FRIEND_TEST(GCTracerTest, BackgroundMajorMCScope);
356
  FRIEND_TEST(GCTracerTest, EmbedderAllocationThroughput);
357
  FRIEND_TEST(GCTracerTest, MultithreadedBackgroundScope);
358
  FRIEND_TEST(GCTracerTest, NewSpaceAllocationThroughput);
359 360
  FRIEND_TEST(GCTracerTest, PerGenerationAllocationThroughput);
  FRIEND_TEST(GCTracerTest, PerGenerationAllocationThroughputWithProvidedTime);
361
  FRIEND_TEST(GCTracerTest, RegularScope);
362
  FRIEND_TEST(GCTracerTest, IncrementalMarkingDetails);
363
  FRIEND_TEST(GCTracerTest, IncrementalScope);
364
  FRIEND_TEST(GCTracerTest, IncrementalMarkingSpeed);
365
  FRIEND_TEST(GCTracerTest, MutatorUtilization);
366
  FRIEND_TEST(GCTracerTest, RecordGCSumHistograms);
367
  FRIEND_TEST(GCTracerTest, RecordMarkCompactHistograms);
368
  FRIEND_TEST(GCTracerTest, RecordScavengerHistograms);
369

370 371 372 373
  struct BackgroundCounter {
    double total_duration_ms;
  };

374 375 376
  // Returns the average speed of the events in the buffer.
  // If the buffer is empty, the result is 0.
  // Otherwise, the result is between 1 byte/ms and 1 GB/ms.
377 378
  static double AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer);
  static double AverageSpeed(const base::RingBuffer<BytesAndDuration>& buffer,
379
                             const BytesAndDuration& initial, double time_ms);
380

381
  void ResetForTesting();
382
  void ResetIncrementalMarkingCounters();
ulan's avatar
ulan committed
383
  void RecordIncrementalMarkingSpeed(size_t bytes, double duration);
384 385
  void RecordMutatorUtilization(double mark_compactor_end_time,
                                double mark_compactor_duration);
386

387 388 389 390 391
  // Overall time spent in mark compact within a given GC cycle. Exact
  // accounting of events within a GC is not necessary which is why the
  // recording takes place at the end of the atomic pause.
  void RecordGCSumCounters(double atomic_pause_duration);

392 393
  double MonotonicallyIncreasingTimeInMs();

394 395 396 397 398 399 400 401
  // Print one detailed trace line in name=value format.
  // TODO(ernstm): Move to Heap.
  void PrintNVP() const;

  // Print one trace line.
  // TODO(ernstm): Move to Heap.
  void Print() const;

402 403
  // Prints a line and also adds it to the heap's ring buffer so that
  // it can be included in later crash dumps.
jfb's avatar
jfb committed
404
  void PRINTF_FORMAT(2, 3) Output(const char* format, ...) const;
405

406
  double TotalExternalTime() const {
407 408 409
    return current_.scopes[Scope::HEAP_EXTERNAL_WEAK_GLOBAL_HANDLES] +
           current_.scopes[Scope::HEAP_EXTERNAL_EPILOGUE] +
           current_.scopes[Scope::HEAP_EXTERNAL_PROLOGUE] +
410
           current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_EPILOGUE] +
411
           current_.scopes[Scope::MC_INCREMENTAL_EXTERNAL_PROLOGUE];
412 413
  }

414
  void FetchBackgroundCounters(int first_scope, int last_scope);
415 416
  void FetchBackgroundMinorGCCounters();
  void FetchBackgroundMarkCompactCounters();
417
  void FetchBackgroundGeneralCounters();
418

419 420 421 422 423 424 425 426 427 428
  // Pointer to the heap that owns this tracer.
  Heap* heap_;

  // Current tracer event. Populated during Start/Stop cycle. Valid after Stop()
  // has returned.
  Event current_;

  // Previous tracer event.
  Event previous_;

429 430
  // Size of incremental marking steps (in bytes) accumulated since the end of
  // the last mark compact GC.
ulan's avatar
ulan committed
431
  size_t incremental_marking_bytes_;
432

433 434 435
  // Duration of incremental marking steps since the end of the last mark-
  // compact event.
  double incremental_marking_duration_;
436

437
  double incremental_marking_start_time_;
438

439
  double recorded_incremental_marking_speed_;
440

441 442
  double average_time_to_incremental_marking_task_ = 0.0;

443 444
  double recorded_embedder_speed_ = 0.0;

445 446 447 448
  // Incremental scopes carry more information than just the duration. The infos
  // here are merged back upon starting/stopping the GC tracer.
  IncrementalMarkingInfos
      incremental_marking_scopes_[Scope::NUMBER_OF_INCREMENTAL_SCOPES];
449

450

451
  // Timestamp and allocation counter at the last sampled allocation event.
452
  double allocation_time_ms_;
453
  size_t new_space_allocation_counter_bytes_;
454
  size_t old_generation_allocation_counter_bytes_;
455
  size_t embedder_allocation_counter_bytes_;
456 457

  // Accumulated duration and allocated bytes since the last GC.
458
  double allocation_duration_since_gc_;
459
  size_t new_space_allocation_in_bytes_since_gc_;
460
  size_t old_generation_allocation_in_bytes_since_gc_;
461
  size_t embedder_allocation_in_bytes_since_gc_;
462

463 464
  double combined_mark_compact_speed_cache_;

hpayer's avatar
hpayer committed
465 466 467
  // Counts how many tracers were started without stopping.
  int start_counter_;

468 469 470 471 472 473
  // Used for computing average mutator utilization.
  double average_mutator_duration_;
  double average_mark_compact_duration_;
  double current_mark_compact_mutator_utilization_;
  double previous_mark_compact_end_time_;

474 475
  base::RingBuffer<BytesAndDuration> recorded_minor_gcs_total_;
  base::RingBuffer<BytesAndDuration> recorded_minor_gcs_survived_;
476 477 478 479 480
  base::RingBuffer<BytesAndDuration> recorded_compactions_;
  base::RingBuffer<BytesAndDuration> recorded_incremental_mark_compacts_;
  base::RingBuffer<BytesAndDuration> recorded_mark_compacts_;
  base::RingBuffer<BytesAndDuration> recorded_new_generation_allocations_;
  base::RingBuffer<BytesAndDuration> recorded_old_generation_allocations_;
481
  base::RingBuffer<BytesAndDuration> recorded_embedder_generation_allocations_;
482 483
  base::RingBuffer<double> recorded_context_disposal_times_;
  base::RingBuffer<double> recorded_survival_ratios_;
484

485
  base::Mutex background_counter_mutex_;
486
  BackgroundCounter background_counter_[Scope::NUMBER_OF_SCOPES];
487
};
488

489 490
}  // namespace internal
}  // namespace v8
491

492
#endif  // V8_HEAP_GC_TRACER_H_