Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

How can I fix "WARNING: Detected 2 Thread(s) started in app boot:" with concurrent-ruby? #2237

Closed
ndbroadbent opened this issue Apr 27, 2020 · 10 comments
Labels

Comments

@ndbroadbent
Copy link

ndbroadbent commented Apr 27, 2020

  • Puma: 4.3.3
  • Rails: 5.2.4.2
  • Ruby: 2.6.5

I've been trying to get rid of this in my logs WARNING: Detected 2 Thread(s) started in app boot:.

Here are the logs when I start puma:

(I edited this line to print the full backtrace.)

[69210] ! WARNING: Detected 2 Thread(s) started in app boot:
[69210] ! #<Thread:0x00007ffa9f28e500@/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:41 sleep_forever> - /Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:43:in `pop'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:43:in `block in <class:RubyThreadLocalVar>'
[69210] ! #<Thread:0x00007ffab82b49a8@/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-5.2.4.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:303 sleep> - /Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-5.2.4.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:305:in `sleep'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-5.2.4.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:305:in `block (2 levels) in run'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-5.2.4.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:304:in `loop'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activerecord-5.2.4.2/lib/active_record/connection_adapters/abstract/connection_pool.rb:304:in `block in run'

I edited this file: /Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:

    ...
    QUEUE  = Queue.new
    puts "Ruby thread caller"
    puts "------------------------------------------------------------------"
    puts caller
    THREAD = Thread.new do
    ...

Output:

