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 <t...@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@lists.osgeo.org
https://lists.osgeo.org/mailman/listinfo/postgis-users
_______________________________________________
postgis-users mailing list
postgis-users@lists.osgeo.org
https://lists.osgeo.org/mailman/listinfo/postgis-users
_______________________________________________
postgis-users mailing list
postgis-users@lists.osgeo.org
https://lists.osgeo.org/mailman/listinfo/postgis-users
_______________________________________________
postgis-users mailing list
postgis-users@lists.osgeo.org
https://lists.osgeo.org/mailman/listinfo/postgis-users
_______________________________________________
postgis-users mailing list
postgis-users@lists.osgeo.org
https://lists.osgeo.org/mailman/listinfo/postgis-users

Reply via email to