Performance issue with computed columns

[robe]

As discussed in this blog post:

​https://blog.rustprooflabs.com/2019/12/postgres12-generated-columns-postgis

Using generated columns seems to be much slower than using on the fly computation. I was able to replicate similar results on my tiger data.

In my case, I was using tiger colorado state boundary and edges.

PostgreSQL 12.4, compiled by Visual C++ build 1914, 64-bit POSTGIS="3.0.2 3.0.2" [EXTENSION] PGSQL="120" GEOS="3.8.1-CAPI-1.13.3" SFCGAL="1.3.8" PROJ="Rel. 5.2.0, September 15th, 2018" LIBXML="2.9.9" LIBJSON="0.12" LIBPROTOBUF="1.2.1" WAGYU="0.4.3 (Internal)"

A computed query such as this

-- took 6 secs 314 msec

SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r
        ON ST_Contains(ST_Buffer(ST_Transform(way_4326, 3857), 500), r.way);

In contrast, way_buffer created using:

ALTER TABLE test.co_random_points
    ADD way_buffer GEOMETRY (POLYGON, 3857) 
    GENERATED ALWAYS AS (ST_Buffer(ST_Transform(way_4326, 3857), 500)) STORED ;

-- 30 secs

SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON ST_Contains(p.way_buffer, r.way);

-- manual buffer create using

ALTER TABLE test.co_random_points
    ADD way_buffer_manual GEOMETRY (POLYGON, 3857);
	
UPDATE test.co_random_points
    SET way_buffer_manual = way_buffer;
	
CREATE INDEX ix_random_points_way_buffer_manual_gist ON test.co_random_points
    USING GIST (way_buffer_manual);

-- returns in 1 secs 227ms
SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON ST_Contains(p.way_buffer_manual, r.way)
    ;

Can think of a reason why a computed column should be any worse than a manual column.

I'll try to come up with a smaller test case we can easily fit in our testing

[robe]

I think I may have found the culprit. I suspect our postgis_addbbox doesn't get run for computed columns. So to prove I did this:

ALTER TABLE test.co_random_points
    ADD way_buffer_cbox GEOMETRY (POLYGON, 3857) 
    GENERATED ALWAYS AS (postgis_AddBBox(ST_Buffer(ST_Transform(way_4326, 3857), 500)) ) STORED ;
	
CREATE INDEX ix_random_points_way_buffer_cbox_gist ON test.co_random_points
    USING GIST (way_buffer_cbox);
	
-- 1 secs 208 msec.
SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON ST_Contains(p.way_buffer_cbox, r.way)
    ;

Comparable to what you get with the manual as expected

[robe]

okay got excited too quickly. I have to recheck but it seemed like

