[postgis-users] Changed intersection test speed after PG 11 -> 12 and PostGIS 2.5 -> 3 upgrade

Thu Mar 5 06:40:34 PST 2020

Sorry for sending the information in multiple pieces. What I meant to 
write as well is that I ran REINDEX on the relevant 12/3 table 
(treenode_edge) and reran the queries. It didn't make a measurable 
difference. The same for VACUUM, no difference. I ran VACUUM FULL too on 
the table and if anything it became slightly slower (see below).

Since the plans are the same and run-times are the same (with all data 
in memory) in 11/2.5 and 12/2.5 it is enough to only look at 12. Still, 
this leaves us with the unexplained difference between these two indes 
scans (for the query with &&&):

12.7:

   Index Scan using treenode_edge_gix on treenode_edge te  
   (cost=0.42..391.68 rows=1 width=16) (actual time=0.936..27.404 
   rows=1005 loops=1)
     Index Cond: (edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry)
     Filter: ((edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry) AND (project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
     Rows Removed by Filter: 5
     Buffers: shared hit=1370
   Planning Time: 0.782 ms
   Execution Time: 27.518 ms

12/3.0:

   Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.67..28.71 rows=1 width=16) (actual time=0.730..163.358 rows=1004 loops=1)
     Index Cond: ((edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry) AND (edge &&& st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision)))
     Filter: ((project_id = 1) AND st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
     Rows Removed by Filter: 5
     Buffers: shared hit=6546
   Planning Time: 1.312 ms
   Execution Time: 163.471 ms

The only difference is that more pages are hit in 12/3.0 (Buffers: 
shared hit 1370 vs 6546). This difference becomes even more apparent 
after the VACUUM FULL in 12/3.0:

   Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.67..28.71 rows=1 width=16) (actual time=2.673..206.723 rows=1004 loops=1)
     Index Cond: ((edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry) AND (edge &&& st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision)))
     Filter: ((project_id = 1) AND st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
     Rows Removed by Filter: 5
     Buffers: shared hit=8195
   Planning Time: 1.209 ms
   Execution Time: 207.005 ms

It is surprising that after a VACUUM FULL results in more pages read.  
Also, like stated before it seems the bitmap heap scan doesn't play a 
role if result start to become bigger.

You also mentioned sampling profilers before:

>>>If you could run a sampling profiler against your two queries that
>>>would pick up the places where the execution paths differ for the
>>>different versions, it's all I'm trying to do, but I haven't been able
>>>to even replicate the behavious so far, so I am at an impasse at this
>>>moment.

I have never worked with a sampling profiler, but I assume it varies 
parameters in a query and logs the plans? Do you have a particular one 
in mind? On a brief search I found pgstatprof. I suppose in my case it 
should sample different query bounding box sizes and see if there are 
plan changes for some parameters.

Cheers,
Tom

On Thu, Mar 05, 2020 at 08:28:14AM -0500, Tom Kazimiers wrote:
>A small correction to my last mail: I only noticed after I have sent 
>it that the 11.7/2.5 query didn't load everything from memory and had 
>to hit the disk (Buffers: shared hit=302 read=1349 dirtied=2). This is 
>the first query, with everything in cache:
>
>11.7/2.5.2 (query 1 with &&&):
>
> Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.42..353.59 rows=1 width=16) (actual time=0.656..23.590 rows=1005 loops=1)
>   Index Cond: (edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry)
>   Filter: ((edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry) AND (project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>   Rows Removed by Filter: 5
>   Buffers: shared hit=1621
> Planning Time: 0.684 ms
> Execution Time: 23.683 ms
>
>And this fits indeed better to the initial observation that PostGIS 
>2.5 is faster than 3.0 for this query if both &&& and ST_3DDWithin are 
>used.  3.0 is faster if &&& is not used, but only because the 2.5 
>queries get much slower.
>
>Best,
>Tom
>
>On Thu, Mar 05, 2020 at 12:39:06AM -0500, Tom Kazimiers wrote:
>>Hi Paul,
>>
>>Thank you for your continued effort to find out what's going on 
>>here!  This is all indeed very strange.
>>
>>I just set up a second test database with more entries (50 million) 
>>using 12.2/2.5.3 and ran the relevant query from the initial post 
>>(returning ~1000 rows) in this database as well as 12.2/3.0 and 
>>11/2.5.3:
>>
>> EXPLAIN (ANALYZE, BUFFERS)
>> SELECT te.id, te.parent_id
>> FROM treenode_edge te
>> WHERE te.edge &&& ST_MakeLine(ARRAY[
>>     ST_MakePoint(471548.0, 330140.0, 160440.0),
>>     ST_MakePoint(542460.0, 290140.0, 160400.0)] ::geometry[])
>> AND ST_3DDWithin(te.edge, ST_MakePolygon(ST_MakeLine(ARRAY[
>>     ST_MakePoint(471548.0,  290140.0,    160420.0),
>>     ST_MakePoint(542460.0, 290140.0,    160420.0),
>>     ST_MakePoint(542460.0, 330140.0, 160420.0),
>>     ST_MakePoint(471548.0,  330140.0, 160420.0),
>>     ST_MakePoint(471548.0,  290140.0,    160420.0)]::geometry[])),
>>     20.0)
>> AND te.project_id = 1;
>>
>>11.7/2.5.2:
>>
>> Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.42..353.59 rows=1 width=16) (actual time=5.386..172.324 rows=1005 loops=1)
>>   Index Cond: (edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry)
>>   Filter: ((edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry) AND (project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>   Rows Removed by Filter: 5
>>   Buffers: shared hit=302 read=1349 dirtied=2
>> Planning Time: 1.324 ms
>> Execution Time: 172.535 ms
>>
>>12/2.5.3:
>>
>> Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.42..391.68 rows=1 width=16) (actual time=0.936..27.404 rows=1005 loops=1)
>>   Index Cond: (edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry)
>>   Filter: ((edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry) AND (project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>   Rows Removed by Filter: 5
>>   Buffers: shared hit=1370
>> Planning Time: 0.782 ms
>> Execution Time: 27.518 ms
>>
>>12/3.0:
>>
>> Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.67..28.71 rows=1 width=16) (actual time=0.730..163.358 rows=1004 loops=1)
>>   Index Cond: ((edge &&& '01020000800200000000000000F0C71C41000000007026144100000000C095034100000000F88D20410000000070B511410000000080940341'::geometry) AND (edge &&& st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision)))
>>   Filter: ((project_id = 1) AND st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>   Rows Removed by Filter: 5
>>   Buffers: shared hit=6546
>> Planning Time: 1.312 ms
>> Execution Time: 163.471 ms
>>
>>This is all very strange. Like in the initial mail, I don't see any 
>>bitmap scans anymore, only the index scan with different runtimes. 
>>Also, now the 12/2.5.3 query has now the speed of the original 
>>11/2.5.3 query (?!) from my first post. The estimates are wrong in 
>>on all version though. All databases have had run ANALYZE right 
>>beforehand and have a comparible configuration with the relevant 
>>part of the data in memory.
>>
>>Also, changing the function cost of ST_3DDWithin, doesn't have any 
>>effect anymore. I can't get it to run with the bitmap heap scan 
>>again (which doesn't seem to play a role with bigger result sets 
>>anyway).
>>
>>I suppose the main difference is that 12/2.5.3 was just recreatead 
>>from a backup and is therefore tightly packed on disk (and memory?). 
>>Could this have such a big influence?
>>
>>The timings above suggest to me that neither Postgres 12 nor PostGIS 
>>3 have a negative influence on performance here. I will run a vaccum 
>>and reindex on the 12/3.0 setup (which might take a day or so) and 
>>see if this changes anything.
>>
>>In a previous mail you suggested to only look at the ST_3DDWithin 
>>part, i,e, using this query:
>>
>>  EXPLAIN (ANALYZE, BUFFERS)
>>  SELECT te.id, te.parent_id
>>  FROM treenode_edge te
>>  WHERE ST_3DDWithin(te.edge, ST_MakePolygon(ST_MakeLine(ARRAY[
>>      ST_MakePoint(471548.0,  290140.0,    160420.0),
>>      ST_MakePoint(542460.0, 290140.0,    160420.0),
>>      ST_MakePoint(542460.0, 330140.0, 160420.0),
>>      ST_MakePoint(471548.0,  330140.0, 160420.0),
>>      ST_MakePoint(471548.0,  290140.0,    160420.0)]::geometry[])),
>>      20.0)
>>  AND te.project_id = 1;
>>
>>And this is how that looks like:
>>
>>11/2.5.3:
>>
>> Gather  (cost=16804.64..590073.63 rows=30 width=16) (actual time=366.372..1123.021 rows=782 loops=1)
>>   Workers Planned: 4
>>   Workers Launched: 4
>>   Buffers: shared hit=371525
>>   ->  Parallel Bitmap Heap Scan on treenode_edge te  (cost=15804.64..589070.63 rows=8 width=16) (actual time=372.224..994.656 rows=156 loops=5)
>>         Recheck Cond: (edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>         Filter: ((project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>         Rows Removed by Filter: 187033
>>         Heap Blocks: exact=97218
>>         Buffers: shared hit=371525
>>         ->  Bitmap Index Scan on treenode_edge_2d_gist  (cost=0.00..15804.63 rows=916441 width=0) (actual time=204.907..204.907 rows=1105737 loops=1)
>>               Index Cond: (edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>               Buffers: shared hit=9758
>> Planning Time: 0.470 ms
>> JIT:
>>   Functions: 30
>>   Options: Inlining true, Optimization true, Expressions true, Deforming true
>>   Timing: Generation 4.219 ms, Inlining 197.812 ms, Optimization 188.993 ms, Emission 79.596 ms, Total 470.619 ms
>> Execution Time: 1124.520 ms
>>
>>
>>12/2.5.3:
>>
>> Gather  (cost=24934.73..862262.11 rows=79121 width=16) (actual time=192.531..770.051 rows=1005 loops=1)
>>   Workers Planned: 4
>>   Workers Launched: 4
>>   Buffers: shared hit=104591
>>   ->  Parallel Bitmap Heap Scan on treenode_edge te  (cost=23934.73..853350.01 rows=19780 width=16) (actual time=153.920..675.015 rows=201 loops=5)
>>         Recheck Cond: (edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>         Filter: ((project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>         Rows Removed by Filter: 244695
>>         Heap Blocks: exact=23644
>>         Buffers: shared hit=104591
>>         ->  Bitmap Index Scan on treenode_edge_2d_gist  (cost=0.00..23914.95 rows=1220804 width=0) (actual time=158.067..158.068 rows=1224482 loops=1)
>>               Index Cond: (edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>               Buffers: shared hit=10480
>> Planning Time: 0.470 ms
>> Execution Time: 770.358 ms
>>
>>12/3.0:
>>
>> Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.67..5577.07 rows=4755 width=16) (actual time=0.453..90.967 rows=1004 loops=1)
>>   Index Cond: (edge &&& st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>   Filter: ((project_id = 1) AND st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>   Rows Removed by Filter: 7
>>   Buffers: shared hit=6547 read=4
>> Planning Time: 0.643 ms
>> Execution Time: 91.079 ms
>>
>>Interestingly, here, 12/3.0 does better and doesn't attempt to 
>>parallelize like you observed as well or try to use JIT (it's 
>>enabled in all clusters). At least with PostGIS 2.5 it seems the 
>>extra &&& is also helpful for performance (and I might need the &&& 
>>to limit the results a bit more). Still, while the 12/3 ST_3DDWithin 
>>part is faster than the whole thing on 12/3 run is faster now than 
>>the above 12/2.5.3 run.
>>
>>Without knowing much about the internals of the indices used, I 
>>would assume that a REINDEX could indeed help, because the index 
>>scan would then likely need to cover less memory. If this doesn't 
>>explain the timing difference, I will recreate the 12/3.0 database 
>>from scratch just like I created the 12/2.5 database today (before I 
>>believe the 12/3.0 was created by `pg_upgrade --link`).
>>
>>Best,
>>Tom
>>
>>On Mon, Mar 02, 2020 at 01:40:50PM -0800, Paul Ramsey wrote:
>>>So, this gets stranger the more I poke, but not in any helpful way.
>>>I installed 3.0.2dev and 2.5.4dev in my Pg12 instance and ran the same
>>>query using your test file.
>>>
>>>https://github.com/tomka/tmp/blob/master/postgres/catmaid-postgis-test.pgsql
>>>pg_restore -O -f- catmaid-postgis-test.pgsql | psql postgis254d
>>>
>>>And using this test query:
>>>
>>>explain analyze SELECT Count(*) FROM (
>>>
>>>                     SELECT te.id, te.parent_id
>>>
>>>                                                            FROM
>>>treenode_edge te
>>>
>>>                             WHERE ST_3DDWithin(te.edge,
>>>ST_MakePolygon(ST_MakeLine(ARRAY[
>>>                                       ST_MakePoint(471548.0,
>>>290140.0,    160420.0),
>>>
>>>ST_MakePoint(542460.0, 290140.0,    160420.0),
>>>
>>>                   ST_MakePoint(542460.0, 330140.0, 160420.0),
>>>
>>>                                       ST_MakePoint(471548.0,
>>>330140.0, 160420.0),
>>>
>>>ST_MakePoint(471548.0,  290140.0,    160420.0)]::geometry[])),
>>>
>>>        20.0)
>>>) a;
>>>
>>>And I get a 8ms execution from 12/3 and a 128ms execution from 12/2.5!
>>>
>>>--- pg12/postgis3.0
>>>
>>>Aggregate  (cost=584.97..584.98 rows=1 width=8) (actual
>>>time=7.155..7.155 rows=1 loops=1)
>>> ->  Index Scan using treenode_edge_gix on treenode_edge te
>>>(cost=0.53..584.88 rows=33 width=0) (actual time=0.706..7.057 rows=143
>>>loops=1)
>>>       Index Cond: (edge &&&
>>>st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry,
>>>'20'::double precision))
>>>       Filter: st_3ddwithin(edge,
>>>'0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry,
>>>'20'::double precision)
>>>Planning Time: 2.843 ms
>>>Execution Time: 7.278 ms
>>>
>>>-- pg12/postgis2.5
>>>
>>>Aggregate  (cost=14477.72..14477.73 rows=1 width=8) (actual
>>>time=148.645..148.645 rows=1 loops=1)
>>> ->  Bitmap Heap Scan on treenode_edge te  (cost=1142.85..14472.35
>>>rows=2151 width=0) (actual time=16.940..148.583 rows=143 loops=1)
>>>       Recheck Cond: (edge &&
>>>'0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>>       Filter:
>>>(('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry
>>>&& st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge,
>>>'0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry,
>>>'20'::double precision))
>>>       Rows Removed by Filter: 32400
>>>       Heap Blocks: exact=3507
>>>       ->  Bitmap Index Scan on treenode_edge_2d_gist
>>>(cost=0.00..1142.32 rows=32271 width=0) (actual time=15.024..15.024
>>>rows=32543 loops=1)
>>>             Index Cond: (edge &&
>>>'0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>>Planning Time: 0.833 ms
>>>Execution Time: 148.855 ms
>>>
>>>Also, the 12/2.5 query wants to parallelize (???) while the 12/3 one does not.
>>>
>>>Anyways, it's super funky and not so helpful.
>>>
>>>The trouble with your test set is that it's too small (relative to the
>>>query?) so it's not processing many rows.
>>>
>>>If you could run a sampling profiler against your two queries that
>>>would pick up the places where the execution paths differ for the
>>>different versions, it's all I'm trying to do, but I haven't been able
>>>to even replicate the behavious so far, so I am at an impasse at this
>>>moment.
>>>
>>>P
>>>
>>>
>>>On Tue, Feb 4, 2020 at 1:01 PM Tom Kazimiers <tom at voodoo-arts.net> wrote:
>>>>
>>>>>>Thanks for the report.  I've ticketed as a bug -
>>>>>>https://trac.osgeo.org/postgis/ticket/4635
>>>>
>>>>Thanks for filing the ticket Regina!
>>>>
>>>>On Tue, Feb 04, 2020 at 11:49:44AM -0800, Paul Ramsey wrote:
>>>>>OK, cleaning this out a little.
>>>>>Ticket for reference https://trac.osgeo.org/postgis/ticket/4635#comment:2
>>>>
>>>>"Good" to know that you seem to be able to reproduce this slow-down.
>>>>
>>>>>First, drop all the rest of your testing SQL and just test the contents
>>>>>of the bb_edge CTE. That seems to be sufficient, and it’s the only
>>>>>spatial part.
>>>>
>>>>Good point, I should have restricted it to that from beginning.
>>>>
>>>>>Second, for testing 3.0, drop the use of the &&& operator and see what happens with just the ST_DWithin3D function call, which should be throwing an index op in there implicitly.
>>>>>
>>>>>SELECT Count(*) FROM (
>>>>>SELECT te.id, te.parent_id
>>>>>   FROM treenode_edge te
>>>>>   WHERE ST_3DDWithin(te.edge, ST_MakePolygon(ST_MakeLine(ARRAY[
>>>>>       ST_MakePoint(471548.0,  290140.0,    160420.0),
>>>>>       ST_MakePoint(542460.0, 290140.0,    160420.0),
>>>>>       ST_MakePoint(542460.0, 330140.0, 160420.0),
>>>>>       ST_MakePoint(471548.0,  330140.0, 160420.0),
>>>>>       ST_MakePoint(471548.0,  290140.0,    160420.0)]::geometry[])),
>>>>>       20.0)
>>>>>) a;
>>>>>
>>>>>We are definitely seeing different plans in that CTE.
>>>>
>>>>This is what I get in the test database with 12/3:
>>>>
>>>> Aggregate  (cost=506.38..506.41 rows=1 width=8) (actual time=1.530..1.530 rows=1 loops=1)
>>>>   Buffers: shared hit=198
>>>>   ->  Index Scan using treenode_edge_gix on treenode_edge te  (cost=0.53..506.29 rows=33 width=0) (actual time=0.168..1.512 rows=143 loops=1)
>>>>         Index Cond: (edge &&& st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>>>         Filter: ((project_id = 1) AND st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>>>         Buffers: shared hit=198
>>>> Planning Time: 0.654 ms
>>>> Execution Time: 1.583 ms
>>>>
>>>>Dropping the &&& operator still allows the use of the index it seems and
>>>>is noticeably faster. (In my original query, I used both &&& and
>>>>ST_3DDWithin, because I wanted to reduce the number of false positives
>>>>that I would get with only one of them in some densely populated areas.
>>>>The &&& would make sure every result object bounding box intersects with
>>>>the query bounding box and the ST_3DDWithin would ensure I don't get
>>>>edges that are actually only passing by somewhere close, but not
>>>>actually intersecting the field of view. The line/geometry used with
>>>>ST_3DDWithin is in fact a flat cut through the center of the query
>>>>bounding box. Therefore I believe I still need the &&& in production,
>>>>unfortunately.)
>>>>
>>>>This is what I get for the above query with the test database in the
>>>>11/2.5 setup:
>>>>
>>>> Finalize Aggregate  (cost=10302.14..10302.17 rows=1 width=8) (actual time=43.245..43.245 rows=1 loops=1)
>>>>   Buffers: shared hit=3768
>>>>   ->  Gather  (cost=10301.91..10302.14 rows=2 width=8) (actual time=43.125..47.544 rows=3 loops=1)
>>>>         Workers Planned: 2
>>>>         Workers Launched: 2
>>>>         Buffers: shared hit=3768
>>>>         ->  Partial Aggregate  (cost=9301.91..9301.94 rows=1 width=8) (actual time=27.190..27.190 rows=1 loops=3)
>>>>               Buffers: shared hit=3768
>>>>               ->  Parallel Bitmap Heap Scan on treenode_edge te  (cost=693.46..9299.66 rows=899 width=0) (actual time=4.058..27.175 rows=48 loops=3)
>>>>                     Recheck Cond: (edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>>>                     Filter: ((project_id = 1) AND ('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry && st_expand(edge, '20'::double precision)) AND _st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>>>                     Rows Removed by Filter: 10800
>>>>                     Heap Blocks: exact=2171
>>>>                     Buffers: shared hit=3768
>>>>                     ->  Bitmap Index Scan on treenode_edge_2d_gist  (cost=0.00..692.92 rows=32352 width=0) (actual time=5.430..5.430 rows=32543 loops=1)
>>>>                           Index Cond: (edge && '0103000080010000000500000000000000A0C71C410000000020B51141000000008094034100000000A0C71C4100000000C0261441000000008094034100000000208E204100000000C026144100000000C095034100000000208E20410000000020B5114100000000C095034100000000A0C71C410000000020B511410000000080940341'::geometry)
>>>>                           Buffers: shared hit=261
>>>> Planning Time: 22.836 ms
>>>> Execution Time: 47.885 ms
>>>>
>>>>>We are definitely seeing different plans in that CTE.
>>>>
>>>>Out of curiosity, what is the plan you are seeing?
>>>>
>>>>>Testing for 12/3:
>>>>>
>>>>>12/3 is picking an index scan on the spatial index, which is turning out to be slower.
>>>>>You can adjust the COST of the ST_3DDWithin down: default cost is 10000.
>>>>>Where does the plan change as you adjust it down?
>>>>>ALTER FUNCTION ST_3DDWithin COST 9000;
>>>>
>>>>Once I set it to 608 and lower, this is what I get:
>>>>
>>>> Aggregate  (cost=59.66..59.69 rows=1 width=8) (actual time=1.436..1.436 rows=1 loops=1)
>>>>   Buffers: shared hit=183
>>>>   ->  Bitmap Heap Scan on treenode_edge te  (cost=2.18..59.58 rows=33 width=0) (actual time=1.055..1.418 rows=143 loops=1)
>>>>         Filter: ((project_id = 1) AND st_3ddwithin(edge, '0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>>>         Heap Blocks: exact=119
>>>>         Buffers: shared hit=183
>>>>         ->  Bitmap Index Scan on treenode_edge_gix  (cost=0.00..2.17 rows=19 width=0) (actual time=1.027..1.027 rows=143 loops=1)
>>>>               Index Cond: (edge &&& st_expand('0103000080010000000500000000000000F0C71C410000000070B51141000000002095034100000000F88D20410000000070B51141000000002095034100000000F88D20410000000070261441000000002095034100000000F0C71C410000000070261441000000002095034100000000F0C71C410000000070B511410000000020950341'::geometry, '20'::double precision))
>>>>               Buffers: shared hit=64
>>>> Planning Time: 0.703 ms
>>>> Execution Time: 1.516 ms
>>>>
>>>>The planner doesn't come up with any other plan if I set it to anything
>>>>lower than 608.
>>>>
>>>>>A big change between 2.5 and 3.0 was costing on spatial functions, so
>>>>>seeing different plans is not surprising, especially since the
>>>>>mechanisms for building the plan have changed so much (SQL wrapper
>>>>>functions vs Pg12 support functions). It’s possible that with the cost
>>>>>of the function set so high, and actually being seen by the planner
>>>>>now, we’re getting an index scan that, in this case, is less efficient
>>>>>than the alternative.
>>>>
>>>>I see, thanks for the explanation. In my the 12/3 version of my
>>>>production database (50 million edges), I can't reproduce the cost based
>>>>plan change from above though. No matter how low I set the function cost
>>>>there, I always get the spatial scan in the plan.
>>>>
>>>>Cheers,
>>>>Tom
>>>>_______________________________________________
>>>>postgis-users mailing list
>>>>postgis-users at lists.osgeo.org
>>>>https://lists.osgeo.org/mailman/listinfo/postgis-users
>>>_______________________________________________
>>>postgis-users mailing list
>>>postgis-users at lists.osgeo.org
>>>https://lists.osgeo.org/mailman/listinfo/postgis-users
>>_______________________________________________
>>postgis-users mailing list
>>postgis-users at lists.osgeo.org
>>https://lists.osgeo.org/mailman/listinfo/postgis-users
>_______________________________________________
>postgis-users mailing list
>postgis-users at lists.osgeo.org
>https://lists.osgeo.org/mailman/listinfo/postgis-users