View with and without ::text casting performs differently.

From: Brian Fehrle <brianf(at)consistentstate(dot)com>
To: pgsql-performance(at)postgresql(dot)org
Subject: View with and without ::text casting performs differently.
Date: 2013-09-05 22:45:16
Message-ID: 5229097C.4070401@consistentstate.com
Views: Raw Message | Whole Thread | Download mbox | Resend email
Thread:
Lists: pgsql-performance

Hi All,

I have a view, that when created with our create statement works
wonderfully, a query on the view with a standard where clause that
narrows the result to a single row performs in under a single ms.
However, when we export this view and re-import it (dump and restore of
the database, which happens often), the exported version of the view has
been modified by Postgres to include various typecasting of some columns
to text.

All columns that it typecasts to text are varchar(20), so there is
nothing wrong in what it's doing there. However, with the view
definition including the ::text casting, the query planner changes and
it goes into a nested loop, taking a query from <1ms to over ten minutes.

*NOTE: *When I execute the queries with and without ::text myself
outside of the view, there is no issues. the query plan is correct and I
get my result fast, it's only when putting the query in the view and
then executing it does it do the nested loop and take forever.

----------- Query plan for view defined without ::text ---------------
Nested Loop (cost=17.440..272.590 rows=1 width=1810) (actual
time=0.515..0.527 rows=1 loops=1)
-> Nested Loop (cost=17.440..265.480 rows=1 width=1275) (actual
time=0.471..0.482 rows=1 loops=1)
-> Nested Loop (cost=17.440..265.190 rows=1 width=761)
(actual time=0.460..0.471 rows=1 loops=1)
-> Nested Loop (cost=17.440..258.910 rows=1 width=186)
(actual time=0.437..0.447 rows=1 loops=1)
-> Nested Loop (cost=17.440..258.590 rows=1
width=154) (actual time=0.417..0.425 rows=1 loops=1)
-> Nested Loop (cost=17.440..252.240 rows=1
width=160) (actual time=0.388..0.395 rows=1 loops=1)
Join Filter:
((alpha_yankee.bravo_papa)::text = (six_zulu.kilo_uniform)::text)
-> Nested Loop (cost=0.000..108.990
rows=7 width=137) (actual time=0.107..0.109 rows=1 loops=1)
-> Nested Loop
(cost=0.000..102.780 rows=10 width=124) (actual time=0.077..0.078 rows=1
loops=1)
-> Index Scan using
juliet_yankee on alpha_yankee (cost=0.000..18.240 rows=13 width=84)
(actual time=0.043..0.044 rows=1 loops=1)
Index Cond:
((bravo_charlie)::text = 'tango'::text)
-> Index Scan using
charlie_quebec on juliet_three (cost=0.000..6.490 rows=1 width=40)
(actual time=0.029..0.029 rows=1 loops=1)
Index Cond:
((echo)::text = (alpha_yankee.kilo_yankee)::text)
Filter:
((four)::text = 'alpha_whiskey'::text)
-> Index Scan using
charlie_yankee on romeo (cost=0.000..0.610 rows=1 width=33) (actual
time=0.027..0.027 rows=1 loops=1)
Index Cond: ((echo)::text
= (juliet_three.lima_victor)::text)
Filter:
((lima_bravo)::text = 'alpha_whiskey'::text)
-> Bitmap Heap Scan on papa six_zulu
(cost=17.440..20.450 rows=1 width=64) (actual time=0.268..0.276 rows=21
loops=1)
Recheck Cond:
(((charlie_victor)::text = (juliet_three.echo)::text) AND
((bravo_india)::text = (alpha_yankee.juliet_whiskey)::text))
-> BitmapAnd
(cost=17.440..17.440 rows=1 width=0) (actual time=0.255..0.255 rows=0
loops=1)
-> Bitmap Index Scan on
alpha_foxtrot (cost=0.000..6.710 rows=28 width=0) (actual
time=0.048..0.048 rows=21 loops=1)
Index Cond:
((charlie_victor)::text = (juliet_three.echo)::text)
-> Bitmap Index Scan on
delta (cost=0.000..10.440 rows=108 width=0) (actual time=0.202..0.202
rows=757 loops=1)
Index Cond:
((bravo_india)::text = (alpha_yankee.juliet_whiskey)::text)
-> Index Scan using whiskey_india on
alpha_lima (cost=0.000..6.340 rows=1 width=57) (actual
time=0.026..0.027 rows=1 loops=1)
Index Cond: ((echo)::text =
(six_zulu.bravo_india)::text)
-> Index Scan using golf on whiskey_oscar
(cost=0.000..0.310 rows=1 width=43) (actual time=0.017..0.018 rows=1
loops=1)
Index Cond: ((echo)::text =
(alpha_lima.whiskey_six)::text)
-> Index Scan using bravo_foxtrot on mike_mike
lima_charlie (cost=0.000..6.270 rows=1 width=617) (actual
time=0.020..0.020 rows=1 loops=1)
Index Cond: ((echo)::text =
(six_zulu.kilo_uniform)::text)
-> Index Scan using charlie_papa on mike_oscar
(cost=0.000..0.270 rows=1 width=530) (actual time=0.008..0.008 rows=1
loops=1)
Index Cond: ((echo)::text = (lima_charlie.yankee)::text)
-> Index Scan using juliet_victor on juliet_six six_seven
(cost=0.000..7.080 rows=1 width=556) (actual time=0.033..0.034 rows=1
loops=1)
Index Cond: ((echo)::text = 'tango'::text)
Total runtime: 0.871 ms
----------------------------------------------------------------------------------------

