Performance issue

[Alystrasz]

Hello again,
I think I managed to find a reproducible performance issue, using the same configuration as gost/server#171 with the GeoLife dataset (one thing, 2156994 locations).

Trying to get the locations count, hitting v1.0/Things(1)/Locations?$count=true executes this :

SELECT COUNT(DISTINCT A_location.location_id) 
FROM (SELECT location.id AS location_id, location.name AS location_name, 
             location.description AS location_description, 
             location.encodingtype AS location_encodingtype,  
             location.geojson::text AS location_geojson 
             FROM v1.location  WHERE (SELECT thing.id AS thing_id 
                                                           FROM v1.thing INNER JOIN v1.thing_to_location 
                                                                                    ON thing.id = thing_to_location.thing_id 
                                                                                    AND location.id = thing_to_location.location_id  
                                                           WHERE thing.id = 1) 
                                             IS NOT NULL 
                                             ORDER BY location_id DESC) 
AS A_location;

The request leads the postgres to consume 100% of my i7-8650U CPU.

Here is its plan:

                                                                             QUERY PLAN                                                                              
---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=36010995.64..36010995.65 rows=1 width=8) (actual time=7199.216..7199.216 rows=1 loops=1)
   ->  Index Only Scan Backward using location_pkey on location  (cost=0.43..35984156.85 rows=2147103 width=1076) (actual time=0.207..6498.243 rows=2156994 loops=1)
         Filter: ((SubPlan 1) IS NOT NULL)
         Heap Fetches: 2156994
         SubPlan 1
           ->  Nested Loop  (cost=0.57..16.62 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2156994)
                 ->  Index Only Scan using thing_pkey on thing  (cost=0.14..8.16 rows=1 width=8) (actual time=0.001..0.001 rows=1 loops=2156994)
                       Index Cond: (id = 1)
                       Heap Fetches: 2156994
                 ->  Index Scan using fki_location_1 on thing_to_location  (cost=0.43..8.45 rows=1 width=8) (actual time=0.001..0.001 rows=1 loops=2156994)
                       Index Cond: (location.id = location_id)
                       Filter: (thing_id = 1)
 Planning time: 0.473 ms
 Execution time: 7199.305 ms
(14 rows)

Here is an refactored example of the request, which still consumes 100% of CPU, but resolves in around 3 seconds:

SELECT COUNT(DISTINCT A_location.location_id) 
FROM (SELECT location.id AS location_id, location.name AS location_name, 
            location.description AS location_description, 
            location.encodingtype AS location_encodingtype, 
            location.geojson::text AS location_geojson 
            FROM v1.location  
            WHERE EXISTS (SELECT * FROM v1.thing, v1.thing_to_location  
	                                 WHERE thing.id = 1 
                                         AND thing.id = thing_to_location.thing_id 
                                         AND location.id = thing_to_location.location_id)) 
AS A_location;

                                                                      QUERY PLAN                                                                      
------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=244221.14..244221.15 rows=1 width=8) (actual time=3154.462..3154.462 rows=1 loops=1)
   ->  Hash Semi Join  (cost=95649.14..238827.92 rows=2157285 width=8) (actual time=841.538..2413.231 rows=2156994 loops=1)
         Hash Cond: (location.id = thing_to_location.location_id)
         ->  Seq Scan on location  (cost=0.00..85530.92 rows=2157892 width=8) (actual time=0.017..307.736 rows=2156994 loops=1)
         ->  Hash  (cost=60256.07..60256.07 rows=2157285 width=8) (actual time=834.680..834.680 rows=2156994 loops=1)
               Buckets: 524288  Batches: 8  Memory Usage: 14628kB
               ->  Nested Loop  (cost=0.14..60256.07 rows=2157285 width=8) (actual time=0.043..483.771 rows=2156994 loops=1)
                     ->  Index Only Scan using thing_pkey on thing  (cost=0.14..8.16 rows=1 width=8) (actual time=0.018..0.020 rows=1 loops=1)
                           Index Cond: (id = 1)
                           Heap Fetches: 1
                     ->  Seq Scan on thing_to_location  (cost=0.00..38675.06 rows=2157285 width=16) (actual time=0.021..250.078 rows=2156994 loops=1)
                           Filter: (thing_id = 1)
 Planning time: 0.757 ms
 Execution time: 3155.212 ms
(14 rows)

[bertt]

yes I see, the second query is much faster. Changing the query's needs to be done in the query builder (https://github.com/gost/server/blob/master/database/postgis/querybuilder.go), which can be a challenge regarding all functional requirements (from OGC test suite) and performance requirements for other queries.

[Alystrasz]

Another interesting optimisation example is requesting locations count from a thing that does not exist:

Requesting an existing thing

Gost request

SELECT COUNT(DISTINCT A_location.location_id) 
FROM (SELECT location.id AS location_id, location.name AS location_name,      
             location.description AS location_description, 
             location.encodingtype AS location_encodingtype, 
             location.geojson::text AS location_geojson 
      FROM v1.location  
      WHERE (SELECT thing.id AS thing_id 
             FROM v1.thing INNER JOIN v1.thing_to_location 
                         ON thing.id = thing_to_location.thing_id 
                         AND location.id = thing_to_location.location_id   
             WHERE thing.id = 1) 
      IS NOT NULL 
      ORDER BY location_id DESC) 
AS A_location;

