Reputation: 965
I am a newbie in ruby/rails and have been breaking my head with a problem for the past 2 days and am hoping that someone in this forum can help me out with it.
I am working on rails 4 and running an application in production using Passenger + Nginx with Mysql database (mysql2 adapter). I have following code in my ProductsController.rb (log_info is my custom logging wrapper that just calls the Rails logger):
def index
log_info("ProductsController", "Getting Products...")
@products = Product.get_products(params[:offset])
log_info("ProductsController", "Got all Products...")
# populate access_url before sending the data through
update_products_with_access_url(@products)
end
Here is the definition of get_products function inside Product model:
def self.get_products(products_offset)
products_offset ||= 0
Product.includes(:categories, :suppliers).
where(active: true).order(updated_at: :desc).
limit(20).
offset(products_offset * 20)
end
The problem is that my application hangs in production (works fine in dev) for a few mins when the index action is called. This behaviour is happening almost half the time - it works fine the other half of time.
I can see in the log that the action has been called but is not getting executed. Here is a snippet from the log file:
I, [2015-06-10T13:31:01.802673 #14916] INFO -- : Processing by ProductsController#index as HTML
I, [2015-06-10T13:33:09.718339 #14916] INFO -- : [INFO][2015-06-10 13:33:09 UTC][ProductsController][Getting Products...]
I, [2015-06-10T13:33:09.719365 #14916] INFO -- : [INFO][2015-06-10 13:33:09 UTC][ProductsController][Got all Products...]
D, [2015-06-10T13:33:09.720980 #14916] DEBUG -- : Product Load (0.8ms) SELECT `products`.* FROM `products` WHERE `products`.`active` = 1 ORDER BY `products`.`updated_at` DESC LIMIT 12 OFFSET 0
D, [2015-06-10T13:33:09.725110 #14916] DEBUG -- : ProductCategory Load (0.5ms) SELECT `product_categories`.* FROM `product_categories` WHERE `product_categories`.`product_id` IN (30, 29, 28, 27, 26, 25, 24, 23, 22, 21, 20, 19)
As you can see there is difference of at least 2 mins between the first two lines of log file above. And the log shows that index action had received the call, but I am not sure why it is taking so long (sometimes more than 5 mins.) to execute the very first line in that index action. I suspect there is some kind of caching happening. I was earlier thinking that the call might be hanging in connecting with MySQL database, but now am not sure. Am I missing something here?
Can someone please help me out in fixing this application hang issue?
Upvotes: 0
Views: 146
Reputation: 4635
Please check if there are any before filters, quite often they can be the reason of such hangs.
Upvotes: 1