Обсуждение: View with and without ::text casting performs differently.

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

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

Brian Fehrle <brianf@consistentstate.com> writes:
> 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.

This is normal (varchar doesn't actually have any operations of its own).

> 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.

I rather doubt that the now-explicit-instead-of-implicit casts have much
to do with that.  It seems more likely that you forgot to re-ANALYZE in
the new database, or there are some different planner settings, or
something along that line.

            regards, tom lane

On 09/05/2013 05:50 PM, Tom Lane wrote:
> Brian Fehrle <brianf@consistentstate.com> writes:
>> 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.
> This is normal (varchar doesn't actually have any operations of its own).
>
>> 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.
> I rather doubt that the now-explicit-instead-of-implicit casts have much
> to do with that.  It seems more likely that you forgot to re-ANALYZE in
> the new database, or there are some different planner settings, or
> something along that line.
I have two versions of the view in place on the same server, one with
the typecasting and one without, and this is where I see the differences
(no ::text runs in 0.5ms and with ::text runs in 13 or so minutes with
nested loop), so it's all running off the same statistics on the data.

Running an analyse on all tables involved did not change the query plan
on the 'bad' version of the view (default_statistics_target = 400)

- Brian F
>
>             regards, tom lane

Brian Fehrle <brianf@consistentstate.com> writes:
> On 09/05/2013 05:50 PM, Tom Lane wrote:
>> I rather doubt that the now-explicit-instead-of-implicit casts have much
>> to do with that.  It seems more likely that you forgot to re-ANALYZE in
>> the new database, or there are some different planner settings, or
>> something along that line.

> I have two versions of the view in place on the same server, one with
> the typecasting and one without, and this is where I see the differences
> (no ::text runs in 0.5ms and with ::text runs in 13 or so minutes with
> nested loop), so it's all running off the same statistics on the data.

Hm.  Can you provide a self-contained example?

            regards, tom lane

On 09/06/2013 12:35 PM, Tom Lane wrote:
> Brian Fehrle <brianf@consistentstate.com> writes:
>> On 09/05/2013 05:50 PM, Tom Lane wrote:
>>> I rather doubt that the now-explicit-instead-of-implicit casts have much
>>> to do with that.  It seems more likely that you forgot to re-ANALYZE in
>>> the new database, or there are some different planner settings, or
>>> something along that line.
>> I have two versions of the view in place on the same server, one with
>> the typecasting and one without, and this is where I see the differences
>> (no ::text runs in 0.5ms and with ::text runs in 13 or so minutes with
>> nested loop), so it's all running off the same statistics on the data.
> Hm.  Can you provide a self-contained example?

I'll see what I can do to recreate this with bogus data. It's sensitive
data that may just be some sort of anomaly in terms of the data
distribution that is causing it.

- Brian F
>
>             regards, tom lane