Algorithm takes 5sec but the page takes 1.5m to load

Question

After calling a process via ajax

if ($('#content-recommendation').length) {
    $.ajax({
    url:'/get_content_recommendation/' + gon.item_id + '.js',
    type:"get"
  });
}

I do this in itens_controller/get_content_recommendation

before_action :set_item, only: [:get_content_recommendation,...]
...
def get_content_recommendation
  # GET /itens/1

  start_t = Time.now

  @itens_recomendados_conteudo = @item.get_tf_idf_recommendations

  finish_t = Time.now
  puts "Tempo para realizar todo o processo: " + (finish_t - start_t).to_s + "segundos"

  respond_to do |format|
    format.js
  end

end

In item#get_tf_idf_recommendations

def get_tf_idf_recommendations

# Esse cara está com problema!

  Item.all.includes(:generos).each do |item|
    aux = Array.new 
    item.generos.each do |gen| 
      aux << gen.id
    end
  data << aux
  end
# -----

# Codigo deveria continuar mas o retorno é apenas para mostrar os itens na view quando o ajax é carregado
return Item.first
end

My code to change html is in views/item#get_content_recommendation.js.erb

$("#content-recommendation").html("<%= 'Apareceu!' %>")

The code of item#get_tf_idf_recommendations marked as problematic is for some reason delaying the answer of my ajax the time marked after the execution by start_t - finish_t is of Tempo para realizar todo o processo:4.923116s but ajax only appears after 1m:30s. If I comment the problem code the text appears on time.

Nothing unusual about the log:

Started GET "/get_content_recommendation/1.js" for 127.0.0.1 at 2014-08-23 11:29:34 -0300
Processing by ItensController#get_content_recommendation as JS
  Parameters: {"id"=>"1"}
  Item Load (0.4ms)  SELECT  `itens`.* FROM `itens`  WHERE `itens`.`id` = 1 LIMIT 1
  Item Load (9.2ms)  SELECT `itens`.* FROM `itens`
  Generalizacao Load (13.4ms)  SELECT `generalizacoes`.* FROM `generalizacoes`  WHERE `generalizacoes`.`item_id` IN (1, 2, ... 1749, 1750, 1751, 1752)

  Genero Load (0.6ms)  SELECT `generos`.* FROM `generos`  WHERE `generos`.`id` IN (1, 12, ... 30, 29)

  Item Load (0.5ms)  SELECT  `itens`.* FROM `itens`  LIMIT 5
Tempo para realizar todo o processo: 4.923116segundos
    Rendered itens/_content_recommendation.html.erb (0.8ms)
    Rendered itens/get_content_recommendation.js.erb (2.2ms)
Completed 200 OK in 4932ms (Views: 5.5ms | ActiveRecord: 24.2ms | Solr: 0.0ms)

EDITED:

After removing the ajax and clicking on a normal full request, I saw that the problem is not ajax but rather a performance problem in the algorithm... Time is still the same 5.03214s after that the log is:

...
Rendered itens/_avaliacoes.html.erb (3.7ms)
Rendered itens/_content_recommendation.html.erb (1.3ms)
Rendered itens/show.html.erb within layouts/application (693.6ms)
Rendered layouts/_header.html.erb (5.1ms)
Rendered layouts/_footer.html.erb (0.4ms)
Completed 200 OK in 6396ms (Views: 1194.7ms | ActiveRecord: 61.7ms | Solr: 0.0ms)

But the page only loads after 1.5m as can be seen by Google Chrome trace:

Blocking    0.987 ms
DNS Lookup  624.962 ms
Connecting  0.412 ms
Sending 0.129 ms
Waiting 1.5 min
Receiving 1.441 ms

The worst thing is that you can’t stop knowing what’s taking so long and how to get better!

Answer 1

Your method is a bit confusing, you don’t need to use the . all, see that the neck is the select of all items, one way to leave more ruby style would be:

def get_tf_idf_recommendations
 itens = Item.includes(:generos)
 itens.generos.map(:id)
end

I do not know how is your modeling so it is worth testing this alternative, if you have a relationship so you do not need to search in all items will help, for example: current_user.orders.itens.

A good tip is to always use the documentation to see which is the best method to use and not have to keep making code like java, but to make it more readable and dynamic.