Re: Interesting speed anomaly

Gavin Sherry írta:

>On Thu, 15 Dec 2005, Gavin Sherry wrote:
>
>
>
>>On Wed, 14 Dec 2005, Zoltan Boszormenyi wrote:
>>
>>
>>
>>>Tom Lane írta:
>>>
>>>
>>>
>>>>Zoltan Boszormenyi <zboszor(at)dunaweb(dot)hu> writes:
>>>>
>>>>
>>>>
>>>>
>>>>>$ time echo "select * from v_invoice_browse where code||inv_no = 'CARO200000020'" | dbaccess db
>>>>>
>>>>>
>>>>>
>>>>>
>>>>
>>>>
>>>>
>>>>>Is there a way to speed this operation up?
>>>>>
>>>>>
>>>>>
>>>>>
>>>>Make an expression index on "code||inv_no", if you think this case is
>>>>important enough to be worth maintaining an extra index for.
>>>>
>>>>(This is not on-topic for -hackers, IMHO. Try pgsql-perform.)
>>>>
>>>> regards, tom lane
>>>>
>>>>
>>>>
>>>>
>>>>
>>>Thanks for both the hint and the pointer to the mailing list.
>>>My problem is, I can't see how could I create any index on a view.
>>>PostgreSQL refuses it:
>>>
>>>create index iinvbrowse1 on v_invoice_browse ((code||inv_no));
>>>ERROR: "v_invoice_browse" is not a table
>>>
>>>Creating indexes on the 12 invoice tables, like this:
>>>
>>>create index iinvoice1 on invoice1 (('PREFIX'||id));
>>>
>>>
>>Are you creating the index on (core || id) on on the string 'PREFIX' or
>>some other literal?
>>
>>
>
>Sorry, I sent this email instead of cancelling it. I take it 'code' is a
>string generated by the query, for example: "select 'CAR' as code,* from
>cars ...."? If so, it seems strange that we do not use the expressional
>index. Could you send the output of explain analyze?
>
>Thanks,
>
>Gavin
>
>
>

The VIEW is created like this (shorter example):

create view v1 (code,num) as
select 'AAA',id from table1
union
select 'BBB',id from table2;

I created the indexes on the individual tables as

create index index1 on table1 (('AAA'||id));
create index index2 on table2 (('BBB'||id));

Every index has the same literal the table is associated with in the VIEW.

Here is the explain analyze output, on PostgreSQL 8.0.3.
I can test the same from 8.1.1 tomorrow.

*************************************************
# explain analyze select * from v_invoice_browse where code||inv_no =
'CARO200000020';

QUERY PLAN

