search

guard / listen

The Listen gem listens to file modifications and notifies you about the changes.
https://rubygems.org/gems/listen
MIT License
1.92k stars 246 forks source link

Eats CPU in rails 5.1 app #436

Closed slayer closed 3 years ago

slayer commented 6 years ago

Hi

I have a problem with listen gem with delayed_job - it eats 100% of cpu core

strace log:


30157 fstatfs(10, 0x7efd2ccd1730)       = -1 EBADF (Bad file descriptor)
30157 fcntl(10, F_GETFL)                = -1 EBADF (Bad file descriptor)
30157 fstatfs(10, 0x7efd2ccd1730)       = -1 EBADF (Bad file descriptor)
30157 fcntl(10, F_GETFL)                = -1 EBADF (Bad file descriptor)
30157 fstatfs(10, 0x7efd2ccd1730)       = -1 EBADF (Bad file descriptor)
30157 fcntl(10, F_GETFL)                = -1 EBADF (Bad file descriptor)
... thousands of lines ...
30145 fstatfs(12, 0x7efd2cdd2730)       = -1 EBADF (Bad file descriptor)
30145 fstatfs(12, 0x7efd2cdd2730)       = -1 EBADF (Bad file descriptor)
30145 fstatfs(12, 0x7efd2cdd2730)       = -1 EBADF (Bad file descriptor)
30145 fstatfs(12, 0x7efd2cdd2730)       = -1 EBADF (Bad file descriptor)
30145 fstatfs(12, 0x7efd2cdd2730)       = -1 EBADF (Bad file descriptor)
30145 fstatfs(12, 0x7efd2cdd2730)       = -1 EBADF (Bad file descriptor)
... thousands of lines ...

removing listen gem with commenting out EventedFileUpdateChecker solves the problem

Troubleshooting: 1.

master app@13da9b5b30fe /app $ ruby -v
ruby 2.4.1p111 (2017-03-22 revision 58053) [x86_64-linux]

master app@13da9b5b30fe /app $ LISTEN_GEM_DEBUGGING=1 bundle exec ./bin/delayed_job run
I, [2017-09-28T13:49:34.445526 #713]  INFO -- : Listen loglevel set to: 1
I, [2017-09-28T13:49:34.445631 #713]  INFO -- : Listen version: 3.1.5
I, [2017-09-28T13:49:34.844163 #713]  INFO -- : Record.build(): 0.00013 seconds
I, [2017-09-28T13:49:35.936456 #713]  INFO -- : Starting delayed_job...
I, [2017-09-28T13:49:37.561782 #713]  INFO -- : Record.build(): 1.92696 seconds

  1. There is no effect in output on touch foo 

  2. master app@13da9b5b30fe /app $ LISTEN_GEM_DEBUGGING=2 bundle exec ./bin/delayed_job run                                                 
I, [2017-09-28T13:52:08.080991 #782]  INFO -- : Listen loglevel set to: 0
I, [2017-09-28T13:52:08.081062 #782]  INFO -- : Listen version: 3.1.5
D, [2017-09-28T13:52:08.402276 #782] DEBUG -- : Adapter: considering polling ...
D, [2017-09-28T13:52:08.402365 #782] DEBUG -- : Adapter: considering optimized backend...
I, [2017-09-28T13:52:08.463022 #782]  INFO -- : Record.build(): 0.00014 seconds
D, [2017-09-28T13:52:08.463146 #782] DEBUG -- : Waiting for processing to start...
D, [2017-09-28T13:52:08.621924 #782] DEBUG -- : Adapter: considering polling ...
D, [2017-09-28T13:52:08.621983 #782] DEBUG -- : Adapter: considering optimized backend...
D, [2017-09-28T13:52:09.425362 #782] DEBUG -- : Waiting for processing to start...
I, [2017-09-28T13:52:09.526112 #782]  INFO -- : Starting delayed_job...
I, [2017-09-28T13:52:11.592021 #782]  INFO -- : Record.build(): 2.26683 seconds

    no effect on touch foo2

problem repreduced in host system (linux) and in the docker container ruby: ruby 2.4.1p111 (2017-03-22 revision 58053) [x86_64-linux]

Thanks

printercu commented 6 years ago

I'm facing the same issue, though without delayed job but with spring. After some investigation, I've found that in high-cpu times process has this backtrace:

Click to show ``` ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/pathname.rb:389:in `plus' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/pathname.rb:350:in `+' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:42:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:73:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:67:in `_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:27:in `block in scan' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each_key' ~/.rvm/rubies/ruby-2.4.1/lib/ruby/2.4.0/set.rb:324:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/directory.rb:24:in `scan' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/change.rb:55:in `invalidate' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/base.rb:114:in `_queue_change' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:65:in `block in _process_event' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:60:in `each' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:60:in `_process_event' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/base.rb:42:in `block (2 levels) in configure' ~/.rvm/gems/ruby-2.4.1/gems/rb-fsevent-0.10.2/lib/rb-fsevent/fsevent.rb:77:in `run' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:71:in `_run_worker' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/darwin.rb:55:in `_run' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/adapter/base.rb:78:in `block in start' ~/.rvm/gems/ruby-2.4.1/gems/listen-3.1.5/lib/listen/internals/thread_pool.rb:6:in `block in add' ```

I've found that Change#invalidate is extensively called with ./tmp/cache and ./tmp/uploads which is used to store uploads in tests. It also noticeable that it starts using cpu after test suite finished, as it clears ./tmp/uploads after tests.

By default rails adds ./tmp/restart.txt to watchlist, I've tried removing it but got same result.

felixbuenemann commented 6 years ago

I've also had 150% cpu usage while in the pry rails console in rails 5.1.4 with listen 3.1.5 under ruby 2.4.2 on macOS 10.13.3.

After killing all listen threads with Thread.list[1..-1].each(&:kill) CPU usage went back to normal.

I didn't take a backtrace from the threads, but will do so if I encounter the issue again.

tobycox commented 6 years ago

This is killing me as well. A page reload in development takes around 60 seconds. Here's a flamegraph of a request. 85% of the time spent in listen: image

orenfromberg commented 6 years ago

I removed gem 'listen' from my gemfile, ran bundle lock --update=listen, and the issue went away.

ColinDKelley commented 3 years ago

Please let us know if this problem persists under v3.3 (currently available in v3.3.0.pre.2).