QUERY PLAN                                                                              
---------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=20512896.13..20512896.14 rows=1 width=8) (actual time=7023.280..7023.281 rows=1 loops=1)
   ->  Index Only Scan Backward using location_pkey on location  (cost=0.43..20486071.24 rows=2145991 width=1076) (actual time=0.127..6325.654 rows=2156994 loops=1)
         Filter: ((SubPlan 1) IS NOT NULL)
         Heap Fetches: 0
         SubPlan 1
           ->  Nested Loop  (cost=0.43..9.47 rows=1 width=8) (actual time=0.002..0.002 rows=1 loops=2156994)
                 ->  Seq Scan on thing  (cost=0.00..1.01 rows=1 width=8) (actual time=0.000..0.000 rows=1 loops=2156994)
                       Filter: (id = 1)
                 ->  Index Scan using fki_location_1 on thing_to_location  (cost=0.43..8.45 rows=1 width=8) (actual time=0.001..0.001 rows=1 loops=2156994)
                       Index Cond: (location.id = location_id)
                       Filter: (thing_id = 1)
 Planning time: 0.462 ms
 Execution time: 7023.394 ms
(13 rows)

Optimised request

SELECT COUNT(DISTINCT location.id) 
FROM v1.location, v1.thing_to_location
WHERE thing_to_location.thing_id = 1 
AND location.id = thing_to_location.location_id;

QUERY PLAN                                                                           
----------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=166889.46..166889.47 rows=1 width=8) (actual time=1847.720..1847.720 rows=1 loops=1)
   ->  Merge Join  (cost=3.54..161496.97 rows=2156994 width=8) (actual time=0.068..1363.777 rows=2156994 loops=1)
         Merge Cond: (location.id = thing_to_location.location_id)
         ->  Index Only Scan using location_pkey on location  (cost=0.43..56020.06 rows=2156775 width=8) (actual time=0.043..203.233 rows=2156994 loops=1)
               Heap Fetches: 0
         ->  Index Scan using fki_location_1 on thing_to_location  (cost=0.43..73127.84 rows=2156994 width=8) (actual time=0.020..629.880 rows=2156994 loops=1)
               Filter: (thing_id = 1)
 Planning time: 0.570 ms
 Execution time: 1847.789 ms
(9 rows)

Requesting a non-existing thing

Gost request

SELECT COUNT(DISTINCT A_location.location_id) 
FROM (SELECT location.id AS location_id, location.name AS location_name, 
             location.description AS location_description, 
             location.encodingtype AS location_encodingtype, 
             location.geojson::text AS location_geojson 
      FROM v1.location  
      WHERE (SELECT thing.id AS thing_id 
             FROM v1.thing INNER JOIN v1.thing_to_location 
                         ON thing.id = thing_to_location.thing_id 
                         AND location.id = thing_to_location.location_id               
             WHERE thing.id = 4)
      IS NOT NULL 
      ORDER BY location_id DESC)
AS A_location;

QUERY PLAN                                                                            
------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=11885796.13..11885796.14 rows=1 width=8) (actual time=2349.109..2349.109 rows=1 loops=1)
   ->  Index Only Scan Backward using location_pkey on location  (cost=0.43..11858971.24 rows=2145991 width=1076) (actual time=2349.097..2349.097 rows=0 loops=1)
         Filter: ((SubPlan 1) IS NOT NULL)
         Rows Removed by Filter: 2156994
         Heap Fetches: 0
         SubPlan 1
           ->  Nested Loop  (cost=0.43..5.47 rows=1 width=8) (actual time=0.000..0.000 rows=0 loops=2156994)
                 ->  Seq Scan on thing  (cost=0.00..1.01 rows=1 width=8) (actual time=0.000..0.000 rows=0 loops=2156994)
                       Filter: (id = 4)
                       Rows Removed by Filter: 1
                 ->  Index Scan using fki_thing_1 on thing_to_location  (cost=0.43..4.45 rows=1 width=8) (never executed)
                       Index Cond: (thing_id = 4)
                       Filter: (location.id = location_id)
 Planning time: 0.455 ms
 Execution time: 2349.190 ms
(15 rows)

Optimised request

SELECT COUNT(DISTINCT location.id) 
FROM v1.location, v1.thing_to_location
WHERE thing_to_location.thing_id = 4
AND location.id = thing_to_location.location_id;

                                                                QUERY PLAN                                                                 
-------------------------------------------------------------------------------------------------------------------------------------------
 Aggregate  (cost=8.90..8.91 rows=1 width=8) (actual time=0.030..0.031 rows=1 loops=1)
   ->  Nested Loop  (cost=0.86..8.90 rows=1 width=8) (actual time=0.017..0.017 rows=0 loops=1)
         ->  Index Scan using fki_thing_1 on thing_to_location  (cost=0.43..4.45 rows=1 width=8) (actual time=0.016..0.016 rows=0 loops=1)
               Index Cond: (thing_id = 4)
         ->  Index Only Scan using location_pkey on location  (cost=0.43..4.45 rows=1 width=8) (never executed)
               Index Cond: (id = thing_to_location.location_id)
               Heap Fetches: 0
 Planning time: 0.574 ms
 Execution time: 0.109 ms
(9 rows)

It seems that using "simpler" requests enables the database engine to find earlier there's no entities to retrieve.

[bertt]

nice work! Next step is to get these queries in the code in an optimized QueryBuilder without breaking things. However, as we are busy with other projects we can't work on this now. Let's see whats possible in between jobs.