Oh, I didn't realize that analyze gave that much more info. I've got a
lot to learn about this tuning stuff ;-)
I've attached the output. I see from the new output where the slow query
is taking its time (the nested loop at line 10), but I still have no
idea why this plan is getting chosen....
Thanks!
- DAP
>-----Original Message-----
>From: pgsql-performance-owner@xxxxxxxxxxxxxx
>[mailto:pgsql-performance-owner@xxxxxxxxxxxxxx] On Behalf Of
>Russell Smith
>Sent: Tuesday, November 16, 2004 11:36 PM
>To: pgsql-performance@xxxxxxxxxxxxxx
>Subject: Re: [PERFORM] query plan question
>
>On Wed, 17 Nov 2004 02:54 pm, you wrote:
>> I have a query for which postgres is generating a different
>plan on different machines. The database schema is the same,
>the dataset is the same, the configuration is the same (e.g.,
>pg_autovacuum running in both cases), both systems are Solaris
>9. The main difference in the two systems is that one is sparc
>and the other is intel.
>>
>> The query runs in about 40 ms on the intel box, but takes
>about 18 seconds on the sparc box. Now, the intel boxes we
>have are certainly faster, but I'm curious why the query plan
>might be different.
>>
>> For the intel:
>>
>> QUERY PLAN
>> Unique (cost=11.50..11.52 rows=2 width=131)
>> -> Sort (cost=11.50..11.50 rows=2 width=131)
>> Sort Key: up.prefix, s.name, s.tuid, s.foundryversion
>> -> Hash Join (cost=10.42..11.49 rows=2 width=131)
>> Hash Cond: ("outer".dbid = "inner"."schema")
>> -> Seq Scan on "schema" s (cost=0.00..1.02
>rows=2 width=128)
>> -> Hash (cost=10.41..10.41 rows=4 width=11)
>> -> Nested Loop (cost=0.00..10.41
>rows=4 width=11)
>> -> Nested Loop (cost=0.00..2.14
>rows=4 width=4)
>> -> Seq Scan on flow fl
>(cost=0.00..0.00 rows=1 width=4)
>> Filter: (servicetype = 646)
>> -> Index Scan using
>usage_flow_i on "usage" u (cost=0.00..2.06 rows=6 width=8)
>> Index Cond: (u.flow =
>"outer".dbid)
>> -> Index Scan using
>usageparameter_usage_i on usageparameter up (cost=0.00..2.06
>rows=1 width=15)
>> Index Cond: (up."usage" =
>"outer".dbid)
>> Filter: ((prefix)::text <>
>> 'xsd'::text)
>>
>> For the sparc:
>>
>> QUERY PLAN
>> Unique (cost=10.81..10.83 rows=1 width=167)
>> -> Sort (cost=10.81..10.82 rows=1 width=167)
>> Sort Key: up.prefix, s.name, s.tuid, s.foundryversion
>> -> Nested Loop (cost=9.75..10.80 rows=1 width=167)
>> Join Filter: ("outer".flow = "inner".dbid)
>> -> Hash Join (cost=9.75..10.79 rows=1 width=171)
>> Hash Cond: ("outer".dbid = "inner"."schema")
>> -> Seq Scan on "schema" s
>(cost=0.00..1.02 rows=2 width=128)
>> -> Hash (cost=9.75..9.75 rows=1 width=51)
>> -> Nested Loop (cost=0.00..9.75
>rows=1 width=51)
>> Join Filter:
>("inner"."usage" = "outer".dbid)
>> -> Index Scan using
>usage_flow_i on "usage" u (cost=0.00..4.78 rows=1 width=8)
>> -> Index Scan using
>usageparameter_schema_i on usageparameter up (cost=0.00..4.96
>rows=1 width=51)
>> Filter:
>((prefix)::text <> 'xsd'::text)
>> -> Seq Scan on flow fl (cost=0.00..0.00
>rows=1 width=4)
>> Filter: (servicetype = 646)
>>
>Unique (cost=11.50..11.52 rows=2 width=131) Unique
>(cost=10.81..10.83 rows=1 width=167)
>
>The estimations for the cost is basically the same, 10ms for
>the first row. Can you supply Explain analyze to see what
>it's actually doing?
>
>Russell Smith
>
>---------------------------(end of
>broadcast)---------------------------
>TIP 6: Have you searched our list archives?
>
> http://archives.postgresql.org
>
QUERY PLAN
"Unique (cost=10.81..10.83 rows=1 width=167) (actual time=19390.684..19390.687 rows=1 loops=1)"
" -> Sort (cost=10.81..10.82 rows=1 width=167) (actual time=19390.678..19390.679 rows=1 loops=1)"
" Sort Key: up.prefix, s.name, s.tuid, s.foundryversion"
" -> Nested Loop (cost=9.75..10.80 rows=1 width=167) (actual time=19377.051..19390.391 rows=1 loops=1)"
" Join Filter: ("outer".flow = "inner".dbid)"
" -> Hash Join (cost=9.75..10.79 rows=1 width=171) (actual time=19173.684..19181.827 rows=770 loops=1)"
" Hash Cond: ("outer".dbid = "inner"."schema")"
" -> Seq Scan on "schema" s (cost=0.00..1.02 rows=2 width=128) (actual time=0.240..0.693 rows=20 loops=1)"
" -> Hash (cost=9.75..9.75 rows=1 width=51) (actual time=19173.354..19173.354 rows=0 loops=1)"
" -> Nested Loop (cost=0.00..9.75 rows=1 width=51) (actual time=30.456..19166.759 rows=770 loops=1)"
" Join Filter: ("inner"."usage" = "outer".dbid)"
" -> Index Scan using usage_flow_i on "usage" u (cost=0.00..4.78 rows=1 width=8) (actual time=0.593..9.576 rows=771 loops=1)"
" -> Index Scan using usageparameter_schema_i on usageparameter up (cost=0.00..4.96 rows=1 width=51) (actual time=16.171..22.411 rows=770 loops=771)"
" Filter: ((prefix)::text <> 'xsd'::text)"
" -> Seq Scan on flow fl (cost=0.00..0.00 rows=1 width=4) (actual time=0.007..0.260 rows=1 loops=770)"
" Filter: (servicetype = 646)"
"Total runtime: 19391.173 ms"
QUERY PLAN
"Unique (cost=11.50..11.52 rows=2 width=131) (actual time=0.724..0.727 rows=1 loops=1)"
" -> Sort (cost=11.50..11.50 rows=2 width=131) (actual time=0.722..0.723 rows=1 loops=1)"
" Sort Key: up.prefix, s.name, s.tuid, s.foundryversion"
" -> Hash Join (cost=10.42..11.49 rows=2 width=131) (actual time=0.551..0.670 rows=1 loops=1)"
" Hash Cond: ("outer".dbid = "inner"."schema")"
" -> Seq Scan on "schema" s (cost=0.00..1.02 rows=2 width=128) (actual time=0.027..0.129 rows=20 loops=1)"
" -> Hash (cost=10.41..10.41 rows=4 width=11) (actual time=0.478..0.478 rows=0 loops=1)"
" -> Nested Loop (cost=0.00..10.41 rows=4 width=11) (actual time=0.355..0.455 rows=1 loops=1)"
" -> Nested Loop (cost=0.00..2.14 rows=4 width=4) (actual time=0.179..0.249 rows=3 loops=1)"
" -> Seq Scan on flow fl (cost=0.00..0.00 rows=1 width=4) (actual time=0.057..0.112 rows=1 loops=1)"
" Filter: (servicetype = 646)"
" -> Index Scan using usage_flow_i on "usage" u (cost=0.00..2.06 rows=6 width=8) (actual time=0.115..0.121 rows=3 loops=1)"
" Index Cond: (u.flow = "outer".dbid)"
" -> Index Scan using usageparameter_usage_i on usageparameter up (cost=0.00..2.06 rows=1 width=15) (actual time=0.044..0.046 rows=0 loops=3)"
" Index Cond: (up."usage" = "outer".dbid)"
" Filter: ((prefix)::text <> 'xsd'::text)"
"Total runtime: 0.842 ms"