1) Creating the new computed column and using it was fast 1 secs 208 ms 2) But then I ran the query against the old computed column and it too was fast ` 1 secs 300 ms

3) Recreating the table and adding in the 2 new computed columns with the index, and doing a vacuum (analyze,verbose) test.co_random_points.

Then running the query testing both computed columns, they are back to 30 secs to complete. I'm going to revisit this to see if they become fast again. Maybe some external process is fixing things.

[robe]

One more observation:

 --   1 secs 203 msec, count: 28446
SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON (p.way_buffer ~ r.way AND _ST_Contains(p.way_buffer,r.way) );

Has plan below which suggest our supportfn logic may be playing a role in the slowness.

Finalize Aggregate  (cost=393149116.81..393149116.82 rows=1 width=8) (actual time=1140.497..1163.716 rows=1 loops=1)
  ->  Gather  (cost=393149116.70..393149116.81 rows=1 width=8) (actual time=1139.926..1163.705 rows=2 loops=1)
        Workers Planned: 1
        Workers Launched: 1
        ->  Partial Aggregate  (cost=393148116.70..393148116.71 rows=1 width=8) (actual time=1120.645..1120.646 rows=1 loops=2)
              ->  Nested Loop  (cost=0.29..393135032.63 rows=5233627 width=664) (actual time=2.239..1115.969 rows=14223 loops=2)
                    ->  Parallel Seq Scan on co_random_points p  (cost=0.00..3451.65 rows=11765 width=1232) (actual time=0.028..14.876 rows=10000 loops=2)
                    ->  Index Scan using ix_co_road_line_way_gist on co_road_line r  (cost=0.29..33410.90 rows=445 width=252) (actual time=0.087..0.109 rows=1 loops=20000)
                          Index Cond: (way @ p.way_buffer)
                          Filter: _st_contains(p.way_buffer, way)
                          Rows Removed by Filter: 0
Planning Time: 0.229 ms
Execution Time: 1163.951 ms

In contrast:

 --   28 secs 431 msec. count: 28446
SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON (ST_Contains(p.way_buffer,r.way) );

has explain:

Finalize Aggregate  (cost=393107931.66..393107931.67 rows=1 width=8) (actual time=27923.252..27928.296 rows=1 loops=1)
  ->  Gather  (cost=393107931.54..393107931.65 rows=1 width=8) (actual time=27922.892..27928.290 rows=2 loops=1)
        Workers Planned: 1
        Workers Launched: 1
        ->  Partial Aggregate  (cost=393106931.54..393106931.55 rows=1 width=8) (actual time=27903.523..27903.524 rows=1 loops=2)
              ->  Nested Loop  (cost=0.28..393096258.35 rows=4269278 width=664) (actual time=4.112..27895.261 rows=14223 loops=2)
                    ->  Parallel Seq Scan on co_road_line r  (cost=0.00..59761.44 rows=785044 width=252) (actual time=0.091..157.895 rows=666688 loops=2)
                    ->  Index Scan using ix_co_random_points_way_buffer on co_random_points p  (cost=0.28..500.64 rows=2 width=1232) (actual time=0.041..0.041 rows=0 loops=1333375)
                          Index Cond: (way_buffer ~ r.way)
                          Filter: st_contains(way_buffer, r.way)
                          Rows Removed by Filter: 0
Planning Time: 2.210 ms
Execution Time: 27928.598 ms

-- manually stored (stores same as computed)

--  1 secs 104 msec.,count: 28446
SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON (ST_Contains(p.way_buffer_manual,r.way) );

-- explain

Finalize Aggregate  (cost=393114999.14..393114999.15 rows=1 width=8) (actual time=1066.612..1090.536 rows=1 loops=1)
  ->  Gather  (cost=393114999.03..393114999.14 rows=1 width=8) (actual time=1066.291..1090.529 rows=2 loops=1)
        Workers Planned: 1
        Workers Launched: 1
        ->  Partial Aggregate  (cost=393113999.03..393113999.04 rows=1 width=8) (actual time=1047.151..1047.152 rows=1 loops=2)
              ->  Nested Loop  (cost=0.29..393103325.83 rows=4269278 width=1768) (actual time=2.982..1042.833 rows=14223 loops=2)
                    ->  Parallel Seq Scan on co_random_points p  (cost=0.00..8451.65 rows=11765 width=2336) (actual time=1.310..18.678 rows=10000 loops=2)
                    ->  Index Scan using ix_co_road_line_way_gist on co_road_line r  (cost=0.29..33410.90 rows=133 width=252) (actual time=0.080..0.101 rows=1 loops=20000)
                          Index Cond: (way @ p.way_buffer_manual)
                          Filter: st_contains(p.way_buffer_manual, way)
                          Rows Removed by Filter: 0
Planning Time: 2.202 ms
Execution Time: 1090.765 ms

[robe]

okay and now some magic happened so speed is fine and fast as expected:

-- 1 secs 185 ms	
EXPLAIN ANALYZE SELECT COUNT(p.*)
    FROM test.co_random_points p
    INNER JOIN test.co_road_line r 
        ON (ST_Contains(p.way_buffer,r.way) );

plan

Finalize Aggregate  (cost=393114999.14..393114999.15 rows=1 width=8) (actual time=1119.286..1142.649 rows=1 loops=1)
  ->  Gather  (cost=393114999.03..393114999.14 rows=1 width=8) (actual time=1118.663..1142.641 rows=2 loops=1)
        Workers Planned: 1
        Workers Launched: 1
        ->  Partial Aggregate  (cost=393113999.03..393113999.04 rows=1 width=8) (actual time=1099.408..1099.409 rows=1 loops=2)
              ->  Nested Loop  (cost=0.29..393103325.83 rows=4269278 width=1768) (actual time=3.032..1094.740 rows=14223 loops=2)
                    ->  Parallel Seq Scan on co_random_points p  (cost=0.00..8451.65 rows=11765 width=2336) (actual time=1.320..19.293 rows=10000 loops=2)
                    ->  Index Scan using ix_co_road_line_way_gist on co_road_line r  (cost=0.29..33410.90 rows=133 width=252) (actual time=0.084..0.106 rows=1 loops=20000)
                          Index Cond: (way @ p.way_buffer)
                          Filter: st_contains(p.way_buffer, way)
                          Rows Removed by Filter: 0
Planning Time: 2.220 ms
Execution Time: 1142.879 ms

[robe]

Downgrading this to a medium from high, as it seems to be a fleeting problem. One that goes away after some time. What process makes it go away though is a mystery to me. I thought if it was just something to do with table analyzing then a

vacuum (analyze, verbose) the_table;

would have fixed it, but instead seems to be some other process that runs that eventually fixes it.

[Algunenano]

Note that in the fast plan each parallel worker (2 of them) is doing a seq scan over co_random_points and then for each point (10k each) an index scan over over ix_co_road_line_way_gist. In the slow plan it's happening the other way around, each worker does a seq scan over co_road_line, and then for each line (666688 each) it does a seq scan over the points.

So it looks that the thing that's making things slow is not having good stats and once that is solves things work as expected. Can you try to do the process analyzing both tables (the random points and the ones with the generated column) before running any query and see if those times are normal?

[robe]

Replying to Algunenano:

Note that in the fast plan each parallel worker (2 of them) is doing a seq scan over co_random_points and then for each point (10k each) an index scan over over ix_co_road_line_way_gist. In the slow plan it's happening the other way around, each worker does a seq scan over co_road_line, and then for each line (666688 each) it does a seq scan over the points.

So it looks that the thing that's making things slow is not having good stats and once that is solves things work as expected. Can you try to do the process analyzing both tables (the random points and the ones with the generated column) before running any query and see if those times are normal?

I suspect you are right. I thought I had analyzed both tables to confirm, but it's possible I missed one. This time around, first run I rebuilt all the tables (didn't do any analyze what so ever) and the computed geometry column ran just as fast as the manual one (both around 1 sec, 356ms (give or take 50 ms) and both much faster than the adhoc buffer.

That said I'm just going to close this out after I create a regress test. I don't think there is an issue here, but probably good to test computed columns in our arsenal.

So I'll create a test that has both a computed and non-computed, a fake street table, analyze both tables and do a timing compare using clock_timestamp and throw an error if the computed timing ends up being slower than the adhoc buffering.

[Regina Obe <lr@…>]

In a15f8921/git:

Add test for computed columns references #4750 for PostGIS 3.1