[NO-TICKET] Redesign GC profiling to add timeline support and reduce overhead

[ivoanjo]

What does this PR do?

This PR redesigns the garbage collection profiling feature to add support for timeline and reduce its overhead.

Here's how it looks in timeline mode:

Here's how it looks in flamegraph mode:

A TL;DR description of how it works now is below:

1. Wiring it up

• Ruby exposes native-level tracepoint events for when it starts/stops doing GC (RUBY_INTERNAL_EVENT_GC_ENTER/RUBY_INTERNAL_EVENT_GC_EXIT).
• Inside the CpuAndWallTimeWorker we create a tracepoint that listens for these events and calls the on_gc_start and on_gc_finish events on the ThreadContext collector.
• The RUBY_INTERNAL_EVENT_GC_ENTER/RUBY_INTERNAL_EVENT_GC_EXIT tracepoint events are emitted while Ruby is doing GC, which means we can't allocate anything. The code we use is thus built to not allocate anything.
• We can't do all the work we want in on_gc_finish because we can't allocate anything, so that function returns a flag that tells the CpuAndWallTimeWorker to call sample_after_gc as soon as the GC finishes.

2. Tracking

• When a thread starts doing GC (on_gc_start), we record its current cpu-time and wall-time.
• When a thread stops doing GC (on_gc_finish), we record how much cpu-time and wall-time elapsed.
• When sample_after_gc gets called, we turn the data recorded above + some metadata from Ruby into a sample event to represent GC as a fake Garbage Collection thread.

3. Overhead

• To avoid impacting applications a lot, the Ruby GC works incrementally. That is, rather than doing a full GC (marking, sweeping) in a single step, Ruby breaks this into smaller steps.
• We get told about every smaller step: we get a pair of on_gc_start/on_gc_finish calls for each step.
• In the past, we always called sample_after_gc after every on_gc_finish to record the GC. This was a big source of overhead: in a sample application that allocates as much as possible in a loop I was able to observe more than 50k calls to on_gc_start/on_gc_finish per second, which obviously would represent a lot of overhead if we create one GC sample for each of these.
• To avoid this overhead, we coalesce/accumulate the cpu/wall-time from multiple calls to on_gc_start/on_gc_finish and only create a sample to represent this data from time to time (default is every 10ms or every full GC cycle, whatever happens first).

Compared to the old implementation, here's what changed:

• Garbage collection events get attributed to a placeholder "Garbage Collection" thread
• We no longer record "Garbage Collection" samples on the thread that triggered GC. (And thus no longer include the stack of that thread when recording GC information). This enabled a nice cleanup of the code in the stack collector
• GCs across several threads can be included in the same sample
• Timeline support is included
• Extra metadata about the GC can be seen in the timeline
• Overhead is lowered, even during heavy periods of GC action

Motivation:

I worked on this as part of the Profiler R&D week. I've been wanting to go back and fix the problems with the gc profiling implementation for a long time :)

Additional Notes:

I'm opening this PR on top of @AlexJF's #3281 because otherwise both were going to conflict, given the changes to the stack recorder. The two PRs are otherwise completely independent.

I'll wait until #3281 is merged to master to merge this PR as well.

How to test the change?

Test coverage is included.

During development, this tiny benchmark was useful:

require 'benchmark/ips'
require 'ddtrace'

puts RUBY_DESCRIPTION

Datadog.configure do |c|
  c.profiling.enabled = true
  c.profiling.advanced.allocation_counting_enabled = false
  c.telemetry.enabled = false
end

class Potato
  def initialize(val)
    @potato = val
  end
end

Benchmark.ips do |x|
  x.config(time: 10, warmup: 2)

  x.report("DD_PROFILING_FORCE_ENABLE_GC=#{ENV['DD_PROFILING_FORCE_ENABLE_GC']} Potato.new(10)", "Potato.new(10)")

  x.compare!
end

For Datadog employees:

• If this PR touches code that signs or publishes builds or packages, or handles
  credentials of any kind, I've requested a review from @DataDog/security-design-and-guidance.
• This PR doesn't touch any of that.

[AlexJF]

I don't get the need for both? Is this a backend limitation (i.e., why doesn't it just parse wall_time_ns values directly)? Why does it (seem to) work fine for non-GC frames?

[ivoanjo]

This is a great question. I've pushed a note in 391db52 to address this:

      // This event gets both a regular cpu/wall-time duration, as a normal cpu/wall-time sample would, as well as a
      // timeline duration.
      // This is done to enable two use-cases:
      // * regular cpu/wall-time makes this event show up as a regular stack in the flamegraph
      // * the timeline duration is used when the event shows up in the timeline

In practice, we could change the backend to use get the cpu/wall-time timeline duration and use it for the timeline event, but doing it this way keeps us consistent with what other runtimes do for timeline (e.g. dotnet), and thus makes it easy to share code across them.

[codecov-commenter]

Codecov Report

Attention: 1 lines in your changes are missing coverage. Please review.

Comparison is base (56745c9) 98.22% compared to head (807a519) 98.23%.
Report is 34 commits behind head on alexjf/prof-8667-heap-profiling-part1.

Files	Patch %	Lines
...atadog/profiling/collectors/thread_context_spec.rb	99.16%	1 Missing ⚠️

Additional details and impacted files

@@                          Coverage Diff                           @@
##           alexjf/prof-8667-heap-profiling-part1    #3313   +/-   ##
======================================================================
  Coverage                                  98.22%   98.23%           
======================================================================
  Files                                       1253     1253           
  Lines                                      72794    72774   -20     
  Branches                                    3419     3414    -5     
======================================================================
- Hits                                       71504    71486   -18     
+ Misses                                      1290     1288    -2     

☔ View full report in Codecov by Sentry.
📢 Have feedback on the report? Share it here.

[AlexJF]

Still LGTM, 👍 Heads-up on incoming conflicts 😄

[marcotc]

Awesome work, @ivoanjo!

[ivoanjo]

Update: This PR was originally opened on top of #3281 but there were a number of changes to that branch, so I chose to rebase on top of master and force-push.

The rebase was clean other than a manual fix in profiling/component.rb + a new spec from master that needed updating ( bfdd1b7 ). No other changes were made.

[ivoanjo]

Thanks y'all for the help and reviews. Merging away!