Continuous Profiler: NameError uninitialized constant Datadog::Profiling::Tasks exception

[qcam]

Hi 👋 , I would like to report an issue regarding the beta continuous profiler. We encountered some crash due to the exception mentioned in the title after enabling the profiler. The tracer and other features work as usual before and after removing the profiler setup.

Environment

• Ruby 2.7.3 via 2.7.3-slim-buster.
• Rails 6.0.3.7.
• ddtrace gem (0.49.0)
• google-protobuf (3.17.2)

Our set up

# config/initializers/datadog.rb
  Datadog.configure do |c|
    c.profiling.enabled = true

    # Other configurations removed for brevity.
    # c.use ...
  end

# config.ru
require 'ddtrace/profiling/preload'

# Codes removed for brevity.

run Rails.application

Stacktrace

gems/ddtrace-0.49.0/lib/ddtrace/configuration/components.rb:75:in `build_profiler': uninitialized constant Datadog::Profiling::Tasks (NameError)
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration/components.rb:160:in `initialize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:162:in `new'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:162:in `replace_components!'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:54:in `block in configure'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:138:in `block in safely_synchronize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:136:in `synchronize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:136:in `safely_synchronize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:51:in `configure'
    from gems/ddtrace-0.49.0/lib/ddtrace/contrib/extensions.rb:26:in `configure'
    from config/initializers/datadog_tracer.rb:9:in `<top (required)>'
    from gems/railties-6.0.3.7/lib/rails/engine.rb:666:in `block in load_config_initializer'
// Rest removed for brevity

Please let me know if more info is needed. Thank you 🙏 .

[ivoanjo]

Hey @qcam, thanks a lot for the report. That... is really weird.

• Do you see any other warnings/exceptions in your logs? In particular, I wonder if there's any issue in Datadog::Profiling (ddtrace/profiling.rb).

• Can you reproduce this issue every time? Or does it sometimes work? I'm wondering if this could be a threading issue.

• Are you using puma? Could you share your full stack trace for the issue? I may be able to use that to determine how and when exactly is the loading happening.

---

(My current analysis notes:)

It looks like the require 'ddtrace/profiling/tasks/setup' for some reason did not happen before we tried to run that. But that build_profiler method checks for it:

        def build_profiler(settings, agent_settings)
          return unless Datadog::Profiling.supported? && settings.profiling.enabled

          # Load extensions needed to support some of the Profiling features
          Datadog::Profiling::Tasks::Setup.new.run

And Datadog::Profiling triggers those requires:

    def self.load_profiling
      return false unless supported?
      #...
      require 'ddtrace/profiling/transport/http'
    end

    load_profiling if supported?

So either something failed during #load_profiling or there may be some kind of race during initialization.

[qcam]

Thank you very much for the prompt reply 🙏 . Please see my answers below:

Do you see any other warnings/exceptions in your logs? In particular, I wonder if there's any issue in Datadog::Profiling (ddtrace/profiling.rb).

I tried to find logs around the exception but most of it was Puma failing around build_profiler.

Can you reproduce this issue every time? Or does it sometimes work? I'm wondering if this could be a threading issue.

Yup, it had been consistently failing on our staging environment.

Are you using puma? Could you share your full stack trace for the issue? I may be able to use that to determine how and when exactly is the loading happening.

Yes we are running Puma. Please see the full stack trace below:

gems/ddtrace-0.49.0/lib/ddtrace/configuration/components.rb:75:in `build_profiler': uninitialized constant Datadog::Profiling::Tasks (NameError)
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration/components.rb:160:in `initialize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:162:in `new'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:162:in `replace_components!'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:54:in `block in configure'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:138:in `block in safely_synchronize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:136:in `synchronize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:136:in `safely_synchronize'
    from gems/ddtrace-0.49.0/lib/ddtrace/configuration.rb:51:in `configure'
    from gems/ddtrace-0.49.0/lib/ddtrace/contrib/extensions.rb:26:in `configure'
    from config/initializers/datadog.rb:9:in `<top (required)>'
    from gems/railties-6.0.3.7/lib/rails/engine.rb:666:in `block in load_config_initializer'
    from gems/activesupport-6.0.3.7/lib/active_support/notifications.rb:182:in `instrument'
    from gems/railties-6.0.3.7/lib/rails/engine.rb:665:in `load_config_initializer'
    from gems/railties-6.0.3.7/lib/rails/engine.rb:625:in `block (2 levels) in <class:Engine>'
    from gems/railties-6.0.3.7/lib/rails/engine.rb:624:in `each'
    from gems/railties-6.0.3.7/lib/rails/engine.rb:624:in `block in <class:Engine>'
    from gems/railties-6.0.3.7/lib/rails/initializable.rb:32:in `instance_exec'
    from gems/railties-6.0.3.7/lib/rails/initializable.rb:32:in `run'
    from gems/railties-6.0.3.7/lib/rails/initializable.rb:61:in `block in run_initializers'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:228:in `block in tsort_each'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:350:in `block (2 levels) in each_strongly_connected_component'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:422:in `block (2 levels) in each_strongly_connected_component_from'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:431:in `each_strongly_connected_component_from'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:421:in `block in each_strongly_connected_component_from'
    from gems/railties-6.0.3.7/lib/rails/initializable.rb:50:in `each'
    from gems/railties-6.0.3.7/lib/rails/initializable.rb:50:in `tsort_each_child'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:415:in `call'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:415:in `each_strongly_connected_component_from'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:349:in `block in each_strongly_connected_component'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:347:in `each'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:347:in `call'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:347:in `each_strongly_connected_component'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:226:in `tsort_each'
    from /usr/local/lib/ruby/2.7.0/tsort.rb:205:in `tsort_each'
    from gems/railties-6.0.3.7/lib/rails/initializable.rb:60:in `run_initializers'
    from gems/railties-6.0.3.7/lib/rails/application.rb:363:in `initialize!'
    from config/environment.rb:7:in `<top (required)>'
    from /usr/local/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:83:in `require'
    from /usr/local/lib/ruby/2.7.0/rubygems/core_ext/kernel_require.rb:83:in `require'
    from config.ru:7:in `block in <main>'
    from gems/rack-2.2.3/lib/rack/builder.rb:116:in `eval'
    from gems/rack-2.2.3/lib/rack/builder.rb:116:in `new_from_string'
    from gems/rack-2.2.3/lib/rack/builder.rb:105:in `load_file'
    from gems/rack-2.2.3/lib/rack/builder.rb:66:in `parse_file'
    from gems/puma-5.3.2/lib/puma/configuration.rb:345:in `load_rackup'
    from gems/puma-5.3.2/lib/puma/configuration.rb:267:in `app'
    from gems/puma-5.3.2/lib/puma/runner.rb:143:in `load_and_bind'
    from gems/puma-5.3.2/lib/puma/cluster.rb:349:in `run'
    from gems/puma-5.3.2/lib/puma/launcher.rb:181:in `run'
    from gems/puma-5.3.2/lib/puma/cli.rb:80:in `run'
    from gems/puma-5.3.2/bin/puma:10:in `<top (required)>'
    from bin/puma:23:in `load'
    from bin/puma:23:in `<main>'

