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

Booting puma shows "WARNING: Detected 21 Thread(s) started in app boot" #25259

Closed
mathie opened this issue Jun 3, 2016 · 17 comments · Fixed by #25302
Closed

Booting puma shows "WARNING: Detected 21 Thread(s) started in app boot" #25259

mathie opened this issue Jun 3, 2016 · 17 comments · Fixed by #25302

Comments

@mathie
Copy link

mathie commented Jun 3, 2016

Steps to reproduce

I'm just spinning up a brand new Rails 5 project to kick the tyres and find out what's new. It comes with puma by default (which is awesome, and saves me installing it later!). Straight out of the box, it works fine. Then I follow the Heroku guidelines for configuring it, which essentially boils down to uncommenting the following lines in config/puma.rb:

workers ENV.fetch("WEB_CONCURRENCY") { 2 }
preload_app!
on_worker_boot do
  ActiveRecord::Base.establish_connection if defined?(ActiveRecord)
end

Now when I boot the server, with bundle exec puma -C config/puma.rb I get:

[15663] Puma starting in cluster mode...
[15663] * Version 3.4.0 (ruby 2.3.1-p112), codename: Owl Bowl Brawl
[15663] * Min threads: 5, max threads: 5
[15663] * Environment: development
[15663] * Process workers: 2
[15663] * Preloading application
[15663] * Listening on tcp://0.0.0.0:3000
[15663] ! WARNING: Detected 21 Thread(s) started in app boot:
[15663] ! #<Thread:0x007fe40cd38040@/Users/mathie/.rbenv/versions/2.3.1/lib/ruby/gems/2.3.0/gems/listen-3.0.8/lib/listen/internals/thread_pool.rb:6 sleep> - /Users/mathie/.rbenv/versions/2.3.1/lib/ruby/ge
ms/2.3.0/gems/rb-fsevent-0.9.7/lib/rb-fsevent/fsevent.rb:42:in `select'
[ ... repeated, presumably ~20 more times ...]
[15663] Use Ctrl-C to stop
[15663] - Worker 1 (pid: 15707) booted, phase: 0
[15663] - Worker 0 (pid: 15706) booted, phase: 0

The bit that bothers me is the warning about multiple threads, in case that wasn't clear.

If I were to hazard a guess, I'd say whatever's new in Rails 5 that has introduced the dependency on listen is responsible for this, but I don't know what that is. I also don't know if it needs its threads restarted on_worker_boot or whether Rails already handles that correctly, automatically. It would be ace if, between you and the Puma team, you could figure out how to elide the warning. I don't like ignoring warnings!

Having written this up, I suspect I should be submitting an issue to the Rails repo instead, but since it's now such little effort to do so, I'm going to flag it up here, too. 😄

Expected behavior

I expect a brand new Rails app, configured to run in a popular deployment scenario, to boot with zero warnings.

Actual behavior

In reality, with what I believe is a fairly standard deployment configuration, the Rails app boots with several warnings, as shown above, which is a suboptimal new user experience.

System configuration

Rails version: 5.0.0.rc1

Ruby version: 2.3.1

@mathie
Copy link
Author

mathie commented Jun 5, 2016

I've followed up a bit on puma/puma#991. A summary:

  • The warnings show up when booting the server with bundle exec puma -C config/puma.rb but not when you boot the server with rails s.
  • The difference in my configuration file from the Rails-generated skeleton is that I've uncommented workers, and correspondingly uncommented preload_app! and on_worker_boot.
  • Automatic code reloading is definitely not working with this configuration.

I'm beginning to suspect the answer is not to bother with clustered mode in development, and I've updated my configuration accordingly. 😄

@schneems
Copy link
Member

schneems commented Jun 5, 2016

r? @matthewd threads are coming from the new file watcher related #24990 (comment)

@mathie
Copy link
Author

mathie commented Jun 5, 2016

Feel free to close this as a dupe of #24990. 😄

@e2
Copy link
Contributor

e2 commented Jun 6, 2016

@mathie - not really a dupe.

The large number of threads are because on OSX Listen uses one thread per watched directory.

The ONLY reason for this is because the current implementation of rb-fsevent doesn't expose which watched directory a given event came from. The mapping itself is necessary to unify backend adapters while preparing for other features in Listen (such as symlink support, directory-specific callbacks, etc.).

The ONLY reason this in turn hasn't been improved is because I don't use OSX, so I don't even have Xcode or a way to test things on OSX.

If someone can extend rb-fsevent to report the watched directory with every event, I'll happily get rid of the threads on the Listen side ;)

schneems added a commit to schneems/rails that referenced this issue Jun 6, 2016
We need one file checker booted per process as talked about in rails#24990. Before we do a check to see if any updates have been registered by the listener we first check to make sure that the current process has booted a listener.

We are intentionally not starting a listener when the checker is created. This way we can avoid rails#25259 in which puma warns of multiple threads created before fork. As written the listener for each process will be invoked by the `ActionDispatch::Executor` middleware when the `updated?` method is called. This is the first middleware on the stack and will be invoked before application code is read into memory.

The downside of this approach is that the API is a little less obvious. I.e. that you have to call `updated?` to get the listener to start is not intuitive. We could make `boot!` not private if we want to make the API a little nicer. Alternatively we could boot when the checker is initialized however this reintroduces the puma threads warning, and also means that in cases of `rails server` or when using `preload!` that we have extra threads notifying of changes on a process that we don't care about.

[close rails#24990] [close rails#25259]
schneems added a commit to schneems/rails that referenced this issue Jun 6, 2016
We need one file checker booted per process as talked about in rails#24990. Before we do a check to see if any updates have been registered by the listener we first check to make sure that the current process has booted a listener.

We are intentionally not starting a listener when the checker is created. This way we can avoid rails#25259 in which puma warns of multiple threads created before fork. As written the listener for each process will be invoked by the `ActionDispatch::Executor` middleware when the `updated?` method is called. This is the first middleware on the stack and will be invoked before application code is read into memory.

The downside of this approach is that the API is a little less obvious. I.e. that you have to call `updated?` to get the listener to start is not intuitive. We could make `boot!` not private if we want to make the API a little nicer. Alternatively we could boot when the checker is initialized however this reintroduces the puma threads warning, and also means that in cases of `rails server` or when using `preload!` that we have extra threads notifying of changes on a process that we don't care about.

[close rails#24990] [close rails#25259]
@schneems
Copy link
Member

schneems commented Jun 7, 2016

@e2 thanks for your work and your comments

For our cases we don't really need the names of files or directories changed, we only set one essentially global flag of @updated and then we reload all the code. Looking at my PR #25302 it looks like we need to boot before we fork after all, so that won't be a valid solution for this issue. If we could reduce the number of threads that would help to highlight if/when a new thread gets introduced that wasn't there previously.

Regarding the socket comment, I guess that approach is kind of what puma/unicorn do essentially they self pipe for communication between master and workers. Might be worth looking more into that approach.

@e2
Copy link
Contributor

e2 commented Jun 7, 2016

we only set one essentially global flag of @Updated and then we reload all the code

There's really no overhead which can be avoided, because all APIs pass events (files/dirs) in callbacks.

If we could reduce the number of threads that would help to highlight if/when a new thread gets introduced that wasn't there previously.

To be honest I wouldn't worry about the thread count. It's one thread per watched directory, and not one thread per directory. Most are waiting on a read/select anyway, so they're not busy at all. They are actually somewhat needed on OSX, since MD5 sum checking is needed to detect if directories actually changed.

(HFS has 1-second time resolution, so scanning directories alone is insufficient, and while the rb-fsevent driver can handle file-level changes, the amount of events send per change used to be too much to handle efficiently).

Just saying that Listen is pretty much just a large stack of OSX "workarounds". Even Windows support is ironically simpler (for a change).

So given the 2 approaches:

  1. Ignore the threads. There's only a handful and any alternative to eliminate them is probably a lot more code and work than worth it. They have little overhead.
  2. Socket/process option - superior, but starting another server may be overhead in of itself. It's not like you need tens of forks running in development mode.

Overall, I think running Puma cluster mode in develompent is overkill - and that's the real root cause here.

@schneems
Copy link
Member

schneems commented Jun 8, 2016

I took a stab at using a IO.pipe but got stuck https://gist.github.com/schneems/1e50a78b64a7920c503b319d6112166b. Feel like there might be a way forwards there.

Overall, I think running Puma cluster mode in develompent is overkill - and that's the real root cause here.

This would make the problem much simpler but I do think there are valid reasons for running clusters locally. While i'm not using evented file monitor in production yet, if I happen to be using other code that breaks when used with forks, I would rather find it in development then when it breaks in production.

For example what if we started keeping a whitelist of positive public asset matches in memory for ActiveDispatch::Static for speed. We could update it if/when a file is added on disk. If we did this now without running in cluster locally, it would work in development, but fail in production. A "this doesn't work with forks" may be relatively rare bug but their potential severity warrants caution. If we can get this code working with forks without much overhead I think we should. I'll be around n the foreseeable future to maintain it.

@e2
Copy link
Contributor

e2 commented Jun 8, 2016

I took a stab at using a IO.pipe

I'll gladly check it out when I'm back. (I'm gone for a few days). I'll be happy to extend Listen to support something like this out of the box too. Listen could even maybe detect forking internally and switch to a pipe (or optionally socket) implementation automatically (if allowed by an option).

I do think there are valid reasons for running clusters locally

I agree. Some people do use Listen e.g. for tracking uploaded files - although that's best handled by a single process, because you don't want multiple processes handling the same added files.

Making Listen forkable would be beneficial. Especially since pros like you would save lots of time ;)

@schneems
Copy link
Member

That PR didn't actually solve this problem but this is more of a "not a bug" type of a bug, yes you'll still get a ton of thread warnings, but you should be able to safely ignore them.

schneems added a commit to schneems/rails that referenced this issue Jun 24, 2016
We need one file checker booted per process as talked about in rails#24990. Before we do a check to see if any updates have been registered by the listener we first check to make sure that the current process has booted a listener.

We are intentionally not starting a listener when the checker is created. This way we can avoid rails#25259 in which puma warns of multiple threads created before fork. As written the listener for each process will be invoked by the `ActionDispatch::Executor` middleware when the `updated?` method is called. This is the first middleware on the stack and will be invoked before application code is read into memory.

The downside of this approach is that the API is a little less obvious. I.e. that you have to call `updated?` to get the listener to start is not intuitive. We could make `boot!` not private if we want to make the API a little nicer. Alternatively we could boot when the checker is initialized however this reintroduces the puma threads warning, and also means that in cases of `rails server` or when using `preload!` that we have extra threads notifying of changes on a process that we don't care about.

[close rails#24990] [close rails#25259]
@abinoda
Copy link

abinoda commented May 25, 2018

@schneems @e2 @mathie I was running into this and it stopped happening once I added https://github.com/Shopify/bootsnap

@olivierlacan
Copy link
Contributor

@abinoda But you don't use preload_app!, correct? As far as I can tell this issue only occurs with preload_app! used in conjuction with a on_worker_boot hook that spawns a thread (as establish_connection does).

@abinoda
Copy link

abinoda commented Feb 9, 2019

@olivierlacan I do use preload_app!

@bbozo
Copy link

bbozo commented Jul 31, 2019

I have the same issue, and it's connected to the connection reaper, the trace leads me to:

      class Reaper
        attr_reader :pool, :frequency

        def initialize(pool, frequency)
          @pool      = pool
          @frequency = frequency
        end

        def run
          return unless frequency && frequency > 0
          Thread.new(frequency, pool) { |t, p|
            loop do
              sleep t
              p.reap
              p.flush
            end
          }
        end
      end

do we know if preload_app! is safe to use in production?

@sergey-alekseev
Copy link
Contributor

do we know if preload_app! is safe to use in production?

At the least the aforementioned Heroku article recommends this, so I assume "yes".

I was running into this and it stopped happening once I added

I use bootsnap (1.4.6) and still have this issue.


May be reopen the issue as it's still actual? @schneems

$ heroku local web
9:11:31 AM web.1 |  [84250] Puma starting in cluster mode...
9:11:31 AM web.1 |  [84250] * Version 4.3.3 (ruby 2.7.1-p83), codename: Mysterious Traveller
9:11:31 AM web.1 |  [84250] * Min threads: 5, max threads: 5
9:11:31 AM web.1 |  [84250] * Environment: development
9:11:31 AM web.1 |  [84250] * Process workers: 1
9:11:31 AM web.1 |  [84250] * Preloading application
9:11:36 AM web.1 |  [84250] * Listening on tcp://0.0.0.0:3000
9:11:36 AM web.1 |  [84250] ! WARNING: Detected 5 Thread(s) started in app boot:
9:11:36 AM web.1 |  [84250] ! #<Thread:0x00007f9fa3e75258 .rvm/gems/ruby-2.7.1/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:38 sleep_forever> - .rvm/gems/ruby-2.7.1/gems/concurrent-ruby-1.1.6/lib/concurrent-ruby/concurrent/atomic/ruby_thread_local_var.rb:40:in `pop'
9:11:36 AM web.1 |  [84250] ! #<Thread:0x00007f9fa7614b00 .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/internals/thread_pool.rb:6 sleep> - .rvm/gems/ruby-2.7.1/gems/rb-fsevent-0.10.3/lib/rb-fsevent/fsevent.rb:44:in `select'
9:11:36 AM web.1 |  [84250] ! #<Thread:0x00007f9fa7614808 .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/internals/thread_pool.rb:6 sleep> - .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/event/config.rb:19:in `sleep'
9:11:36 AM web.1 |  [84250] ! #<Thread:0x00007f9fa4a0c670 .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/internals/thread_pool.rb:6 sleep> - .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/record/entry.rb:24:in `lstat'
9:11:36 AM web.1 |  [84250] ! #<Thread:0x00007f9fa4a0c440 .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/internals/thread_pool.rb:6 sleep> - .rvm/gems/ruby-2.7.1/gems/listen-3.1.5/lib/listen/event/config.rb:19:in `sleep'
9:11:36 AM web.1 |  [84250] Use Ctrl-C to stop
9:11:36 AM web.1 |  [84250] - Worker 0 (pid: 84256) booted, phase: 0

