On Wed, Jan 25, 2012 at 8:51 PM, Linus P. <
[email protected]> wrote:
Well, maybe it’s not necessary… It is the slowest of my queries as far
as I can see anyway.
I’m using Rails 3.2 and I have enabled automatic EXPLAIN on slow queries
(>0.5s). This query is currently being “explained” in my console when I run
it on my localhost. “SQL (556.5ms) …”
556.5ms seems a bit slow to me, isn’t it?
Indeed.
TL;DR
- On my system, a similar query seems a lot faster
- you may have a bad “sort” on categories.name, subcategories.name
without
index ?
I had a similar database structure here, filled it with 10,000 records
(you
seem to have around 2,200 ?),
postgresql 9.1 on Ubuntu and ran a similar query:
cl1 = ContactLine.includes(:contact) ; nil
cl2 = cl1.includes(:contact => :person) ; nil
cl3 = cl2.where(“people.first_name = ‘M’ OR people.first_name =
‘longer_word’”) ; nil # 8 times ‘M’ and 8 times ‘longer_word’
cl4 = cl3.order(“contacts.email”) ; nil
167:0> puts cl4.explain
SQL (16.9ms) SELECT “contact_lines”.“id” AS …
FROM “contact_lines”
LEFT OUTER JOIN “contacts” ON “contacts”.“id” =
“contact_lines”.“contact_id”
LEFT OUTER JOIN “people” ON “people”.“id” = “contacts”.“person_id”
WHERE (people.first_name = ‘M’ OR people.first_name = ‘longer_word’)
ORDER BY contacts.email
EXPLAIN (1.4ms) EXPLAIN SELECT “contact_lines”.“id” …
EXPLAIN for: SELECT “contact_lines”.“id” …
QUERY PLAN
Sort (cost=691.05…691.06 rows=1 width=2699)
Sort Key: contacts.email
→ Hash Join (cost=455.53…691.04 rows=1 width=2699)
Hash Cond: (contact_lines.contact_id = contacts.id)
→ Seq Scan on contact_lines (cost=0.00…198.00 rows=10000
width=50)
→ Hash (cost=455.52…455.52 rows=1 width=2649)
→ Hash Join (cost=229.01…455.52 rows=1 width=2649)
Hash Cond: (contacts.person_id = people.id)
→ Seq Scan on contacts (cost=0.00…189.00
rows=10000 width=41)
→ Hash (cost=229.00…229.00 rows=1 width=2608)
→ Seq Scan on people (cost=0.00…229.00
rows=1 width=2608)
Filter: (((first_name)::text =
‘M’::text)
OR ((first_name)::text = ‘longer_word’::text))
(12 rows)
=> nil
The log on a development server (plain rails s
) is:
Started GET “/contact_lines” for 127.0.0.1 at 2012-01-25 22:26:41 +0100
Processing by ContactLinesController#index as HTML
SQL (8.6ms) SELECT “contact_lines”.“id” AS t0_r0…
… ORDER BY contacts.email
Rendered contact_lines/index.html.haml within layouts/application
(99.4ms)
Completed 200 OK in 105ms (Views: 89.5ms | ActiveRecord: 14.7ms)
About indexes … The above is without explicitly set indexes.
Assuming that the first_name::text filtering would be the most
expensive, I
added
this migration:
class AddIndexFirstName < ActiveRecord::Migration
def change
add_index :people, :first_name
end
end
This worked:
\d people
Table "public.people"
Column | Type |
Modifiers
--------------±----------------------------±----------------------------------------------------
id | integer | not null default
nextval(‘people_id_seq’::regclass)
full_name | character varying(255) |
first_name | character varying(255) |
…
Indexes:
“people_pkey” PRIMARY KEY, btree (id)
“index_people_on_first_name” btree (first_name)
The EXPLAIN changed:
SQL (12.7ms) SELECT “contact_lines”.“id” AS t0_r0, …
QUERY PLAN
Sort (cost=474.59…474.59 rows=1 width=2699)
Sort Key: contacts.email
→ Hash Join (cost=239.07…474.58 rows=1 width=2699)
Hash Cond: (contact_lines.contact_id = contacts.id)
→ Seq Scan on contact_lines (cost=0.00…198.00 rows=10000
width=50)
→ Hash (cost=239.05…239.05 rows=1 width=2649)
→ Hash Join (cost=12.54…239.05 rows=1 width=2649)
Hash Cond: (contacts.person_id = people.id)
→ Seq Scan on contacts (cost=0.00…189.00
rows=10000 width=41)
→ Hash (cost=12.53…12.53 rows=1 width=2608)
→ Bitmap Heap Scan on people
(cost=8.52…12.53 rows=1 width=2608)
Recheck Cond: (((first_name)::text =
‘M’::text) OR ((first_name)::text = ‘longer_word’::text))
→ BitmapOr (cost=8.52…8.52 rows=1
width=0)
→ Bitmap Index Scan on
index_people_on_first_name (cost=0.00…4.26 rows=1 width=0)
Index Cond:
((first_name)::text = ‘M’::text)
→ Bitmap Index Scan on
index_people_on_first_name (cost=0.00…4.26 rows=1 width=0)
Index Cond:
((first_name)::text = ‘longer_word’::text)
(17 rows)
But the performance was the same. A log of a hit to the server.
Processing by ContactLinesController#index as HTML
SQL (11.7ms) SELECT “contact_lines”.“id” AS t0_r0, …
…
WHERE (people.first_name = ‘M’ OR people.first_name = ‘longer_word’)
Rendered contact_lines/index.html.haml within layouts/application
(104.1ms)
Completed 200 OK in 112ms (Views: 90.8ms | ActiveRecord: 19.8ms)
Maybe it is related to something in your query plan that I do not see
here
and is suspicious:
from
http://snipt.net/Linuus/postgresql?key=e4728f444b24839e3f80adf3829bcba9
Sort (cost=3267.32…3272.25 rows=1972 width=2104) (actual
time=39.308…39.468 rows=1880 loops=1)
Sort Key: categories.name, subcategories.name
Sort Method: quicksort Memory: 313kB ####### ??
from
http://snipt.net/Linuus/rails-query?key=ee73173643e8d21a5a487d8a329c7a26
you seem to not have an index on those 2 name
columns ?
What happens to performance when you remove try sort ?
Category.eager_load(:subcategories)
.joins(“INNER JOIN products AS p ON resellercategories.id =
p.resellercategory_id”)
WITHOUT SORT .order("categories.name ASC, subcategories.name
ASC")
.where(“p.gender = ‘unisex’ OR p.gender = ‘male’”)
If that makes a significant difference, what happens when you add
indices
on those 2
columns (and possibly remove some indices on other columns) ?
Then a bunch of other stuff is happening and I get this:
“Completed 200 OK in 2737ms (Views: 813.5ms | ActiveRecord: 703.2ms)”
So, 550ms of the total 703ms is the above query.
Maybe I’m just picky?
Those indeed seem “large” numbers for a new/fresh application…
Peter