#503 ✓resolved
Mark Bates

Calls to has 1 associations result in multiple db calls

Reported by Mark Bates | August 1st, 2008 @ 05:06 PM

I have a User object which has 1 UserProfile. When I make calls through user.user_profile to get properties off of it, it results in a DB query on each call. I found this in 0.9.3 and 0.9.4.

Here is my slimmed down classes: 

require 'rubygems'
require 'dm-core'
require 'dm-validations'
require 'dm-timestamps'
require 'dm-aggregates'

DataMapper.logger = DataMapper::Logger.new(STDOUT, :debug)
DataMapper.setup(:default, "postgres://ruby:password@localhost/dm_test")

class User
  include DataMapper::Resource
  
  attr_accessor :password_confirmation

  property :id, Serial
  property :username, String
  property :password, String
  property :created_at, DateTime
  property :updated_at, DateTime
  
  has 1, :user_profile

end


class UserProfile
  include DataMapper::Resource

  property :id, Serial
  property :email_address, String
  property :display_name, String
  property :bio, Text, :nullable => true
  property :updated_at, DateTime
  
  belongs_to :user
  
end

User.auto_migrate!
UserProfile.auto_migrate!

user = User.create(:username => "markbates", :password => "123456", :password_confirmation => "123456")

UserProfile.create(:user => User.first, :email_address => "mark@mackframework.com", :display_name => "Mark Bates", :bio => "asldfkjasdf")

puts "------"

puts user.user_profile.email_address
puts user.user_profile.display_name
puts user.user_profile.bio

Here is the Postgres log for this test: 

2008-08-01 17:57:19.880 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.577 ms
2008-08-01 17:57:19.881 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.882 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "username", "password", "created_at", "updated_at" FROM "users" ORDER BY "id" LIMIT 1
2008-08-01 17:57:19.882 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.882 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.267 ms
2008-08-01 17:57:19.882 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.893 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "email_address", "display_name", "updated_at", "user_id" FROM "user_profiles" WHERE "email_address" = 'mark@mackframework.com' ORDER BY "id" LIMIT 1
2008-08-01 17:57:19.893 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.894 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 1.363 ms
2008-08-01 17:57:19.894 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.900 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "email_address", "display_name", "updated_at", "user_id" FROM "user_profiles" WHERE "email_address" = 'mark@mackframework.com' ORDER BY "id" LIMIT 1
2008-08-01 17:57:19.900 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.901 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.432 ms
2008-08-01 17:57:19.901 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.904 EDT 94533 0 ::1 dm_testLOG:  00000: statement: INSERT INTO "user_profiles" ("email_address", "user_id", "updated_at", "bio", "display_name") VALUES ('mark@mackframework.com', 1, '2008-08-01T17:57:19-04:00', 'asldfkjasdf', 'Mark Bates') RETURNING "id"
2008-08-01 17:57:19.904 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.905 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 1.118 ms
2008-08-01 17:57:19.905 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.913 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT COUNT(*) FROM "user_profiles"
2008-08-01 17:57:19.913 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.913 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.862 ms
2008-08-01 17:57:19.913 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.915 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "email_address", "display_name", "updated_at", "user_id" FROM "user_profiles" WHERE "user_id" IN (1) ORDER BY "id"
2008-08-01 17:57:19.915 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.916 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.456 ms
2008-08-01 17:57:19.916 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.918 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "email_address", "display_name", "updated_at", "user_id" FROM "user_profiles" WHERE "user_id" = 1 ORDER BY "id" LIMIT 1
2008-08-01 17:57:19.918 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.918 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.338 ms
2008-08-01 17:57:19.918 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.927 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "email_address", "display_name", "updated_at", "user_id" FROM "user_profiles" WHERE "user_id" = 1 ORDER BY "id" LIMIT 1
2008-08-01 17:57:19.927 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.927 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 2.557 ms
2008-08-01 17:57:19.927 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.929 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "id", "email_address", "display_name", "updated_at", "user_id" FROM "user_profiles" WHERE "user_id" = 1 ORDER BY "id" LIMIT 1
2008-08-01 17:57:19.929 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.929 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.334 ms
2008-08-01 17:57:19.929 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.940 EDT 94533 0 ::1 dm_testLOG:  00000: statement: SELECT "bio", "id" FROM "user_profiles" WHERE "user_id" IN (1) AND "id" IN (1) ORDER BY "id"
2008-08-01 17:57:19.940 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:845
2008-08-01 17:57:19.940 EDT 94533 0 ::1 dm_testLOG:  00000: duration: 0.551 ms
2008-08-01 17:57:19.940 EDT 94533 0 ::1 dm_testLOCATION:  exec_simple_query, postgres.c:1056
2008-08-01 17:57:19.946 EDT 94533 0 ::1 dm_testLOG:  08P01: unexpected EOF on client connection
2008-08-01 17:57:19.946 EDT 94533 0 ::1 dm_testLOCATION:  SocketBackend, postgres.c:323

As you can see it's hitting the DB multiple times at the end to first get the user_profile object, but then it makes separate calls back to the DB for the email_address and the display_name.

Comments and changes to this ticket

  • Sam Smoot

    Sam Smoot August 1st, 2008 @ 05:09 PM

    • Assigned user changed from “Sam Smoot” to “Bernerd Schaefer”
    • State changed from “new” to “open”
    • Tag changed from “associations, dm-core” to “associations, bug, dm-core, priority”

    Hmm... a bug in PropertySet#defaults perhaps? We'll look into it. Thanks Mark.

  • Bernerd Schaefer

    Bernerd Schaefer August 4th, 2008 @ 12:44 PM

    Can you update to edge (8149cf3) and let me know if this still happens? I just committed a fix that I think should resolve this (it resolved #505, which appears similar).

  • Mark Bates

    Mark Bates August 4th, 2008 @ 01:34 PM

    That seems to have done the trick from what I can tell.

  • Bernerd Schaefer

    Bernerd Schaefer August 4th, 2008 @ 01:37 PM

    • State changed from “open” to “resolved”

    Thanks a bunch. I'll close this out — let us know if you come across anything else.

Please Sign in or create a free account to add a new ticket.

With your very own profile, you can contribute to projects, track your activity, watch tickets, receive and update tickets through your email and much more.

New-ticket Create new ticket

Create your profile

Help contribute to this project by taking a few moments to create your personal profile. Create your profile »

People watching this ticket

Tags

Pages