Trouble optimizing Rails queries in controller

Question

I cannot seem to figure out why my total rendering time is not matching up with my active record time + my views time as listed in my production log.

here is the output from my production log:

Completed 200 OK in 12508ms (Views: 0.3ms | ActiveRecord: 46.0ms)

here is the code in my controller:

store = Store.find(:vanity_url => params[:vanity_url])
render :json => store.get_pages_with_includes
return false

in my Store.rb model, there are two methods that i use to render the json representation of my model with all of it's active relations. here is the eager loading method:

def eager_load_pages
    pages = Page.where(:store_id => self.id).includes(
        [{:menu_items => 
            [
                :sizes, 
                {:topping_groups => 
                    {:toppings => :sizes}
                }
            ]
        },
        {:combos => 
            {:combo_item_groups => 
                {:combo_items => 
                    [
                        :sizes,
                        {:topping_groups => 
                            {:toppings => :sizes}
                        }
                    ]
                }
            }
        }]
    ).order('position ASC')
    return pages
end

and here is the to_json method

def get_pages_with_includes
    pages = self.eager_load_pages
    return pages.to_json({:include =>  
        [{:menu_items => 
            {:include =>
                {:topping_groups =>
                    {:include => 
                        {:toppings => 
                            {:include => 
                                :sizes
                            }
                        }
                    }
                }
            }
        },
        {:combos =>
            {:include =>
                {:combo_item_groups => 
                    {:include => 
                        {:combo_items =>
                            {:include => 
                                [:sizes, :topping_groups => 
                                    {:include => 
                                        {:toppings => 
                                            {:include =>
                                                :sizes
                                            }
                                        }
                                    }
                                ]
                            }
                        }
                    }
                }
            }
        }]
    })
end

All of the code is working, and i'm not sure if i can make it more efficient. What i am confused about is why the total page load time is not even close to the amount of time it takes to run my queries. can anyone help me out? Please?? the page should technically be loading in less than 50ms, but its taking 12508ms!

Any help would be much appreciated!

----------UPDATE------------ I ran top from my server and noticed that ruby is occupying 100% of the CPU during these queries. any ideas here? Perhaps this points to the issue...?

Answer 1

Most likely the rendering to JSON in your controller is what's taking too long. How many records are you trying to render? If your Ruby process is taking up all available CPU that means it's not (directly) related to your database, but could be any of these:

• Instantiating objects from your database (if you are retrieving 10,000s of records);
• Rendering these objects to JSON.

Looking at your page load times (Views: 0.3ms | ActiveRecord: 46.0ms) I'd say it's the rendering to JSON. It doesn't show under Views because you're not using any views, but simply calling a render action in the controller directly.

I would suggest you add some tools to your app (such as New Relic RPM) or even simple benchmark methods to find out what's taking so long.

You might also want to consider using a faster JSON parser/renderer instead of the default one. Check out the multi_json gem.