Honestly I also found it very weird since I assume 'ddtrace/profiling/preload' would've loaded everything needed before the initializers run.

[ivoanjo]

Thanks for the extra information. I suspect that there may be an issue around the detection of profiler being supported.

I believe I have a tentative fix. Would you be willing to try out a branch I just created with that fix, and that also adds a bit more debugging information?

If so:

1. Change your Gemfile to use

source 'https://s3.amazonaws.com/gems.datadoghq.com/prerelease-v2' do
  gem 'ddtrace', '0.49.0.debug.profiler.loading.141136'
end

... or alternatively you can just pull it off of GitHub:

gem 'ddtrace', git: 'https://github.com/DataDog/dd-trace-rb', branch: 'debug-profiler-loading'

2. Enable extra logging information by setting the DD_TRACE_DEBUG environment variable to true to enable verbose logging.

3. Try re-running your application again. I suspect profiling will now start and work fine.

4. Share the resulting logs here -- they should enable us to determine which part of the profiling support detection is buggy (protobuf? 👀 )

Thanks, and hopefully we'll have you up and running with the profiler very soon 🎉

[qcam]

@ivoanjo many thanks for the help. I will check out the branch.

On the other hand, I also did some investigation on my end and realized that I could replicate this locally.

My previous config.ru, this one crashes even on my computer (we didn't notice the crash previously since we didn't enable Datadog on development environment).

require 'ddtrace/profiling/preload'

require ::File.expand_path('config/environment', __dir__)
run Rails.application

However if this won't:

require ::File.expand_path('config/environment', __dir__)
require 'ddtrace/profiling/preload'

run Rails.application

EDITED

In fact I don't need require 'ddtrace/profiling/preload' at all, for it not to raise the exception.

[ivoanjo]

Thanks for the info! It seems to feed into my theory: there's two moments in the code where we check if profiler is "supported": 1) when loading ddtrace (inside preload) and 2) when starting the profiler after Datadog.configure gets run.

The problem is that the code assumes that both checks 1) and 2) will always reach the same conclusion: either profiler is supported, or profiler is not supported.

In the problematic case, it looks like in your case check 1 decides that profiler is not supported => doesn't load it, and then check 2 decides that it is => assumes it is loaded and tries to start it. And interestingly enough, it seems that if you move the preload require (or remove it entirely), the check 1 actually passes. 😱

I can definitely remove this assumption between both checks (this is one of the things I included with my test branch above), but if you're up to it, I'd still like to take a look at your logs to try to determine what exactly the profiler thinks is wrong to make it fail the first check, as this should work out of the box for you without needing to fiddle with require order 😄

[qcam]

@ivoanjo The profiler is running with latest version of ddtrace (0.49.0) on our staging after changing the line order as mentioned above. I can see CPU profiles flowing in on Datadog. I suspect it has something to do with the Rails code loader (we use Zeitwerk).

Mind if I ask a #lazyweb question of why I didn't see any memory profiling (like I'd see for other languages like Go)? Do I need to configure something else?

Thank you very much for the help! 🙏 Really appreciated.

[ivoanjo]

Glad your issue was fixed, @qcam :)

Mind if I ask a #lazyweb question of why I didn't see any memory profiling (like I'd see for other languages like Go)?

It's definitely coming at some point! We want to reach feature-parity with what we provide for those other languages, but I don't have a timeline for it yet.

Out of curiosity, was your main use case for profiling the memory profiling features? Or is cpu/wall-clock profiling already valuable to you?

Feel free to share any feedback/wins/etc -- we're here for it 🐶