How to determine the cause of a delay before an action is hit in my Rails app?

Question

I've come to a dead-end with my troubleshooting, and I'm really hoping someone can help.

I'm using rack-mini-profiler to help locate a potential memory leak in my Rails website. I narrowed it down to the method that is being called.

High-level profile: rack-mini-profiler high-level

SQL profile: rack-mini-profiler results

In the SQL profile picture, notice the start times of the query just above and just below the gray bar have a difference of 1037ms. That is the delay I am noticing, and it grows until I restart the application.

When running this locally, I can monitor the terminal. When that method is requested, there is just that 1 second delay, and then it executes. No queries or commands show up in the terminal during that delay.

Does anyone have any ideas as to how I can figure out what is causing this delay?

I'm using Ruby 2.2.0 with Rails 4.1.6.

Thanks!!

EDIT:

This is the method rack-mini-profiler is pointing to:

def submit_answer
    quiz_attempt = CourseCompletion.find_by_id(params[:course_completion_id]).quiz_started
    choice = Choice.new(:answer_id => params[:answer], :quiz_attempt_id => quiz_attempt.id)
    @success = choice.save
    @answer = choice.answer
    @question = @answer.question
    @quiz_attempt = choice.quiz_attempt
    render :layout => false
  end

`submit_answer` is the culprit. There has to be something wrong there, can you share that method? — Rockwell Rice, Jan 30 '21 at 03:12
@RockwellRice Thanks, I've just included it in my description above. The website is a series of quizzes. That method gets called each time an answer to a question is submitted. — Kyle, Jan 30 '21 at 03:30
have you examined controller callbacks(hooks)? https://apidock.com/rails/AbstractController/Callbacks — sig, Jan 30 '21 at 09:01
or model callbacks? https://guides.rubyonrails.org/active_record_callbacks.html — sig, Jan 30 '21 at 09:02
I would try removing some parts of the code (before_actions, code from the action, code from the view) to discard parts of it and narrow it down. — arieljuod, Jan 30 '21 at 13:06

sig · Accepted Answer · 2021-01-30T09:57:37.480

take a look on ruby-prof github.com/ruby-prof/ruby-prof. Try to wrap body of your action into the block:

require 'ruby-prof'

# profile the code
RubyProf.start
# ... code to profile ...
result = RubyProf.stop

# print a flat profile to text
printer = RubyProf::FlatPrinter.new(result)
printer.print(STDOUT)

and you should receive output in console which would look like:

You also can redirect output of profiler to log or some file on the server.

So in your case edit code:

def submit_answer
    require 'ruby-prof'
    # profile the code
    RubyProf.start


    quiz_attempt = CourseCompletion.find_by_id(params[:course_completion_id]).quiz_started
    choice = Choice.new(:answer_id => params[:answer], :quiz_attempt_id => quiz_attempt.id)
    @success = choice.save
    @answer = choice.answer
    @question = @answer.question
    @quiz_attempt = choice.quiz_attempt
    render :layout => false

    result = RubyProf.stop
    # print a flat profile to text
    printer = RubyProf::FlatPrinter.new(result)
    printer.print(STDOUT)
  end

Add to gemfile

gem 'ruby-prof'

Run bundle install and restart the server. Try to run action again and check rails console output. Methods on top of the table are most time consuming.

How to determine the cause of a delay before an action is hit in my Rails app?

1 Answers1