Correctly close all StatsD clients #1429

marcotc · 2021-03-24T23:12:13Z

The new version of dogstatsd-ruby, v4.9.0, creates a background thread, which needs to be properly closed by calling the previously existing method #close.

In a few parts of our tracer and test suite we fail to call #close on all instances of the StatsD client. This PR addresses that.

The configuration of Runtime Metric and Health Metrics components reuse the existing statsd client from previous configurations, thus directly manipulating the lifecycle of statsd. This doesn't seem like a natural relationship, as the statsd client is nested inside the Runtime Metrics Worker object, and trying to manipulate its lifecycle from outside creates a few complications. These are documented inline. This also gives us another reason to "flatten" our internal tracer components, in this case the statsd client, as that will restore the natural ownership of its lifecycle to the global Components manager.

marcotc · 2021-03-26T17:08:30Z

dogstatsd-ruby 4.9.0 was recently removed, but 5.0.0 will be released shortly with the change changes (just different version number, due to breaking API change).
Even though it's a major release, the breaking changes do not affect ddtrace's statsd calls.

marcotc · 2021-04-07T23:44:38Z

The build failure is now due to DataDog/dogstatsd-ruby#175

marcotc · 2021-04-08T00:35:45Z

spec/spec_helper.rb

@@ -91,6 +91,10 @@
  # with the test execution.
  config.around do |example|
    example.run.tap do
+      # Background thread leak checking is currently too verbose for CI,
+      # slowing down builds to the point of causing CircleCI timeouts.


JRuby builds are timing out: https://app.circleci.com/pipelines/github/DataDog/dd-trace-rb/3161/workflows/2c837108-5272-42dc-841a-694d76e30b60/jobs/126109
And build console output is over 400MiB 😢

400mb of feedback is clearly not helpful. Rather than skipping it entirely in CI, could we count how many errors we've emitted, and after some number, we just stop reporting them, and just include a line at the end of the report with how many errors?

Famously, valgrind does the same:

More than 10000000 total errors detected. I'm not reporting any more. Final error counts will be inaccurate. Go fix your program!

marcotc · 2021-04-08T00:36:47Z

spec/support/tracer_helpers.rb

      @tracer.shutdown!
      @tracer = nil
    end
+
+    Datadog.send(:reset!)


Borrowed from https://github.com/DataDog/dd-trace-rb/pull/1421/files#diff-d2e9b89d3ad8e619ce1d915526eef5288a19e54add48fedafed37f18907b872b

marcotc · 2021-04-08T00:37:27Z

Gemfile

-gem 'dogstatsd-ruby', '>= 3.3.0'
+
+# Unpin when https://github.com/DataDog/dogstatsd-ruby/pull/175 is released
+gem 'dogstatsd-ruby', git: 'https://github.com/marcotc/dogstatsd-ruby.git', ref: 'dd7ef5dfe4ff9336ec27dc3736e0bbd2acede767'


I don't have push access to DataDog/dogstatsd-ruby, so my fork it is for now.

This is reasonable, given that it's only used for testing.

marcotc · 2021-04-08T00:41:03Z

I decided to make this PR pass our build, instead of breaking down all requirements to have a green CI over 3 CI failing PRs.

The first commit contains the main changes. The next two are separate issues that are required for CI to pass. I'm trusting that git history will be enough to help us separate these changes if we need to look back into this changeset.

ivoanjo

Thanks for this 🙇 . I'm a bit concerned with the potential race during close, and hence as much as it pains me, I'll hold off on pressing the merge button >_>

ivoanjo · 2021-04-08T09:04:53Z

Gemfile

-gem 'dogstatsd-ruby', '>= 3.3.0'
+
+# Unpin when https://github.com/DataDog/dogstatsd-ruby/pull/175 is released
+gem 'dogstatsd-ruby', git: 'https://github.com/marcotc/dogstatsd-ruby.git', ref: 'dd7ef5dfe4ff9336ec27dc3736e0bbd2acede767'


This is reasonable, given that it's only used for testing.

ivoanjo · 2021-04-08T09:19:17Z

lib/ddtrace/configuration/components.rb

        runtime_metrics.enabled = false
-        runtime_metrics.stop(true)
+        runtime_metrics.stop(true, close_metrics: false)


Minor: Is this enabled = false needed? Wouldn't stop work even if enabled was still true?

It doesn't seem like it's strictly required. This enabled is part of the worker pooling/threading/loop pattern, so it's tricky to be sure, but as far as I can reason, it's not actually needed to properly shut down runtime_metrics here.

ivoanjo · 2021-04-08T09:28:38Z

lib/ddtrace/workers/runtime_metrics.rb

+      def stop(*args, close_metrics: true)
+        @metrics.close if close_metrics
+        super(*args)
+      end


Is this safe? We're calling .close on something that is shared with a background thread, so if Runtime::Metrics or Datadog::Statsd are not thread-safe, this can be problematic.

I was thinking that perhaps we can have an easy fix by moving the close after the call to super -- then we know the background activity has stopped, so it should be a safer time to close the resource?

I don't have a strong opinion here.
It's rather hard to reason about this worker class, as there are a few layers of pooling/threading/loop that interweave with each other... I always get lost in the process. It seems like something we'd want to "flatten" in the future.

I'll give it a shot and see if works correctly with close after super.

Yes please! I think the module approach right now makes the combined objects have a lot of behavior and weird cases. I'd really like to move to using composition for these workers, e.g. two objects which communicate with clear APIs, rather than the current approach of having a lot of behavior injected into the class via a combination of include and prepend.

ivoanjo · 2021-04-08T09:33:40Z