[69210] * Preloading application
Loading Rails application...
Ruby thread caller
------------------------------------------------------------------
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:8:in `<module:Concurrent>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:4:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/thread_local_var.rb:2:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/thread_local_var.rb:2:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/reentrant_read_write_lock.rb:5:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/reentrant_read_write_lock.rb:5:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomics.rb:8:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomics.rb:8:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent.rb:6:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent.rb:6:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.2/lib/active_support/logger_silence.rb:5:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.2/lib/active_support/logger_silence.rb:5:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.2/lib/active_support/logger.rb:3:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.2/lib/active_support/logger.rb:3:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.2/lib/active_support.rb:29:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/activesupport-5.2.4.2/lib/active_support.rb:29:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/railties-5.2.4.2/lib/rails.rb:7:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/railties-5.2.4.2/lib/rails.rb:7:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/railties-5.2.4.2/lib/rails/all.rb:3:in `require'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/railties-5.2.4.2/lib/rails/all.rb:3:in `<top (required)>'
/Users/myuser/code/myapp/config/application.rb:7:in `require'
/Users/myuser/code/myapp/config/application.rb:7:in `<top (required)>'
/Users/myuser/code/myapp/config/environment.rb:4:in `require_relative'
/Users/myuser/code/myapp/config/environment.rb:4:in `<top (required)>'
config.ru:5:in `require_relative'
config.ru:5:in `block in <main>'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rack-2.2.2/lib/rack/builder.rb:116:in `eval'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rack-2.2.2/lib/rack/builder.rb:116:in `new_from_string'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rack-2.2.2/lib/rack/builder.rb:105:in `load_file'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/rack-2.2.2/lib/rack/builder.rb:66:in `parse_file'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/lib/puma/configuration.rb:321:in `load_rackup'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/lib/puma/configuration.rb:246:in `app'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/lib/puma/runner.rb:155:in `load_and_bind'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/lib/puma/cluster.rb:413:in `run'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/lib/puma/launcher.rb:172:in `run'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/lib/puma/cli.rb:80:in `run'
/Users/myuser/.rbenv/versions/2.6.5/lib/ruby/gems/2.6.0/gems/puma-4.3.3/bin/puma:10:in `<top (required)>'
/Users/myuser/.rbenv/versions/2.6.5/bin/puma:23:in `load'
/Users/myuser/.rbenv/versions/2.6.5/bin/puma:23:in `<main>'

/Users/myuser/code/myapp/config/application.rb:7 is just:

require 'rails/all'

The problem seems to be that bootsnap requires concurrent-ruby when the app boots (UPDATE: I was getting a lot of bootsnap lines in the backtrace so I turned it off, but the warning is still happening.)

lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb is required, and this creates a new Thread immediately when the class is loaded:

module Concurrent
  class RubyThreadLocalVar < AbstractThreadLocalVar
    FREE   = []
    LOCK   = Mutex.new
    ARRAYS = {} # used as a hash set
    @@next = 0
    QUEUE  = Queue.new
    THREAD = Thread.new do
      while true
      ...

(Thread.new is called while the class is being defined, and not inside a method.)

Does that mean that this RubyThreadLocalVar thread is not working properly inside the puma workers? I haven't noticed any problems with my app in production, but now I'm concerned that something isn't working properly.

Thanks for your time!

@ndbroadbent ndbroadbent changed the title How can I fix "WARNING: Detected 2 Thread(s) started in app boot:" with bootsnap and concurrent-ruby? How can I fix "WARNING: Detected 2 Thread(s) started in app boot:" with ~bootsnap and~ concurrent-ruby? Apr 27, 2020
@ndbroadbent ndbroadbent changed the title How can I fix "WARNING: Detected 2 Thread(s) started in app boot:" with ~bootsnap and~ concurrent-ruby? How can I fix "WARNING: Detected 2 Thread(s) started in app boot:" with concurrent-ruby? Apr 27, 2020
@ndbroadbent
Copy link
Author

I've also opened an issue on concurrent-ruby: ruby-concurrency/concurrent-ruby#868, to see if they have any thoughts

@dentarg
Copy link
Member

dentarg commented Apr 27, 2020

I think you need to show your Puma config and maybe also the full code to reproduce this, for someone to be able to advise you properly.

@nateberkopec
Copy link
Member

I'm interested to hear what the concurrent-ruby people think. If they weren't creating threads at require-time, this wouldn't be an issue.

@dwishrq
Copy link

dwishrq commented Jul 23, 2020

As a possible (temporary?) workaround, I noticed that I get this warning on startup using v1.1.6 of concurrent-ruby (as the original post above also did) but when I downgraded to 1.1.5 the warning went away.

@andrewhavens
Copy link

andrewhavens commented Jul 23, 2020

I'm getting the same warning with the same (slightly newer) gems. My app is also running on Heroku. I wonder if there are any problems with my current Puma config:

require 'fileutils'
require 'barnes'

threads_count = ENV.fetch("RAILS_MAX_THREADS") { 5 }
threads threads_count, threads_count
port ENV.fetch("PORT") { 3000 }
environment ENV.fetch("RAILS_ENV") { "development" }

if ENV.fetch("RAILS_ENV") { "development" } == 'development'
  worker_timeout 3600
end

workers ENV.fetch("WEB_CONCURRENCY") { 4 }

preload_app!

before_fork do
  FileUtils.touch('/tmp/app-initialized')
  ActiveRecord::Base.connection_pool.disconnect! if defined?(ActiveRecord)
  Barnes.start
end

on_worker_boot do
  ActiveRecord::Base.establish_connection if defined?(ActiveRecord)
end

plugin :tmp_restart

Logs:

 Puma starting in cluster mode...
 * Version 3.12.4 (ruby 2.6.6-p146), codename: Llamas in Pajamas
 * Min threads: 2, max threads: 2
 * Environment: production
 * Process workers: 4
 * Preloading application
** [NewRelic] ...
 ! WARNING: Detected 2 Thread(s) started in app boot:
 ! #<Thread:0x00005561cab0f230@/app/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:38 sleep_forever> - /app/vendor/bundle/ruby/2.6.0/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:40:in `pop'
 ! #<Thread:0x00005561cca752c8@/app/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:299 sleep> - /app/vendor/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:301:in `sleep'

