Postgres performance issue in my Rails app

Question

I'm using derailed_benchmark gem to track my app performance:

$ PATH_TO_HIT="/api/v2/feed.json?per_page=30&page=1&category_name=Feed" USER_SERVER=webrick TEST_COUNT=20 bundle exec derailed exec perf:stackprof

==================================
  Mode: cpu(1000)
  Samples: 20708 (0.42% miss rate)
  GC: 3219 (15.54%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      4720  (22.8%)        4694  (22.7%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
       542   (2.6%)         502   (2.4%)     ActiveSupport::Inflector#underscore
       413   (2.0%)         413   (2.0%)     ActiveSupport::PerThreadRegistry#instance
       364   (1.8%)         364   (1.8%)     ActiveRecord::QueryMethods#validate_order_args
       309   (1.5%)         309   (1.5%)     block in ActiveSupport::Inflector#apply_inflections
       282   (1.4%)         282   (1.4%)     ThreadSafe::NonConcurrentCacheBackend#[]
       257   (1.2%)         257   (1.2%)     ActiveRecord::Relation#initialize
       410   (2.0%)         235   (1.1%)     ActiveRecord::Relation#initialize_copy
       229   (1.1%)         229   (1.1%)     ActiveRecord::Delegation::DelegateCache#relation_delegate_class
       212   (1.0%)         212   (1.0%)     block in ActiveRecord::Relation::Merger#merge
       562   (2.7%)         198   (1.0%)     ActiveRecord::QueryMethods#preprocess_order_args
       190   (0.9%)         189   (0.9%)     ActiveRecord::Core::ClassMethods#arel_table
       181   (0.9%)         181   (0.9%)     JSON#parse
       175   (0.8%)         175   (0.8%)     ActiveRecord::Relation#reset
       165   (0.8%)         165   (0.8%)     ActiveRecord::Attribute#initialize
       153   (0.7%)         153   (0.7%)     ActiveRecord::Relation#values
       151   (0.7%)         151   (0.7%)     ActiveRecord::Inheritance::ClassMethods#base_class
       333   (1.6%)         151   (0.7%)     ActiveRecord::Scoping::Default::ClassMethods#build_default_scope
       144   (0.7%)         144   (0.7%)     Skylight::Normalizers::ActiveRecord::SQL#extract_rust
       142   (0.7%)         142   (0.7%)     ActiveRecord::QueryMethods#joins_values
       138   (0.7%)         138   (0.7%)     block (4 levels) in Class#class_attribute
       195   (0.9%)         133   (0.6%)     ActiveRecord::DynamicMatchers#respond_to?
       158   (0.8%)         121   (0.6%)     ActiveRecord::QueryMethods#where_values=
       125   (0.6%)         115   (0.6%)     ActiveRecord::Reflection::AssociationReflection#klass
       113   (0.5%)         113   (0.5%)     ActiveRecord::Result#initialize_copy
       110   (0.5%)         110   (0.5%)     Arel::Table#initialize
       193   (0.9%)         109   (0.5%)     ActiveRecord::ConnectionAdapters::PostgreSQL::Utils#extract_schema_qualified_name
       114   (0.6%)         106   (0.5%)     Arel::Nodes::Binary#hash
       104   (0.5%)         104   (0.5%)     ActiveRecord::QueryMethods#extending_values
        99   (0.5%)          99   (0.5%)     ActiveRecord::QueryMethods#order_values

How can I fix the "block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache" performance issue?

UPDATE

After running same command with "config.middleware.delete "ActiveRecord::QueryCache" in my config/application.rb the results are:

==================================
  Mode: cpu(1000)
  Samples: 21116 (0.42% miss rate)
  GC: 2213 (10.48%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      5619  (26.6%)        5600  (26.5%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
      2268  (10.7%)        2268  (10.7%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
       421   (2.0%)         383   (1.8%)     ActiveSupport::Inflector#underscore
       304   (1.4%)         304   (1.4%)     ActiveSupport::PerThreadRegistry#instance
       294   (1.4%)         294   (1.4%)     block in ActiveSupport::Inflector#apply_inflections
       270   (1.3%)         270   (1.3%)     ThreadSafe::NonConcurrentCacheBackend#[]
       245   (1.2%)         245   (1.2%)     ActiveRecord::Relation#initialize
       229   (1.1%)         229   (1.1%)     ActiveRecord::QueryMethods#validate_order_args
       219   (1.0%)         219   (1.0%)     ActiveRecord::Delegation::DelegateCache#relation_delegate_class
       207   (1.0%)         207   (1.0%)     ActiveRecord::Inheritance::ClassMethods#base_class
       285   (1.3%)         188   (0.9%)     ActiveRecord::Relation#initialize_copy
       184   (0.9%)         184   (0.9%)     ActiveRecord::Attribute#initialize
       181   (0.9%)         179   (0.8%)     ActiveRecord::Core::ClassMethods#arel_table
       175   (0.8%)         175   (0.8%)     Skylight::Normalizers::ActiveRecord::SQL#extract_rust
       165   (0.8%)         165   (0.8%)     block in ActiveRecord::Relation::Merger#merge
       147   (0.7%)         147   (0.7%)     block (4 levels) in Class#class_attribute
       374   (1.8%)         145   (0.7%)     ActiveRecord::QueryMethods#preprocess_order_args
       113   (0.5%)         113   (0.5%)     ActiveRecord::Relation#values
       112   (0.5%)         112   (0.5%)     ActiveRecord::QueryMethods#joins_values
       171   (0.8%)         109   (0.5%)     ActiveRecord::ConnectionAdapters::PostgreSQL::Utils#extract_schema_qualified_name
        99   (0.5%)          99   (0.5%)     Arel::Table#initialize
        97   (0.5%)          97   (0.5%)     ActiveRecord::Relation#reset
       271   (1.3%)          96   (0.5%)     ActiveRecord::Scoping::Default::ClassMethods#build_default_scope
       107   (0.5%)          95   (0.4%)     ActiveRecord::Reflection::AssociationReflection#klass
        93   (0.4%)          93   (0.4%)     ActiveRecord::QueryMethods#order_values
       125   (0.6%)          93   (0.4%)     ActiveRecord::QueryMethods#where_values=
        88   (0.4%)          88   (0.4%)     ActiveRecord::Reflection::ThroughReflection#active_record
       106   (0.5%)          87   (0.4%)     Skylight::Trace#start
        81   (0.4%)          81   (0.4%)     ActiveRecord::QueryMethods#check_cached_relation
        80   (0.4%)          80   (0.4%)     ActiveRecord::QueryMethods#where_values

UDPATE 2

After running the query with "wall time" mode and not "cpu time" mode, this is the results:

==================================
  Mode: wall(1000)
  Samples: 41424 (1.92% miss rate)
  GC: 3648 (8.81%)
==================================
     TOTAL    (pct)     SAMPLES    (pct)     FRAME
      4780  (11.5%)        4718  (11.4%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_cache
      2783   (6.7%)        2783   (6.7%)     block in ActiveRecord::ConnectionAdapters::PostgreSQLAdapter#exec_no_cache
      1088   (2.6%)        1088   (2.6%)     ActiveSupport::PerThreadRegistry#instance
       934   (2.3%)         934   (2.3%)     ThreadSafe::NonConcurrentCacheBackend#[]
      1031   (2.5%)         926   (2.2%)     ActiveSupport::Inflector#underscore
       739   (1.8%)         739   (1.8%)     block in ActiveSupport::Inflector#apply_inflections
       626   (1.5%)         626   (1.5%)     ActiveRecord::Relation#initialize
       589   (1.4%)         589   (1.4%)     ActiveRecord::Delegation::DelegateCache#relation_delegate_class
       577   (1.4%)         577   (1.4%)     ThreadSafe::NonConcurrentCacheBackend#get_or_default
       549   (1.3%)         549   (1.3%)     ActiveRecord::Attribute#initialize
       497   (1.2%)         497   (1.2%)     block in ActiveRecord::Relation::Merger#merge
       497   (1.2%)         497   (1.2%)     ActiveRecord::QueryMethods#validate_order_args
       702   (1.7%)         424   (1.0%)     ActiveRecord::Relation#initialize_copy
       419   (1.0%)         417   (1.0%)     ActiveRecord::Core::ClassMethods#arel_table
       384   (0.9%)         384   (0.9%)     ActiveRecord::Inheritance::ClassMethods#base_class
       383   (0.9%)         383   (0.9%)     block (4 levels) in Class#class_attribute
       358   (0.9%)         358   (0.9%)     Skylight::Normalizers::ActiveRecord::SQL#extract_rust
       329   (0.8%)         329   (0.8%)     ActiveRecord::Base.logger
       321   (0.8%)         321   (0.8%)     rescue in Net::BufferedIO#rbuf_fill
       315   (0.8%)         315   (0.8%)     ActiveRecord::Core#update_attributes_from_transaction_state
       314   (0.8%)         314   (0.8%)     ActiveRecord::ConnectionAdapters::AbstractAdapter#type_map
       795   (1.9%)         298   (0.7%)     ActiveRecord::QueryMethods#preprocess_order_args
       284   (0.7%)         284   (0.7%)     Arel::Table#initialize
       279   (0.7%)         279   (0.7%)     ActiveRecord::Relation#values
       278   (0.7%)         278   (0.7%)     ActiveRecord::Relation#reset
       734   (1.8%)         264   (0.6%)     ActiveRecord::Scoping::Default::ClassMethods#build_default_scope
       263   (0.6%)         263   (0.6%)     ActiveRecord::QueryMethods#joins_values
       394   (1.0%)         258   (0.6%)     ActiveRecord::ConnectionAdapters::PostgreSQL::Utils#extract_schema_qualified_name
     15323  (37.0%)         249   (0.6%)     ActiveRecord::Querying#find_by_sql
       257   (0.6%)         246   (0.6%)     ActiveRecord::Reflection::AssociationReflection#klass

I'm building my feed.json using index.json.jbuilder, this is how it looks:

json.battles @battles do |battle|
  if (battle.products.size == 2)
    battle_results = battle.calculate_results
    json.(battle, :id)
    vote = battle.votes.find_by(user_id: current_user.id) 
    json.voted vote.present?
    if vote
      json.product_voted vote.product.id == battle.products[0].id ? "first" : "second"
    end
    json.mybattle battle.try(:user).try(:id) == current_user.id
    json.user do 
      username = ""
      if (battle.try(:user).try(:nickname).present?)
        username = battle.try(:user).try(:nickname)
      else
        username = battle.try(:user).try(:name).try(:downcase).try(:delete,' ')
      end
      json.username username
      json.user_id battle.try(:user_id)
      json.profile_image battle.try(:user).try(:image) || ""
      json.full_name battle.try(:user).try(:name) || "" 
    end
    json.votes battle_results[:votes]
    json.created_at time_ago_in_words(battle.created_at) + " ago"
    json.title battle.title
    json.first_product do
      first_product = battle.products[0]
      json.id first_product.id
      json.voted first_product.votes.find_by(user_id: current_user.id).present?
      json.percentage battle_results[:percentage_product_one]
      # json.percentage_after_voting battle_results[:percentage_after_voting_product_one]
      json.name first_product.name
      json.price SearchFunctions.convert_currency(first_product.price.to_s, current_user.currency_code, 'USD')
      # json.price first_product.price.to_s
      json.url first_product.url
      if first_product.images["sub"] && first_product.images["sub"].kind_of?(Array)
        first_product.images["sub"] =  first_product.images["sub"].first(10)
      end
      json.images first_product.images
      json.manufacturer first_product.manufacturer
      json.description first_product.description
      json.is_user_saved first_product.saved_products.find_by(user_id: current_user.id).present?
      json.saved_count first_product.saved_products.length
    end
    json.second_product do
      second_product = battle.products[1]
      json.id second_product.id
      json.voted second_product.votes.find_by(user_id: current_user.id).present?
      json.percentage battle_results[:percentage_product_two]
      # json.percentage_after_voting battle_results[:percentage_after_voting_product_two]
      json.name second_product.name
      json.price SearchFunctions.convert_currency(second_product.price.to_s, current_user.currency_code, 'USD')
      # json.price second_product.price.to_s
      json.url second_product.url
      if second_product.images["sub"] && second_product.images["sub"].kind_of?(Array)
        second_product.images["sub"] =  second_product.images["sub"].first(10)
      end
      json.images second_product.images
      json.manufacturer second_product.manufacturer
      json.description second_product.description
      json.is_user_saved second_product.saved_products.find_by(user_id: current_user.id).present?
      json.saved_count second_product.saved_products.length
    end
  end
end

Answer 1

Well, this may be silly answer, but you probably should decrease or optimise number of queries executed during building feed.json. Check for N+1 queries, for example maybe you are loading author for each feed item or something like that.

You can use bullet gem to help you find N+1 queries. And you can fix those by adding includes to your queries.

Update Based on json view.

It is pretty big json and it looks like you use a lot of models from your application. BY looking at this it is impossible to give you any clear guidelines on how to optimise this. You should probably paste your whole app here, but I think that's not appropriate for SO.

For sure there is a lot space for improvement on database side, but I think your best and easiest way is to just cache this view. By caching I mean using fragment caching for each separate battle.

json.battles @battles do |battle|
  if (battle.products.size == 2)
    json.cache! "#{battle.id}/#{battle.updated_at}" do
      battle_results = battle.calculate_results
      json.(battle, :id)
      vote = battle.votes.find_by(user_id: current_user.id) 
      json.voted vote.present?
      if vote
        json.product_voted vote.product.id == battle.products[0].id ? "first" : "second"
      end
      json.mybattle battle.try(:user).try(:id) == current_user.id
      json.user do 
        username = ""
        if (battle.try(:user).try(:nickname).present?)
          username = battle.try(:user).try(:nickname)
        else
          username = battle.try(:user).try(:name).try(:downcase).try(:delete,' ')
        end
        json.username username
        json.user_id battle.try(:user_id)
        json.profile_image battle.try(:user).try(:image) || ""
        json.full_name battle.try(:user).try(:name) || "" 
      end
      json.votes battle_results[:votes]
      json.created_at time_ago_in_words(battle.created_at) + " ago"
      json.title battle.title
      json.first_product do
        first_product = battle.products[0]
        json.id first_product.id
        json.voted first_product.votes.find_by(user_id: current_user.id).present?
        json.percentage battle_results[:percentage_product_one]
        # json.percentage_after_voting battle_results[:percentage_after_voting_product_one]
        json.name first_product.name
        json.price SearchFunctions.convert_currency(first_product.price.to_s, current_user.currency_code, 'USD')
        # json.price first_product.price.to_s
        json.url first_product.url
        if first_product.images["sub"] && first_product.images["sub"].kind_of?(Array)
          first_product.images["sub"] =  first_product.images["sub"].first(10)
        end
        json.images first_product.images
        json.manufacturer first_product.manufacturer
        json.description first_product.description
        json.is_user_saved first_product.saved_products.find_by(user_id: current_user.id).present?
        json.saved_count first_product.saved_products.length
      end
      json.second_product do
        second_product = battle.products[1]
        json.id second_product.id
        json.voted second_product.votes.find_by(user_id: current_user.id).present?
        json.percentage battle_results[:percentage_product_two]
        # json.percentage_after_voting battle_results[:percentage_after_voting_product_two]
        json.name second_product.name
        json.price SearchFunctions.convert_currency(second_product.price.to_s, current_user.currency_code, 'USD')
        # json.price second_product.price.to_s
        json.url second_product.url
        if second_product.images["sub"] && second_product.images["sub"].kind_of?(Array)
          second_product.images["sub"] =  second_product.images["sub"].first(10)
        end
        json.images second_product.images
        json.manufacturer second_product.manufacturer
        json.description second_product.description
        json.is_user_saved second_product.saved_products.find_by(user_id: current_user.id).present?
        json.saved_count second_product.saved_products.length
      end
    end
  end
end

I added some code at line 3. I just wrote this out of my head, I am not exactly sure if syntax is 100% correct, but it should give you a hint. Also remember that caching is not enabled in development environment. To enable it you need to set config.action_controller.perform_caching = true in config/environments/developement.rb