------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
Subquery Scan v_invoice_browse (cost=346661.81..356932.96 rows=403
width=680) (actual time=9184.529..9735.884 rows=1 loops=1)
Filter: ((code || (inv_no)::text) = 'CARO200000020'::text)
-> Unique (cost=346661.81..355523.19 rows=80558 width=188) (actual
time=9184.313..9602.540 rows=84693 loops=1)
-> Sort (cost=346661.81..346863.21 rows=80558 width=188)
(actual time=9184.310..9241.868 rows=84693 loops=1)
Sort Key: "?column?", prefix, szam, divitem, "?column?",
"?column?", partner, pmode, inv_date, ins_time, ship_date, pterm, netto,
total, vat, decimal14_2_1, "?column?", "?column?", rectify,
invoice_rect, status, acc_status, dpaym, dpaym_incl, netto_w_dpaym,
vat_w_dpaym, acc_group, currency, car, "?column?", userid, bank_account,
"?column?", "?column?", "?column?", "?column?", "?column?", "?column?",
diff_tax, prcar, "case", inv_no, "?column?"
-> Append (cost=0.00..321067.25 rows=80558 width=188)
(actual time=0.149..4540.736 rows=84693 loops=1)
-> Subquery Scan "*SELECT* 1"
(cost=0.00..148200.17 rows=23571 width=188) (actual time=0.148..735.239
rows=24508 loops=1)
-> Nested Loop (cost=0.00..147964.46
rows=23571 width=188) (actual time=0.120..408.176 rows=24508 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.033..0.062 rows=1 loops=1)
-> Seq Scan on pssysinvoice p
(cost=0.00..2.17 rows=1 width=7) (actual time=0.022..0.034 rows=1 loops=1)
Filter: ((code)::text =
'GENI'::text)
-> Seq Scan on psgenjointemp t
(cost=0.00..1.01 rows=1 width=8) (actual time=0.001..0.016 rows=1 loops=1)
-> Seq Scan on mminigeninvoice h
(cost=0.00..1637.49 rows=23571 width=173) (actual time=0.048..81.226
rows=24508 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.006
rows=1 loops=3405)
Index Cond: (szam = $7)
-> Index Scan using icarprorder1 on
mmcarprorder po (cost=0.00..3.06 rows=1 width=20) (actual
time=0.024..0.025 rows=1 loops=15)
Index Cond: (szam = $6)
-> Subquery Scan "*SELECT* 2"
(cost=0.00..19569.22 rows=6067 width=173) (actual time=0.133..222.421
rows=6374 loops=1)
-> Nested Loop (cost=0.00..19508.55
rows=6067 width=173) (actual time=0.102..120.924 rows=6374 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.029..0.034 rows=1 loops=1)
-> Seq Scan on pssysinvoice p
(cost=0.00..2.17 rows=1 width=7) (actual time=0.018..0.021 rows=1 loops=1)
Filter: ((code)::text =
'GENO'::text)
-> Seq Scan on psgenjointemp t
(cost=0.00..1.01 rows=1 width=8) (actual time=0.001..0.003 rows=1 loops=1)
-> Seq Scan on hmouigeninvoice h
(cost=0.00..418.41 rows=6067 width=158) (actual time=0.024..18.507
rows=6374 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.006
rows=1 loops=1506)
Index Cond: (szam = $4)
-> Subquery Scan "*SELECT* 3"
(cost=2477.12..61103.33 rows=17448 width=182) (actual
time=123.516..1608.985 rows=17673 loops=1)
-> Nested Loop (cost=2477.12..60928.85
rows=17448 width=182) (actual time=123.484..1308.538 rows=17673 loops=1)
-> Seq Scan on psgenjointemp t
(cost=0.00..1.01 rows=1 width=8) (actual time=0.001..0.002 rows=1 loops=1)
-> Nested Loop (cost=2477.12..6035.95
rows=17448 width=174) (actual time=123.405..881.408 rows=17673 loops=1)
-> Seq Scan on pssysinvoice p
(cost=0.00..2.17 rows=1 width=7) (actual time=0.019..0.026 rows=1 loops=1)
Filter: ((code)::text =
'SERO'::text)
-> Hash Join
(cost=2477.12..5859.29 rows=17448 width=167) (actual
time=123.365..685.709 rows=17673 loops=1)
Hash Cond:
("outer".worksheet = "inner".szam)
-> Merge Join
(cost=0.00..1955.97 rows=17448 width=159) (actual time=0.181..259.128
rows=17673 loops=1)
Merge Cond:
("outer".szam = "inner".invoice)
-> Index Scan using
iserinvoice1 on hlserinvoice h (cost=0.00..1317.25 rows=17455
width=155) (actual time=0.083..48.727 rows=17680 loops=1)
Filter:
((status = 2) OR (status = 3) OR (status = 4) OR (status = 5) OR (status
= 6))
-> Index Scan using
iserinv_ws2 on rmserinv_ws r (cost=0.00..376.41 rows=17674 width=8)
(actual time=0.066..13.867 rows=17674 loops=1)
-> Hash
(cost=2232.10..2232.10 rows=29210 width=12) (actual
time=112.809..112.809 rows=0 loops=1)
-> Seq Scan on
hlserworksheet w (cost=0.00..2232.10 rows=29210 width=12) (actual
time=0.023..96.831 rows=29210 loops=1)
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.006
rows=1 loops=17652)
Index Cond: (szam = $5)
-> Subquery Scan "*SELECT* 4"
(cost=2477.12..18188.34 rows=4660 width=147) (actual
time=117.116..401.767 rows=4680 loops=1)
-> Hash Join (cost=2477.12..18141.74
rows=4660 width=147) (actual time=117.077..327.933 rows=4680 loops=1)
Hash Cond: ("outer".worksheet =
"inner".szam)
-> Nested Loop (cost=0.00..313.12
rows=4660 width=139) (actual time=0.083..45.284 rows=4680 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.038..0.050 rows=1 loops=1)
-> Seq Scan on
pssysinvoice p (cost=0.00..2.17 rows=1 width=7) (actual
time=0.024..0.034 rows=1 loops=1)
Filter: ((code)::text
= 'GARO'::text)
-> Seq Scan on
psgenjointemp t (cost=0.00..1.01 rows=1 width=8) (actual
time=0.002..0.004 rows=1 loops=1)
-> Seq Scan on hlsergarinvoice
h (cost=0.00..263.32 rows=4660 width=124) (actual time=0.025..8.666
rows=4680 loops=1) Filter:
((status = 2) OR (status = 3) OR (status = 4) OR (status = 5) OR (status
= 6))
-> Hash (cost=2232.10..2232.10
rows=29210 width=12) (actual time=116.241..116.241 rows=0 loops=1)
-> Seq Scan on hlserworksheet w
(cost=0.00..2232.10 rows=29210 width=12) (actual time=0.026..99.493
rows=29210 loops=1)
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.006
rows=1 loops=4680)
Index Cond: (szam = $1)
-> Subquery Scan "*SELECT* 5"
(cost=2477.12..27668.25 rows=7592 width=147) (actual
time=112.818..622.238 rows=8641 loops=1)
-> Hash Join (cost=2477.12..27592.33
rows=7592 width=147) (actual time=112.779..487.632 rows=8641 loops=1)
Hash Cond: ("outer".worksheet =
"inner".szam)
-> Nested Loop (cost=0.00..585.55
rows=7591 width=139) (actual time=0.081..82.083 rows=8641 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.036..0.050 rows=1 loops=1)
-> Seq Scan on
pssysinvoice p (cost=0.00..2.17 rows=1 width=7) (actual
time=0.023..0.035 rows=1 loops=1)
Filter: ((code)::text
= 'INTR'::text)
-> Seq Scan on
psgenjointemp t (cost=0.00..1.01 rows=1 width=8) (actual
time=0.001..0.003 rows=1 loops=1)
-> Seq Scan on hlserininvoice h
(cost=0.00..506.44 rows=7591 width=124) (actual time=0.025..15.979
rows=8641 loops=1) Filter:
((status = 2) OR (status = 3) OR (status = 4) OR (status = 5) OR (status
= 6))
-> Hash (cost=2232.10..2232.10
rows=29210 width=12) (actual time=111.967..111.967 rows=0 loops=1)
-> Seq Scan on hlserworksheet w
(cost=0.00..2232.10 rows=29210 width=12) (actual time=0.045..96.613
rows=29210 loops=1)
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.006
rows=1 loops=8629)
Index Cond: (szam = $1)
-> Subquery Scan "*SELECT* 6"
(cost=463.87..1559.07 rows=6760 width=174) (actual time=28.401..327.715
rows=6903 loops=1)
-> Hash Join (cost=463.87..1491.47
rows=6760 width=174) (actual time=28.371..222.841 rows=6903 loops=1)
Hash Cond: ("outer".szam = "inner".invoice)
-> Nested Loop (cost=0.00..451.60
rows=6773 width=166) (actual time=0.083..82.704 rows=6918 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.034..0.048 rows=1 loops=1)
-> Seq Scan on
pssysinvoice p (cost=0.00..2.17 rows=1 width=7) (actual
time=0.022..0.033 rows=1 loops=1)
Filter: ((code)::text
= 'PARO'::text)
-> Seq Scan on
psgenjointemp t (cost=0.00..1.01 rows=1 width=8) (actual
time=0.001..0.002 rows=1 loops=1)
-> Seq Scan on hlstrinvoice h
(cost=0.00..380.68 rows=6773 width=151) (actual time=0.027..18.831
rows=6918 loops=1)
Filter: ((status = 2) OR
(status = 3) OR (status = 4) OR (status = 5) OR (status = 6))
-> Hash (cost=405.61..405.61
rows=6905 width=12) (actual time=28.095..28.095 rows=0 loops=1)
-> Merge Join
(cost=0.00..405.61 rows=6905 width=12) (actual time=0.126..24.112
rows=6904 loops=1)
Merge Cond: ("outer".szam =
"inner"."order")
-> Index Scan using
istrcustorder1 on hlstrcustorder c (cost=0.00..155.92 rows=5703
width=8) (actual time=0.054..4.119 rows=5698 loops=1)
-> Index Scan using
istrinv_order3 on rmstrinv_order r (cost=0.00..149.21 rows=6904
width=8) (actual time=0.049..5.071 rows=6904 loops=1)
-> Subquery Scan "*SELECT* 7"
(cost=133.95..31198.54 rows=4933 width=182) (actual time=7.382..239.894
rows=5048 loops=1)
-> Hash Join (cost=133.95..31149.21
rows=4933 width=182) (actual time=7.349..152.786 rows=5048 loops=1)
Hash Cond: ("outer".norder = "inner".szam)
-> Seq Scan on hmouicarinvoice h
(cost=0.00..330.58 rows=4933 width=163) (actual time=0.027..14.656
rows=5048 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
-> Hash (cost=127.97..127.97
rows=2389 width=23) (actual time=7.216..7.216 rows=0 loops=1)
-> Nested Loop
(cost=0.00..127.97 rows=2389 width=23) (actual time=0.084..5.788
rows=2389 loops=1)
-> Nested Loop
(cost=0.00..3.19 rows=1 width=15) (actual time=0.045..0.049 rows=1 loops=1)
-> Seq Scan on
pssysinvoice p (cost=0.00..2.17 rows=1 width=7) (actual
time=0.032..0.034 rows=1 loops=1)
Filter:
((code)::text = 'CARO'::text)
-> Seq Scan on
psgenjointemp t (cost=0.00..1.01 rows=1 width=8) (actual
time=0.001..0.002 rows=1
loops=1) -> Seq Scan on
mmcarnorder c (cost=0.00..100.89 rows=2389 width=8) (actual
time=0.020..1.994 rows=2389 loops=1) SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.005
rows=1 loops=5017)
Index Cond: (szam = $3)
-> Index Scan using icarprorder1 on
mmcarprorder po (cost=0.00..3.06 rows=1 width=20) (actual
time=0.015..0.016 rows=1 loops=31)
Index Cond: (szam = $4)
-> Subquery Scan "*SELECT* 8"
(cost=95.81..9977.93 rows=3059 width=172) (actual time=5.200..140.517
rows=3106 loops=1)
-> Hash Join (cost=95.81..9947.34 rows=3059
width=172) (actual time=5.168..88.887 rows=3106 loops=1)
Hash Cond: ("outer".sorder = "inner".szam)
-> Seq Scan on hmouishcinvoice h
(cost=0.00..204.88 rows=3059 width=153) (actual time=0.027..9.218
rows=3106 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
-> Hash (cost=91.63..91.63 rows=1672
width=23) (actual time=5.038..5.038 rows=0 loops=1)
-> Nested Loop
(cost=0.00..91.63 rows=1672 width=23) (actual time=0.048..4.079
rows=1672 loops=1)
-> Nested Loop
(cost=0.00..3.19 rows=1 width=15) (actual time=0.026..0.037 rows=1 loops=1)
-> Seq Scan on
pssysinvoice p (cost=0.00..2.17 rows=1 width=7) (actual
time=0.015..0.024 rows=1 loops=1)
Filter:
((code)::text = 'SHCO'::text)
-> Seq Scan on
psgenjointemp t (cost=0.00..1.01 rows=1 width=8) (actual
time=0.001..0.002 rows=1
loops=1) -> Seq Scan on
mmcarsorder c (cost=0.00..71.72 rows=1672 width=8) (actual
time=0.014..1.474 rows=1672 loops=1)
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.005
rows=1 loops=3104)
Index Cond: (szam = $3)
-> Subquery Scan "*SELECT* 9" (cost=0.00..50.62
rows=5 width=96) (actual time=0.196..0.361 rows=4 loops=1)
-> Nested Loop (cost=0.00..50.57 rows=5
width=96) (actual time=0.161..0.286 rows=4 loops=1)
-> Nested Loop (cost=0.00..4.37
rows=5 width=92) (actual time=0.061..0.090 rows=4 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.025..0.030 rows=1 loops=1)
-> Seq Scan on
pssysinvoice p (cost=0.00..2.17 rows=1 width=7) (actual
time=0.014..0.018 rows=1 loops=1)
Filter: ((code)::text
= 'RES'::text)
-> Seq Scan on
psgenjointemp t (cost=0.00..1.01 rows=1 width=8) (actual
time=0.001..0.002 rows=1 loops=1)
-> Seq Scan on mmcarresinvoice
h (cost=0.00..1.12 rows=5 width=77) (actual time=0.023..0.030 rows=4
loops=1)
Filter: ((status = 2) OR
(status = 3) OR (status = 4) OR (status = 5) OR (status = 6) OR (status
= 7))
-> Index Scan using immcarsorder1 on
mmcarsorder c (cost=0.00..3.02 rows=1 width=8) (actual
time=0.017..0.018 rows=1 loops=4)
Index Cond: ("outer".sorder = c.szam)
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.008..0.009
rows=1 loops=4)
Index Cond: (szam = $2)
-> Index Scan using icarprorder1 on
mmcarprorder po (cost=0.00..3.06 rows=1 width=20) (never executed)
Index Cond: (szam = $1)
-> Subquery Scan "*SELECT* 10"
(cost=0.00..3090.88 rows=955 width=152) (actual time=0.113..38.540
rows=1006 loops=1)
-> Nested Loop (cost=0.00..3081.33 rows=955
width=152) (actual time=0.078..21.903 rows=1006 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.013..0.025 rows=1 loops=1)
-> Seq Scan on pssysinvoice p
(cost=0.00..2.17 rows=1 width=7) (actual time=0.007..0.017 rows=1 loops=1)
Filter: ((code)::text =
'NOTO'::text)
-> Seq Scan on psgenjointemp t
(cost=0.00..1.01 rows=1 width=8) (actual time=0.001..0.002 rows=1 loops=1)
-> Seq Scan on hmouinotinvoice h
(cost=0.00..73.68 rows=955 width=137) (actual time=0.022..3.016
rows=1006 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
SubPlan
-> Index Scan using isercar1 on
mmsercar sc (cost=0.00..3.13 rows=1 width=21) (actual time=0.005..0.005
rows=1 loops=802) Index Cond:
(szam = $0)
-> Subquery Scan "*SELECT* 11" (cost=0.00..77.22
rows=971 width=150) (actual time=0.103..28.261 rows=1046 loops=1)
-> Nested Loop (cost=0.00..67.51 rows=971
width=150) (actual time=0.064..13.408 rows=1046 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.019..0.036 rows=1 loops=1)
-> Seq Scan on pssysinvoice p
(cost=0.00..2.17 rows=1 width=7) (actual time=0.010..0.024 rows=1 loops=1)
Filter: ((code)::text =
'VIRI'::text)
-> Seq Scan on psgenjointemp t
(cost=0.00..1.01 rows=1 width=8) (actual time=0.001..0.002 rows=1 loops=1)
-> Seq Scan on hminivirinvoice h
(cost=0.00..54.60 rows=971 width=135) (actual time=0.020..2.696
rows=1046 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
-> Subquery Scan "*SELECT* 12" (cost=0.00..383.68
rows=4537 width=151) (actual time=0.114..146.647 rows=5704 loops=1)
-> Nested Loop (cost=0.00..338.31 rows=4537
width=151) (actual time=0.076..71.278 rows=5704 loops=1)
-> Nested Loop (cost=0.00..3.19
rows=1 width=15) (actual time=0.028..0.037 rows=1 loops=1)
-> Seq Scan on pssysinvoice p
(cost=0.00..2.17 rows=1 width=7) (actual time=0.016..0.022 rows=1 loops=1)
Filter: ((code)::text =
'VIRO'::text)
-> Seq Scan on psgenjointemp t
(cost=0.00..1.01 rows=1 width=8) (actual time=0.001..0.002 rows=1 loops=1)
-> Seq Scan on hmouivirinvoice h
(cost=0.00..289.75 rows=4537 width=136) (actual time=0.023..13.592
rows=5704 loops=1)
Filter: ((status = 2) OR (status
= 3) OR (status = 4) OR (status = 5) OR (status = 6))
Total runtime: 9749.043 ms
*************************************************

It's interesting that if I rewrite this huge VIEW + the WHERE condition
manually like this (the above short example continues)

select * from table1 where 'AAA'||id = 'AAA2005000001'
union
select * from table2 where 'BBB'||id = 'AAA2005000001';

then it will use the expression indexes and it runs under about 300 msecs.
Replacing UNION with UNION ALL further reduces the runtime,
as someone suggested on the pgsql-performance list.

Best regards,
Zoltán Böszörményi