@samholst
Copy link

samholst commented Jul 28, 2020

I get the same errors for concurrent and activerecord but in Rails 6 and using Ruby 2.7.0 on AWS Ubuntu 16.04.

@nateberkopec
Copy link
Member

Looks like this will be fixed in the next version of concurrent-ruby: ruby-concurrency/concurrent-ruby#868

@dentarg
Copy link
Member

dentarg commented Aug 8, 2020

Looks like this will be fixed in the next version of concurrent-ruby: ruby-concurrency/concurrent-ruby#868

Which has been released now: https://github.com/ruby-concurrency/concurrent-ruby/blob/v1.1.7/CHANGELOG.md#release-v117-6-august-2020, https://rubygems.org/gems/concurrent-ruby/versions

I can confirm that the new concurrent-ruby version got rid of the warning where I saw it.

@h0jeZvgoxFepBQ2C
Copy link

I'm still seeing this with Ruby 2.6.6 and Rails 5.2.4.3:

● puma_app-admin.service - Puma HTTP Server
   Loaded: loaded (/etc/systemd/system/puma_app-admin.service; enabled; vendor preset: enabled)
   Active: active (running) since Tue 2020-09-08 21:26:14 CEST; 23min ago
  Process: 31911 ExecReload=/home/user/.rbenv/bin/rbenv exec bundle exec --keep-file-descriptors
pumactl -F /home/user/apps/app-admin/shared/puma.rb restart (code=exited, status=0/SUCCESS)
 Main PID: 25736 (ruby)
    Tasks: 26
   Memory: 399.2M
      CPU: 2min 2.902s
   CGroup: /system.slice/puma_app-admin.service
           ├─25736 puma 4.3.5 (unix:///home/user/apps/app-admin/shared/sockets/puma.app-admin
.sock?backlog=8000) [20200908194103]
           ├─32431 puma: cluster worker 0: 25736 [20200908194103]

           └─32443 puma: cluster worker 1: 25736 [20200908194103]


Sep 08 21:26:15 appake20 rbenv[25736]: [25736] * Environment: production
Sep 08 21:26:15 appake20 rbenv[25736]: [25736] * Process workers: 2
Sep 08 21:26:15 appake20 rbenv[25736]: [25736] * Preloading application
Sep 08 21:26:22 appake20 rbenv[25736]: [DEPRECATION] requiring "RMagick" is deprecated. Use "rmagic
k" instead
Sep 08 21:26:49 appake20 rbenv[25736]: [25736] * Activated unix:///home/user/apps/app-admin/s
hared/sockets/puma.app-admin.sock?backlog=8000
Sep 08 21:26:49 appake20 rbenv[25736]: [25736] ! WARNING: Detected 1 Thread(s) started in app boot:
Sep 08 21:26:49 appake20 rbenv[25736]: [25736] ! #<Thread:0x000000000a6b71c8@/home/user/apps/fl
ave-admin/shared/bundle/ruby/2.6.0/gems/activerecord-5.2.4.3/lib/active_record/connection_adapters/ab
stract/connection_pool.rb:299 sleep> - /home/user/apps/app-admin/shared/bundle/ruby/2.6.0/gems/
activerecord-5.2.4.3/lib/active_record/connection_adapters/abstract/connection_pool.rb:301:in `sleep'

Even though I have concurrent-ruby 1.1.7 in my Gemfile.lock?

@dentarg
Copy link
Member

dentarg commented Sep 9, 2020

@h0jeZvgoxFepBQ2C That's coming from activerecord: https://github.com/rails/rails/blob/v5.2.4.3/activerecord/lib/active_record/connection_adapters/abstract/connection_pool.rb#L301

...and I can see that you've found the related issues (rails/rails#37066, rails/rails#25259) on rails/rails :) I guess you could try open a new issue there, or maybe better, search/ask in their forum: https://discuss.rubyonrails.org/

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

7 participants