spec/ddtrace_integration_spec.rb

      it 'does not error on reporting health metrics' do
-        expect(Datadog.health_metrics.queue_accepted(1)).to be_a(Integer)
+        expect(Datadog.health_metrics.queue_accepted(1)).to be(true)
      end


Minor: Perhaps to be_truthy would be a bit more flexible here?

ivoanjo · 2021-04-08T09:37:15Z

spec/spec_helper.rb

@@ -91,6 +91,10 @@
  # with the test execution.
  config.around do |example|
    example.run.tap do
+      # Background thread leak checking is currently too verbose for CI,
+      # slowing down builds to the point of causing CircleCI timeouts.


400mb of feedback is clearly not helpful. Rather than skipping it entirely in CI, could we count how many errors we've emitted, and after some number, we just stop reporting them, and just include a line at the end of the report with how many errors?

Famously, valgrind does the same:

More than 10000000 total errors detected. I'm not reporting any more. Final error counts will be inaccurate. Go fix your program!

ivoanjo · 2021-04-08T09:39:03Z

spec/spec_helper.rb

+  # DEV: we have to use an explicit `block`, argument
+  # instead of the implicit `yield` call, as calling
+  # `yield` here crashes the Ruby VM in Ruby < 2.2.
+  def initialize(*args, &block)
    caller_ = caller
    wrapped = lambda do |*thread_args|
      Thread.current.instance_variable_set(:@caller, caller_)
-      yield(*thread_args)
+      block.call(*thread_args) # rubocop:disable Performance/RedundantBlockCall
    end
    wrapped.ruby2_keywords if wrapped.respond_to?(:ruby2_keywords, true)


I like how this method is like the history of Ruby bugs and features. "Let's just wrap it" turns into "oh but this crashes on old rubies, and we need to use correct delegation on modern rubies...". Ahh computers...

delner

Looks good. 👍

ivoanjo · 2021-04-12T07:47:48Z

spec/spec_helper.rb

+        unless $background_thread_leak_warned ||= false
+          warn RSpec::Core::Formatters::ConsoleCodes.wrap(
+            "Too many leaky thread reports! Suppressing further reports.\n" \
+            'Consider addressing the previously reported leaks before proceeding.',
+            :red
+          )
+
+          $background_thread_leak_warned = true
+        end


It may be worth adding a note at the end of the test suite execution too, otherwise if you ignore the output of running a lot of tests (which to be honest, is what I do with such a noisy output as we have right now), you may miss that we still have a bunch of those to fix :)

marcotc mentioned this pull request Mar 25, 2021

Lint changes for latest Rubocop minor release #1430

Merged

marcotc self-assigned this Mar 25, 2021

marcotc added dev/refactor Involves refactoring existing components core Involves Datadog core libraries labels Mar 25, 2021

marcotc marked this pull request as ready for review April 7, 2021 23:44

marcotc requested a review from a team April 7, 2021 23:44

marcotc force-pushed the fix-statsd branch from 54124f0 to 1909606 Compare April 7, 2021 23:50

marcotc added 3 commits April 7, 2021 17:32

Close all StatsD clients

174c92a

Pin dogstatsd-ruby due to concurrency shutdown issue

aa43b1b

Disable thread check output in CI

7f937ab

marcotc force-pushed the fix-statsd branch from 18cf600 to 7f937ab Compare April 8, 2021 00:34

marcotc commented Apr 8, 2021

View reviewed changes

ivoanjo reviewed Apr 8, 2021

View reviewed changes

marcotc added 6 commits April 9, 2021 10:14

Revert Gemfile change as public version was published

15aff01

Add test combination for old dogstastd

74b1f5d

Address comments

643ffef

Fix RuntimeMetrics#stop failures

7a1ae73

Sacrifice for the linting gods ☠️

f0cccf1

Better output differentiation for leaky thread report

de47986

marcotc requested review from ivoanjo and delner April 9, 2021 18:56

delner approved these changes Apr 9, 2021

View reviewed changes

marcotc merged commit b1a159f into master Apr 9, 2021

marcotc deleted the fix-statsd branch April 9, 2021 20:46

github-actions bot added this to the 0.48.0 milestone Apr 9, 2021

ivoanjo reviewed Apr 12, 2021

View reviewed changes

marcotc mentioned this pull request May 3, 2021

Memory leak with dogstatsd-ruby 5.0.1 on Sidekiq workers #1491

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Correctly close all StatsD clients #1429

Correctly close all StatsD clients #1429

marcotc commented Mar 24, 2021 •

edited

marcotc commented Mar 26, 2021

marcotc commented Apr 7, 2021 •

edited

marcotc Apr 8, 2021

ivoanjo Apr 8, 2021

marcotc Apr 8, 2021

marcotc Apr 8, 2021

ivoanjo Apr 8, 2021

marcotc commented Apr 8, 2021

ivoanjo left a comment

ivoanjo Apr 8, 2021

ivoanjo Apr 8, 2021

marcotc Apr 9, 2021

ivoanjo Apr 8, 2021

marcotc Apr 9, 2021

ivoanjo Apr 12, 2021

ivoanjo Apr 8, 2021

ivoanjo Apr 8, 2021

ivoanjo Apr 8, 2021

delner left a comment

ivoanjo Apr 12, 2021

Correctly close all StatsD clients #1429

Correctly close all StatsD clients #1429

Conversation

marcotc commented Mar 24, 2021 • edited

marcotc commented Mar 26, 2021

marcotc commented Apr 7, 2021 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

marcotc commented Apr 8, 2021

ivoanjo left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

delner left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

marcotc commented Mar 24, 2021 •

edited

marcotc commented Apr 7, 2021 •

edited