dev_why.log

Mar 05 16:52:29 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:29 le-mbr rails[29845]: GC STATISTICS
Mar 05 16:52:29 le-mbr rails[29845]: + Mem:  1012840 kb
Mar 05 16:52:29 le-mbr rails[29845]: + GCs:  3
Mar 05 16:52:29 le-mbr rails[29845]: + Num:  976370
Mar 05 16:52:29 le-mbr rails[29845]: + Size: 14607 kb
Mar 05 16:52:29 le-mbr rails[29845]: + Time: 1735.706 ms
Mar 05 16:52:29 le-mbr rails[29845]: + All:  2672.402 ms
Mar 05 16:52:29 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:30 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:31 le-mbr rails[29845]: APP OBJECTS
Mar 05 16:52:31 le-mbr rails[29845]: + Total: 803602
Mar 05 16:52:31 le-mbr rails[29845]: + String: 119986
Mar 05 16:52:31 le-mbr rails[29845]: + Array: 39038
Mar 05 16:52:31 le-mbr rails[29845]: + Hash: 48767
Mar 05 16:52:31 le-mbr rails[29845]: + Regexp: 132
Mar 05 16:52:31 le-mbr rails[29845]: + MetaSymbol: 12
Mar 05 16:52:31 le-mbr rails[29845]: + ActiveRecord::Base: 5995
Mar 05 16:52:31 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:31 le-mbr rails[29845]: Completed 200 OK in 5137ms (Views: 2436.1ms | ActiveRecord: 243.9ms)
Mar 05 16:52:31 le-mbr rails[29845]: Oink Action: admin/dashboard#index
Mar 05 16:52:31 le-mbr rails[29845]: Memory usage: 4046868 | PID: 29845
Mar 05 16:52:31 le-mbr rails[29845]: Instantiation Breakdown: Total: 263 | Role: 68 | Component: 35 | UserCategory: 31 | User: 23 | Company: 22 | CompanyType: 21 | Location: 17 | State: 17 | Tableless: 8 | Country: 7 | Relationship: 2 | CustomReport: 2 | ActiveRecord::SessionStore::Session: 2 | PhoneNumber: 2 | Clipboard: 1 | Referral: 1 | Purchase: 1 | PlannedSeason: 1 | InterpretationSystem: 1 | Profile: 1
Mar 05 16:52:31 le-mbr rails[29845]: Oink Log Entry Complete
Mar 05 16:52:43 le-mbr rails[29845]: 
Mar 05 16:52:43 le-mbr rails[29845]: 
Mar 05 16:52:43 le-mbr rails[29845]: Started GET "/auto_completes/site_objects?q=robins" for 127.0.0.1 at Tue Mar 05 16:52:43 +0800 2013
Mar 05 16:52:43 le-mbr rails[29845]: Processing by AutoCompletesController#site_objects as JSON
Mar 05 16:52:43 le-mbr rails[29845]: Parameters: {"q"=>"robins"}
Mar 05 16:52:43 le-mbr rails[29845]: Geokit is using the domain: website.dev
Mar 05 16:52:43 le-mbr rails[29845]: User Load (0.5ms)  SELECT "users".* FROM "users" WHERE "users"."id" = 1844 LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]:  (0.1ms)  BEGIN
Mar 05 16:52:43 le-mbr rails[29845]:  (0.3ms)  UPDATE "users" SET "perishable_token" = 'JfCNV8j6X1vUji54ftr5', "updated_at" = '2013-03-05 08:52:43.378898', "last_request_at" = '2013-03-05 08:52:43.375443' WHERE "users"."id" = 1844
Mar 05 16:52:43 le-mbr rails[29845]: Company Load (0.5ms)  SELECT "companies".* FROM "companies" WHERE "companies"."id" = 323 LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]: Component Load (1.6ms)  SELECT "components".* FROM "components" INNER JOIN "subscriptions" ON "components"."id" = "subscriptions"."component_id" WHERE "subscriptions"."user_id" = 1844 AND (subscriptions.paid = true AND subscriptions.expired = false)
Mar 05 16:52:43 le-mbr rails[29845]: Role Load (0.7ms)  SELECT "roles".* FROM "roles" INNER JOIN "components_roles" ON "roles"."id" = "components_roles"."role_id" WHERE "components_roles"."component_id" = 33
Mar 05 16:52:43 le-mbr rails[29845]: CompanyType Load (0.3ms)  SELECT "company_types".* FROM "company_types" WHERE "company_types"."id" = 8 LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]:  (1.0ms)  SELECT COUNT(DISTINCT "users"."id") FROM "users" INNER JOIN "relationships" ON "relationships"."user_id" = "users"."id" INNER JOIN "roles" ON "roles"."id" = "relationships"."role_id" WHERE (relationships.company_id = 323) AND (roles.name IN ('company_admin'))
Mar 05 16:52:43 le-mbr rails[29845]: Role Load (0.3ms)  SELECT "roles".* FROM "roles" WHERE "roles"."id" IN (6, 40, 26) AND "roles"."own_company_assignable" = 't'
Mar 05 16:52:43 le-mbr rails[29845]: Component Load (0.3ms)  SELECT "components".* FROM "components" WHERE "components"."name" = 'Admin User' LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]:  (1.1ms)  SELECT COUNT(DISTINCT "subscriptions"."id") FROM "subscriptions" WHERE "subscriptions"."user_id" = 1844 AND "subscriptions"."component_id" = 33
Mar 05 16:52:43 le-mbr rails[29845]: Relationship Load (0.3ms)  SELECT "relationships".* FROM "relationships" WHERE "relationships"."user_id" = 1844 AND "relationships"."company_id" = 323
Mar 05 16:52:43 le-mbr rails[29845]: Role Load (0.3ms)  SELECT "roles".* FROM "roles" WHERE "roles"."id" = 1 LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]: Role Load (0.2ms)  SELECT "roles".* FROM "roles" WHERE "roles"."id" = 6 LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]:  (0.3ms)  COMMIT
Mar 05 16:52:43 le-mbr rails[29845]: Profile Load (0.5ms)  SELECT "profiles".* FROM "profiles" WHERE "profiles"."user_id" = 1844 LIMIT 1
Mar 05 16:52:43 le-mbr rails[29845]: PlannedSeason Load (0.4ms)  SELECT "planned_seasons".* FROM "planned_seasons" WHERE "planned_seasons"."company_id" = 323 AND "planned_seasons"."bucket" = 't' LIMIT 1
Mar 05 16:52:44 le-mbr rails[29845]: Role Load (0.6ms)  SELECT DISTINCT "roles".* FROM "roles" INNER JOIN "relationships" ON "roles"."id" = "relationships"."role_id" WHERE "relationships"."user_id" = 1844
Mar 05 16:52:44 le-mbr rails[29845]: Company Load (16.6ms)  SELECT "companies".* FROM "companies" WHERE (companies.name ~* 'r.*?o.*?b.*?i.*?n.*?s') ORDER BY length(substring(companies.name from '(?i)((^| )robins)')),length(substring(companies.name from '(?i)((^| )r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(companies.name from '(?i)(.*?r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(companies.name from '(?i)((^| )r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')),length(substring(companies.name from '(?i)(.*?r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')) LIMIT 10
Mar 05 16:52:44 le-mbr rails[29845]: Company Load (15.9ms)  SELECT companies.name, companies.id FROM "companies" INNER JOIN "company_types" ON "company_types"."id" = "companies"."company_type_id" WHERE "company_types"."name" = 'Farmer' AND (companies.name ~* 'r.*?o.*?b.*?i.*?n.*?s') ORDER BY length(substring(companies.name from '(?i)((^| )robins)')),length(substring(companies.name from '(?i)((^| )r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(companies.name from '(?i)(.*?r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(companies.name from '(?i)((^| )r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')),length(substring(companies.name from '(?i)(.*?r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')) LIMIT 10
Mar 05 16:52:44 le-mbr rails[29845]: Company Load (7.4ms)  SELECT "companies".* FROM "companies" INNER JOIN "company_types" ON "company_types"."id" = "companies"."company_type_id" INNER JOIN "company_classifiers" ON "company_classifiers"."to_company_id" = "companies"."id" WHERE "company_types"."name" = 'Farmer' AND "company_classifiers"."from_company_id" = 323 AND (company_classifiers.value ILIKE '%robins%')
Mar 05 16:52:44 le-mbr rails[29845]: Paddock Load (171.6ms)  SELECT "paddocks".* FROM "paddocks" INNER JOIN "properties" ON "properties"."id" = "paddocks"."property_id" INNER JOIN "companies" ON "companies"."id" = "properties"."company_id" WHERE (paddocks.name ~* 'r.*?o.*?b.*?i.*?n.*?s') ORDER BY length(substring(paddocks.name from '(?i)((^| )robins)')),length(substring(paddocks.name from '(?i)((^| )r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(paddocks.name from '(?i)(.*?r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(paddocks.name from '(?i)((^| )r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')),length(substring(paddocks.name from '(?i)(.*?r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')) LIMIT 10
Mar 05 16:52:44 le-mbr rails[29845]: Property Load (14.7ms)  SELECT "properties".* FROM "properties" INNER JOIN "companies" ON "companies"."id" = "properties"."company_id" WHERE (properties.name ~* 'r.*?o.*?b.*?i.*?n.*?s') ORDER BY length(substring(properties.name from '(?i)((^| )robins)')),length(substring(properties.name from '(?i)((^| )r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(properties.name from '(?i)(.*?r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(properties.name from '(?i)((^| )r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')),length(substring(properties.name from '(?i)(.*?r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')) LIMIT 10
Mar 05 16:52:44 le-mbr rails[29845]: User Load (14.5ms)  SELECT "users".* FROM "users" INNER JOIN "companies" ON "companies"."id" = "users"."company_id" WHERE (users.name ~* 'r.*?o.*?b.*?i.*?n.*?s') ORDER BY length(substring(users.name from '(?i)((^| )robins)')),length(substring(users.name from '(?i)((^| )r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(users.name from '(?i)(.*?r\\.\\*\\?\\ o\\.\\*\\?\\ b\\.\\*\\?\\ i\\.\\*\\?\\ n\\.\\*\\?\\ s)')),length(substring(users.name from '(?i)((^| )r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')),length(substring(users.name from '(?i)(.*?r\\.\\*\\?o\\.\\*\\?b\\.\\*\\?i\\.\\*\\?n\\.\\*\\?s)')) LIMIT 10
Mar 05 16:52:44 le-mbr rails[29845]: Notification Load (0.4ms)  SELECT "notifications".* FROM "notifications" WHERE (notifications.status = 'active') AND (user_id IS NULL AND company_id IS NULL) LIMIT 1
Mar 05 16:52:44 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:44 le-mbr rails[29845]: GC STATISTICS
Mar 05 16:52:44 le-mbr rails[29845]: + Mem:  1013328 kb
Mar 05 16:52:44 le-mbr rails[29845]: + GCs:  0
Mar 05 16:52:44 le-mbr rails[29845]: + Num:  72093
Mar 05 16:52:44 le-mbr rails[29845]: + Size: 3976 kb
Mar 05 16:52:44 le-mbr rails[29845]: + Time: 0.0 ms
Mar 05 16:52:44 le-mbr rails[29845]: + All:  322.66 ms
Mar 05 16:52:44 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:45 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:45 le-mbr rails[29845]: APP OBJECTS
Mar 05 16:52:45 le-mbr rails[29845]: + Total: 794564
Mar 05 16:52:45 le-mbr rails[29845]: + String: 117063
Mar 05 16:52:45 le-mbr rails[29845]: + Array: 36527
Mar 05 16:52:45 le-mbr rails[29845]: + Hash: 47350
Mar 05 16:52:45 le-mbr rails[29845]: + Regexp: 132
Mar 05 16:52:45 le-mbr rails[29845]: + MetaSymbol: 12
Mar 05 16:52:45 le-mbr rails[29845]: + ActiveRecord::Base: 5887
Mar 05 16:52:45 le-mbr rails[29845]: --------------------------------------------------------------------------------
Mar 05 16:52:45 le-mbr rails[29845]: Completed 200 OK in 2625ms (Views: 4.9ms | ActiveRecord: 255.2ms)
Mar 05 16:52:46 le-mbr rails[29845]: Oink Action: auto_completes#site_objects
Mar 05 16:52:46 le-mbr rails[29845]: Memory usage: 4047112 | PID: 29845
Mar 05 16:52:46 le-mbr rails[29845]: Instantiation Breakdown: Total: 128 | Role: 68 | Company: 21 | User: 11 | Property: 10 | Paddock: 10 | Relationship: 2 | Component: 2 | ActiveRecord::SessionStore::Session: 1 | CompanyType: 1 | PlannedSeason: 1 | Profile: 1
Mar 05 16:52:46 le-mbr rails[29845]: Oink Log Entry Complete

Based on the timestamps it looks like it spent 2 seconds calculating / writing the profiling information. That's probably because so many String, Array and Hash objects were created in that request, and we need to iterate over them all. The "All" entry under "GC STATISTICS" is measuring the time spent in the action. So everything on top of that is setup and teardown.