Rails 6.0.2.2

@h0jeZvgoxFepBQ2C
Copy link

Upgrading concurrent-ruby to 1.1.7 solves it for some people: ruby-concurrency/concurrent-ruby#868

But not for me... I still have this warning on Ruby 2.6.6 and Rails 5.2.3.4 :(

@danielbonnell
Copy link

I can confirm that I too have this issue on Rails 6.0.3.3 with concurrent-ruby 1.1.7 using preload_app! and on_worker_boot. I have been getting periodic ConnectionPool::TimeoutErrors and I wonder if they're somehow related to this?

@ghost
Copy link

ghost commented Sep 22, 2020

For those seeing the "reaper sleep" warning, I think this is harmless. My Puma configuration includes

if num_workers > 1 then
  preload_app!
  before_fork do
    ActiveRecord::Base.connection_pool.disconnect!
  end
  on_worker_boot do
    ActiveRecord::Base.establish_connection
  end
end

and I get the reaper-sleep warning in the staging (but not the development) environment (not sure why). I modify the connection_pool,rb reaper loop to read

        def run
          return unless frequency && frequency > 0
          Thread.new(frequency, pool) { |t, p|
            loop do
              sleep t
              p.reap
              p.flush
              puts format('[%i] quack', Process.pid)
            end
          }
        end

Then

bundle exec puma --config config/puma.rb -e staging 

yields

[19924] Puma starting in cluster mode...
[19924] * Version 3.12.4 (ruby 2.5.7-p206), codename: Llamas in Pajamas
[19924] * Min threads: 1, max threads: 1
[19924] * Environment: staging
[19924] * Process workers: 4
[19924] * Preloading application
[19924] * Listening on tcp://0.0.0.0:3000
[19924] ! WARNING: Detected 1 Thread(s) started in app boot:
[19924] ! #<Thread:0x0000560485c7dd70@.../connection_pool.rb:299 sleep> - .../connection_pool.rb:301:in `sleep'
[19924] Use Ctrl-C to stop
[19924] - Worker 0 (pid: 19957) booted, phase: 0
[19924] - Worker 1 (pid: 19964) booted, phase: 0
[19924] - Worker 2 (pid: 19975) booted, phase: 0
[19924] - Worker 3 (pid: 19990) booted, phase: 0
[19924] quack
[19957] quack
[19964] quack
[19975] quack
[19990] quack

so it seems that reaper for the bottom-level process (19924) persists and is checking for stale connections in what is now an inactive pool, while the workers each have their own reaper doing the same for their active pools. I guess it would be tidier to have some mechanism for terminating the bottom-level reaper thread,

ActiveRecord::Base.connection_pool.kill_reaper!

but that would seem low priority.

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

Successfully merging a pull request may close this issue.

10 participants