----------- Query plan for view defined WITH ::text ---------------
Nested Loop (cost=176136.470..3143249.320 rows=1 width=1810) (actual
time=16357.306..815170.609 rows=1 loops=1)
Join Filter: ((alpha_yankee.bravo_charlie)::text =
(six_seven.echo)::text)
-> Index Scan using juliet_victor on juliet_six six_seven
(cost=0.000..7.080 rows=1 width=556) (actual time=0.035..0.038 rows=1
loops=1)
Index Cond: ((echo)::text = 'tango'::text)
-> Nested Loop (cost=176136.470..3143242.190 rows=2 width=1275)
(actual time=13071.765..812874.705 rows=6815445 loops=1)
-> Nested Loop (cost=176136.470..3143241.560 rows=2
width=1243) (actual time=13071.742..760766.802 rows=6815445 loops=1)
-> Hash Join (cost=176136.470..3143228.850 rows=2
width=1249) (actual time=13071.694..632785.712 rows=6815445 loops=1)
Hash Cond: ((six_zulu.kilo_uniform)::text =
(lima_charlie.echo)::text)
-> Merge Join (cost=174404.520..3141496.860 rows=2
width=160) (actual time=13023.713..619787.785 rows=6815445 loops=1)
Merge Cond: ((juliet_three.echo)::text =
(six_zulu.charlie)::text)
Join Filter:
(((alpha_yankee.juliet_whiskey)::text = (six_zulu.bravo_india)::text)
AND ((alpha_yankee.bravo_papa)::text = (six_zulu.kilo_uniform)::text))
-> Merge Join (cost=174391.960..1013040.600
rows=5084399 width=137) (actual time=13023.660..68777.622 rows=7805731
loops=1)
Merge Cond:
((alpha_yankee.kilo_yankee)::text = (juliet_three.echo)::text)
-> Index Scan using five on
alpha_yankee (cost=0.000..739352.050 rows=9249725 width=84) (actual
time=0.027..14936.587 rows=9204640 loops=1)
-> Sort (cost=174391.750..175895.330
rows=601433 width=53) (actual time=13023.526..14415.639 rows=7952904
loops=1)
Sort Key: juliet_three.echo
Sort Method: quicksort Memory:
139105kB
-> Hash Join
(cost=62105.650..116660.060 rows=601433 width=53) (actual
time=669.244..2278.990 rows=814472 loops=1)
Hash Cond:
((juliet_three.lima_victor)::text = (romeo.echo)::text)
-> Seq Scan on
juliet_three (cost=0.000..40391.860 rows=814822 width=40) (actual
time=0.009..677.160 rows=814473 loops=1)
Filter:
((four)::text = 'alpha_whiskey'::text)
-> Hash
(cost=57562.740..57562.740 rows=363433 width=33) (actual
time=668.812..668.812 rows=363736 loops=1)
Buckets: 65536
Batches: 1 Memory Usage: 23832kB
-> Seq Scan on
romeo (cost=0.000..57562.740 rows=363433 width=33) (actual
time=0.012..489.104 rows=363736 loops=1)
Filter:
((lima_bravo)::text = 'alpha_whiskey'::text)
-> Materialize (cost=0.000..1192114.040
rows=10236405 width=64) (actual time=0.030..72475.323 rows=140608673
loops=1)
-> Index Scan using alpha_foxtrot on
papa six_zulu (cost=0.000..1166523.030 rows=10236405 width=64) (actual
time=0.024..22466.849 rows=10176345 loops=1)
-> Hash (cost=1568.500..1568.500 rows=13076
width=1131) (actual time=47.954..47.954 rows=13054 loops=1)
Buckets: 2048 Batches: 1 Memory Usage:
13551kB
-> Hash Join (cost=19.950..1568.500
rows=13076 width=1131) (actual time=0.415..24.461 rows=13054 loops=1)
Hash Cond:
((lima_charlie.yankee)::text = (mike_oscar.echo)::text)
-> Seq Scan on mike_mike lima_charlie
(cost=0.000..1368.760 rows=13076 width=617) (actual time=0.006..5.948
rows=13054 loops=1)
-> Hash (cost=18.310..18.310 rows=131
width=530) (actual time=0.397..0.397 rows=131 loops=1)
Buckets: 1024 Batches: 1
Memory Usage: 73kB
-> Seq Scan on mike_oscar
(cost=0.000..18.310 rows=131 width=530) (actual time=0.007..0.221
rows=131 loops=1)
-> Index Scan using whiskey_india on alpha_lima
(cost=0.000..6.340 rows=1 width=57) (actual time=0.017..0.017 rows=1
loops=6815445)
Index Cond: ((echo)::text =
(six_zulu.bravo_india)::text)
-> Index Scan using golf on whiskey_oscar (cost=0.000..0.310
rows=1 width=43) (actual time=0.006..0.006 rows=1 loops=6815445)
Index Cond: ((echo)::text = (alpha_lima.whiskey_six)::text)
Total runtime: 815589.464 ms
----------------------------------------------------------------------------------------

If I set enable_nestloop = off, then it works perfectly, however I don't
really have the option to do this, I'd rather see what's causing it.

Any thoughts?

Thanks,
- Brian F

Responses

Browse pgsql-performance by date

  From Date Subject
Next Message Brian Fehrle 2013-09-05 22:46:55 Re: View with and without ::text casting performs differently.
Previous Message Merlin Moncure 2013-09-05 22:42:19 Re: [PERFORM] Can you please suggest me some links where I can learn: