Skip to content

Commit

Permalink
[WIP] Add RailsRequestMonitor
Browse files Browse the repository at this point in the history
This peers into the private APIs of `ActiveSupport` and
`ActionController::LogSubscriber` to check the status of the queued up
events for 'process_action.action_controller', and see if any are larger
than 10 seconds.  If they are, it will report them to the Rails.logger.

Usage
-----

This can be instrumented in many ways, but the easiest is via
config/initializer:

    # config/initializers/request_watcher.local.rb
    if ENV['WATCH_FOR_LONG_REQUESTS']
      require 'workers/rails_request_monitor'

      Thread.new do
        loop do
          sleep 10
          RailsRequestMonitor.log_long_running_requests
        end
      end.abort_on_exception = true
    end

And running a development server by running:

    $ WATCH_FOR_LONG_REQUESTS=1 bin/rails s

This will check every 10 seconds, and when long requests are found, they
will be output to the Rails.log on level WARN.

This can also be instrumented in MiqWebServerRunnerMixin with relative
ease:

    # app/models/mixins/miq_web_server_runner_mixin.rb

    +
    + def do_heartbeat_work
    +   RailsRequestMonitor.log_long_running_requests
    + end

Or anywhere that it makes sense (signal handlers, etc.)

TODO
----

- Update to 1.minute instead of 10.seconds (for quicker testing)
- Tests
- Instrument in `MiqWebServerRunnerMixin` (new commit?)
  • Loading branch information
NickLaMuro committed Sep 7, 2018
1 parent 26bf79c commit fb7f4bd
Showing 1 changed file with 40 additions and 0 deletions.
40 changes: 40 additions & 0 deletions lib/workers/rails_request_monitor.rb
Original file line number Diff line number Diff line change
@@ -0,0 +1,40 @@
# Autoload ActionController::LogSubscriber to make sure it subscribes
# ActiveSupport::Notifications and generates a @queue_key for this thread and
# child threads (they will all be the same)
ActionController::LogSubscriber

class RailsRequestMonitor
THREAD_VAR_KEY = "ActiveSupport::SubscriberQueueRegistry".freeze
QUEUE_KEY = ActiveSupport::Subscriber.subscribers.detect { |sub|
sub.kind_of? ActionController::LogSubscriber
}.instance_variable_get(:@queue_key).dup.freeze

class << self
def log_long_running_requests(with_backtrace = false)
now = Time.now
Thread.list.each do |thread|
if thread[THREAD_VAR_KEY] && queue = thread[THREAD_VAR_KEY].get_queue(QUEUE_KEY)

This comment has been minimized.

Copy link
@jrafanie

jrafanie Sep 7, 2018

Member

Maybe it's not there yet but what's populating the THREAD_VAR_KEY thread local variable with the queue? Does rails do that?

queue.each do |request|
next unless request.time < too_slow

duration = (now - request.time).to_f # don't use event.duration, will mutate
message = "Long running http(s) request: " \
"'#{request.payload[:controller]}##{request.payload[:action]}' " \
"handled by ##{Process.pid}:#{thread.object_id.to_s(16)}, " \
"running for #{duration.round(2)} seconds"
message << "\n#{thread.backtrace}" if with_backtrace

Rails.logger.warn(message)
end
end
end
end

private

# TODO: Maybe make this a setting?
def too_slow
10.seconds.ago
end
end
end

0 comments on commit fb7f4bd

Please sign in to comment.