Eager loading issue

[gottfrois]

Figured it would be easier to discuss about the issue here. Here is a recap of my issue.

class Author
  include Mongoid::Document
end

class SkillModeration
  include Mongoid::Document
  belongs_to :author
end

require 'roar/json'

module AuthorRepresenter
  include Roar::JSON
  property :id
end

module SkillModerationRepresenter
  include Roar::JSON
  property :id
end

module SkillModerationsRepresenter
  include Roar::JSON

  collection :to_a, extend: SkillModerationRepresenter, as: :data

  nested :included do
    collection :authors, getter: proc { to_a.map(&:author).uniq }, extend: AuthorRepresenter
  end
end

The issue is that when I try to represent a collection of SkillModeration resources, I need to eager load the Author resource to avoid N+1 queries. Here I'm using mongoid but it would be the exact same thing with activerecord.

tasks = SkillModeration.all.includes(:author)
tasks.extend SkillModerationsRepresenter
tasks.to_json

Now if we look at the queries generated we see that it performed the eager loading query but also all the N+1 queries.

The eager loading query:

QUERY collection=authors selector={"_id"=>{"$in"=>[BSON::ObjectId('51a5b54b29e1670fae000040'), BSON::ObjectId('528f92fe29e1673b150000f1'), BSON::ObjectId('5331938843ff13000200005a'), BSON::ObjectId('531701fdb9e3b40002000002')]}} flags=[] limit=0 skip=0 batch_size=nil fields=nil runtime: 12.1370ms

The N+1 queries as well:

QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('51a5b54b29e1670fae000040')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 2.3070ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('51a5b54b29e1670fae000040')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 2.1120ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('51a5b54b29e1670fae000040')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 2.2660ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('51a5b54b29e1670fae000040')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 2.2150ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('528f92fe29e1673b150000f1')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 9.2740ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('528f92fe29e1673b150000f1')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 8.3700ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('528f92fe29e1673b150000f1')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 8.0710ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('5331938843ff13000200005a')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 1.6380ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('5331938843ff13000200005a')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 1.4300ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('5331938843ff13000200005a')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 1.4910ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('531701fdb9e3b40002000002')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 1.7860ms
QUERY collection=authors selector={"$query"=>{"_id"=>BSON::ObjectId('531701fdb9e3b40002000002')}, "$orderby"=>{:_id=>1}} flags=[] limit=-1 skip=0 batch_size=nil fields=nil runtime: 1.3940ms

I found that it's because of this code:

collection :to_a, extend: SkillModerationRepresenter, as: :data

nested :included do
  collection :authors, getter: proc { to_a.map(&:author).uniq }, extend: AuthorRepresenter
end

which calls the to_a method twice. If we were in an irb console, it would not be an issue. For example, in a console, you can do this and it won't perform the N+1 queries:

tasks = SkillModeration.all.includes(:author)
tasks.to_a
tasks.to_a

But for some reasons, on a representer object, it triggers the N+1 queries. If for example, you remove the included, the representer class would look like this:

collection :to_a, extend: SkillModerationRepresenter, as: :data

then calling tasks.to_json generates only the eager loading query but not all the N+1.

So the issue seems to come from how representable uses the source (the collection). Calling multiple times the source (to_a) inside the representer cause the eager loading to work only once.

I have no idea how the source is used in the gem, that's why i'm posting this issue. Hope you can help me to figure out what's going on here. It's pretty easy to reproduce, using AR or mongoid.

Thanks

[apotonick]

It's obvious that the problem originates from nested.. is that right?

[gottfrois]

Not necessarly, a simple representer like this will also trigger N+1 queries:

module SkillModerationsRepresenter
  include Roar::JSON

  property :foo, getter: proc { to_a.map(&:author).uniq }
  property :bar, getter: proc { to_a.map(&:author).uniq }
end

[apotonick]

Let's go the other way round: What happens when you do tasks.to_a?

[gottfrois]

Nevermind, I found that this does not work as I would expect:

tasks = SkillModeration.all.includes(:author)
tasks.map(&:author)
tasks.map(&:author)

First time, it uses the eager loaded authors, second time, it performs the N+1 queries... So it's not related to representable.

[apotonick]

Pheew... 😜

Isn't the whole point of includes that it does load the association in one go?

[gottfrois]

Yes :) I just found an open issue for this :) https://jira.mongodb.org/browse/MONGOID-3942

For futur readers, use cache as a possible work around:

tasks = Task.all.includes(:author).cache
tasks.map(&:author)
tasks.map(&:author)

Thanks man for guidance ;)