0

I updated the PostgreSQL server from version 11 to version 15 using pg_upgrade. There are several queries that have been affected after the update. Here is one of these queries, which took 15 seconds on version 11, but now takes 12 minutes on PostgreSQL 15. And here are two execution plans for comparison. What I've already done is ANALYZE all tables and rebuild all indexes. The hardware and configuration are the same. Do you have any ideas? Best regards.

Query Text:

SELECT
    r.*, count(*) OVER() total_rows
    FROM (SELECT rb.id, 
    rb.req_number, 
    rb.req_status, 
    rb.id_own_customer, 
    rb.id_user_create, 
    rb.date_create, 
    rb.contact_person, 
    rb.phone_number, 
    rb.id_org_user_create, 
    rb.responsible, 
    rb.plan_weight, 
    rb.fact_weight, 
    (SELECT descr_org FROM customer_organizations 
    WHERE rb.id_out_customer = id) descr_out_customer, 
    (SELECT name FROM organizations
    WHERE rb.id_own_customer = id_org) descr_own_customer, 
    qaverage.route_distance, qaverage.mileage, 
    qaverage.mileage_in_route, 
    qaverage.cnt_trip, qaverage.progress, 
    p.reg_numbers, rc.max_plan_date_start, rc.max_plan_date_finish, 
    rc.min_plan_date_start, rc.min_plan_date_finish, rc.contractors 
    FROM request_ts_base rb
    LEFT JOIN LATERAL(SELECT re.id_request, 
    string_agg(corg.descr_org, ' ') FILTER(WHERE re.contractor IS NOT NULL) contractors, 
    max(re.date_start) max_plan_date_start, 
    max(re.date_finish) max_plan_date_finish, 
    min(re.date_start) min_plan_date_start, 
    min(re.date_finish) min_plan_date_finish 
    FROM request_ts_extension re LEFT JOIN
    customer_organizations corg ON corg.id = re.contractor 
    WHERE re.id_request = rb.id GROUP BY re.id_request) rc 
    ON TRUE LEFT JOIN LATERAL(SELECT avg(route_distance) route_distance, 
    avg(mileage) mileage, avg(mileage_in_route) mileage_in_route, 
    avg(cnt_trip) cnt_trip, avg(progress) progress FROM request_ts_transport 
    WHERE request_ts_transport.id_request = rb.id) 
    qaverage ON TRUE LEFT JOIN(SELECT string_agg(p1.reg_number, '<AE>') reg_numbers, p1.id_request 
    FROM(SELECT p0.reg_number, rt0.id_request FROM passport p0 JOIN
    request_ts_transport rt0 ON rt0.id_ts = p0.id_mo UNION ALL SELECT tc1.reg_number, tc1.id_request 
    FROM request_transport_cont tc1 LEFT JOIN request_ts_base rtb ON rtb.id = tc1.id_request) p1
    GROUP BY p1.id_request) p ON p.id_request = rb.id) r
    WHERE
      r.date_create >= '2024-08-16 17:00:00' AND
      r.date_create < '2024-08-22 17:00:00' AND
      r.responsible = 100641 AND
      r.id_org_user_create IN (
    SELECT
          child_org_id
        FROM
          org_access
        WHERE
          org_access.parent_org_id = 1657375583)
          ORDER BY
    r.date_create DESC, r.req_number DESC, r.id DESC;

Slow execution plan on PostgreSQL 15:

Sort  (cost=1710828.22..1710828.22 rows=2 width=992) (actual time=1022777.015..1022777.059 rows=59 loops=1)
          Sort Key: rb.date_create DESC, rb.req_number DESC, rb.id DESC
          Sort Method: quicksort  Memory: 40kB
          Buffers: shared hit=78502606, temp read=1973575 written=4431431
          ->  WindowAgg  (cost=1710222.66..1710828.12 rows=2 width=992) (actual time=1022776.649..1022776.933 rows=59 loops=1)
                Buffers: shared hit=78502606, temp read=1973575 written=4431431
                ->  Nested Loop Left Join  (cost=1710222.66..1710818.10 rows=2 width=379) (actual time=15314.202..1022775.813 rows=59 loops=1)
                      Buffers: shared hit=78502429, temp read=1973575 written=4431431
                      ->  Nested Loop Left Join  (cost=1710219.25..1710811.21 rows=2 width=219) (actual time=15314.161..1022772.853 rows=59 loops=1)
                            Buffers: shared hit=78502252, temp read=1973575 written=4431431
                            ->  Nested Loop Left Join  (cost=1710218.52..1710730.01 rows=1 width=155) (actual time=15314.035..1022765.772 rows=59 loops=1)
                                  Join Filter: (rt0.id_request = rb.id)
                                  Rows Removed by Join Filter: 93259443
                                  Buffers: shared hit=78501994, temp read=1973575 written=4431431
                                  ->  Nested Loop Semi Join  (cost=0.72..505.20 rows=1 width=123) (actual time=0.076..2.931 rows=59 loops=1)
                                        Buffers: shared hit=241
                                        ->  Index Scan Backward using test1_idx_idu_dc on request_ts_base rb  (cost=0.43..151.34 rows=142 width=123) (actual time=0.060..1.065 rows=59 loops=1)
                                              Index Cond: ((id_user_create = 450) AND (date_create >= '2024-08-22 19:00:00'::timestamp without time zone) AND (date_create < '2024-08-24 19:00:00'::timestamp without time zone))
                                              Buffers: shared hit=64
                    ->  Index Scan using child_org_id_idx on org_access  (cost=0.29..2.48 rows=1 width=4) (actual time=0.018..0.018 rows=1 loops=59)
                                              Index Cond: (child_org_id = rb.id_org_user_create)
                                              Filter: (parent_org_id = '-1715906210'::integer)
                                              Rows Removed by Filter: 1
                                              Buffers: shared hit=177
                                  ->  HashAggregate  (cost=1710217.80..1710220.30 rows=200 width=36) (actual time=12708.608..17085.665 rows=1580669 loops=59)
                                        Group Key: rt0.id_request
                                        Batches: 1405  Memory Usage: 267505kB  Disk Usage: 308560kB
                                        Buffers: shared hit=78501753, temp read=1973575 written=4431418
                                        ->  Append  (cost=6620.38..1663672.09 rows=9309143 width=13) (actual time=0.539..8719.336 rows=8814315 loops=59)
                                              Buffers: shared hit=78501753
                                              ->  Hash Join  (cost=6620.38..50290.01 rows=297593 width=13) (actual time=0.538..269.004 rows=222192 loops=59)
                                                    Hash Cond: (rt0.id_ts = p0.id_mo)
                                                    Buffers: shared hit=2360011
                                                    ->  Seq Scan on request_ts_transport rt0  (cost=0.00..42885.98 rows=298498 width=8) (actual time=0.014..126.001 rows=222942 loops=59)
                                                          Buffers: shared hit=2354159
                                                    ->  Hash  (cost=6193.50..6193.50 rows=34150 width=13) (actual time=29.997..30.013 rows=34150 loops=1)
                                                          Buckets: 65536  Batches: 1  Memory Usage: 2111kB
                                                          Buffers: shared hit=5852
                                                          ->  Seq Scan on passport p0  (cost=0.00..6193.50 rows=34150 width=13) (actual time=0.011..22.974 rows=34150 loops=1)
                                                                Buffers: shared hit=5852
                                              ->  Seq Scan on request_transport_cont tc1  (cost=0.00..1380653.50 rows=9011550 width=13) (actual time=0.011..7658.655 rows=8592123 loops=59)
                                                    Buffers: shared hit=76141742
                            ->  GroupAggregate  (cost=0.73..80.59 rows=31 width=68) (actual time=0.098..0.098 rows=1 loops=59)
                                  Group Key: re.id_request
                                  Buffers: shared hit=258
                                  ->  Nested Loop Left Join  (cost=0.73..79.73 rows=31 width=46) (actual time=0.082..0.086 rows=1 loops=59)
                                        Buffers: shared hit=258
                                        ->  Index Scan using request_ts_extension_d_rqst on request_ts_extension re  (cost=0.43..11.34 rows=31 width=24) (actual time=0.055..0.058 rows=1 loops=59)
                                              Index Cond: (id_request = rb.id)
                                              Buffers: shared hit=249
                                        ->  Memoize  (cost=0.29..2.26 rows=1 width=26) (actual time=0.006..0.006 rows=1 loops=72)
                                              Cache Key: re.contractor
                                              Cache Mode: logical
                                              Hits: 69  Misses: 3  Evictions: 0  Overflows: 0  Memory Usage: 1kB
                                              Buffers: shared hit=9
                                              ->  Index Scan using customer_organizations_pk on customer_organizations corg  (cost=0.28..2.25 rows=1 width=26) (actual time=0.029..0.029 rows=1 loops=3)
                                                    Index Cond: (id = re.contractor)
                                                    Buffers: shared hit=9
                                    ->  Aggregate  (cost=3.42..3.43 rows=1 width=160) (actual time=0.032..0.032 rows=1 loops=59)
                                            Buffers: shared hit=177
                        ->  Index Scan using request_ts_transport_d_rqst on request_ts_transport  (cost=0.42..3.34 rows=5 width=21) (actual time=0.020..0.020 rows=0 loops=59)
                                        Index Cond: (id_request = rb.id)
                                        Buffers: shared hit=177
                SubPlan 1
                  ->  Index Scan using customer_organizations_pk on customer_organizations  (cost=0.28..2.50 rows=1 width=22) (actual time=0.001..0.001 rows=0 loops=59)
                        Index Cond: (id = rb.id_out_customer)
                SubPlan 2
                  ->  Index Scan using organizations_pk on organizations  (cost=0.28..2.50 rows=1 width=34) (actual time=0.003..0.003 rows=1 loops=59)
                        Index Cond: (id_org = rb.id_own_customer)
                        Buffers: shared hit=177

Fast plan on PostgreSQL 11

    Sort  (cost=1714930.22..1714930.67 rows=178 width=992) (actual time=15279.127..15279.129 rows=45 loops=1)
       Sort Key: rb.date_create DESC, rb.req_number DESC, rb.id DESC
       Sort Method: quicksort  Memory: 65kB
       Buffers: shared hit=1378008, temp read=19958 written=19958
       ->  WindowAgg  (cost=1689686.72..1714914.25 rows=178 width=992) (actual time=15278.950..15279.055 rows=45 loops=1)
             Buffers: shared hit=1378008, temp read=19958 written=19958
             ->  Nested Loop Left Join  (cost=1689686.72..1714022.47 rows=178 width=379) (actual time=14875.260..15278.758 rows=45 loops=1)
                   Buffers: shared hit=1377873, temp read=19958 written=19958
                   ->  Nested Loop Left Join  (cost=1689683.32..1713411.82 rows=178 width=219) (actual time=14875.209..15278.472 rows=45 loops=1)
                         Buffers: shared hit=1377738, temp read=19958 written=19958
                         ->  Nested Loop Semi Join  (cost=1689682.60..1712963.58 rows=6 width=155) (actual time=14875.071..15276.659 rows=45 loops=1)
                               Buffers: shared hit=1376372, temp read=19958 written=19958
                               ->  Hash Left Join  (cost=1689678.10..1712907.38 rows=10 width=155) (actual time=14874.975..15275.858 rows=45 loops=1)
                                     Hash Cond: (rb.id = rt0.id_request)
                                     Buffers: shared hit=1376147, temp read=19958 written=19958
                                     ->  Index Scan using request_ts_base_datecreate_org on request_ts_base rb  (cost=0.43..23229.68 rows=10 width=123) (actual time=1.066..65.947 rows=45 loops=1)
                                           Index Cond: ((date_create >= '2024-08-16 17:00:00'::timestamp without time zone) AND (date_create < '2024-08-22 17:00:00'::timestamp without time zone))
                                           Filter: (responsible = 100641)
                                           Rows Removed by Filter: 40393
                                           Buffers: shared hit=39856
                                     ->  Hash  (cost=1689675.17..1689675.17 rows=200 width=36) (actual time=14834.259..14834.259 rows=2766656 loops=1)
                                           Buckets: 1048576 (originally 1024)  Batches: 4 (originally 1)  Memory Usage: 74056kB
                                           Buffers: shared hit=1336291, temp written=16075
                                           ->  HashAggregate  (cost=1689670.67..1689673.17 rows=200 width=36) (actual time=12228.531..14092.515 rows=2766656 loops=1)
                                                 Group Key: rt0.id_request
                                                 Buffers: shared hit=1336291
                                                 ->  Append  (cost=6620.24..1645668.18 rows=8800499 width=13) (actual time=28.843..7868.353 rows=8803484 loops=1)
                                                       Buffers: shared hit=1336291
                                                       ->  Hash Join  (cost=6620.24..49330.96 rows=221825 width=13) (actual time=28.842..262.406 rows=222128 loops=1)
                                                             Hash Cond: (rt0.id_ts = p0.id_mo)
                                                             Buffers: shared hit=45753
                                                             ->  Seq Scan on request_ts_transport rt0  (cost=0.00..42126.47 rows=222547 width=8) (actual time=0.010..77.281 rows=222877 loops=1)
                                                                   Buffers: shared hit=39901
                                                             ->  Hash  (cost=6193.44..6193.44 rows=34144 width=13) (actual time=28.669..28.669 rows=34150 loops=1)
                                                                   Buckets: 65536  Batches: 1  Memory Usage: 2111kB
                                                                   Buffers: shared hit=5852
                                                                   ->  Seq Scan on passport p0  (cost=0.00..6193.44 rows=34144 width=13) (actual time=0.009..22.607 rows=34150 loops=1)
                                                                         Buffers: shared hit=5852
                                                       ->  Seq Scan on request_transport_cont tc1  (cost=0.00..1376324.74 rows=8578674 width=13) (actual time=0.014..6597.547 rows=8581356 loops=1)
                                                             Buffers: shared hit=1290538
                               ->  Bitmap Heap Scan on org_access  (cost=4.50..5.61 rows=1 width=4) (actual time=0.013..0.013 rows=1 loops=45)
                                     Recheck Cond: ((child_org_id = rb.id_org_user_create) AND (parent_org_id = 1657375583))
                            Heap Blocks: exact=45
                                     Buffers: shared hit=225
                                     ->  BitmapAnd  (cost=4.50..4.50 rows=1 width=0) (actual time=0.011..0.011 rows=0 loops=45)
                                           Buffers: shared hit=180
                                           ->  Bitmap Index Scan on child_org_id_idx  (cost=0.00..1.32 rows=5 width=0) (actual time=0.003..0.003 rows=3 loops=45)
                                                 Index Cond: (child_org_id = rb.id_org_user_create)
                                                 Buffers: shared hit=90
                                           ->  Bitmap Index Scan on org_access_parent_org_id_idx  (cost=0.00..2.88 rows=199 width=0) (actual time=0.007..0.007 rows=199 loops=45)
                                                 Index Cond: (parent_org_id = 1657375583)
                                                 Buffers: shared hit=90
                         ->  GroupAggregate  (cost=0.72..74.15 rows=28 width=68) (actual time=0.038..0.038 rows=1 loops=45)
                               Group Key: re.id_request
                               Buffers: shared hit=1366
                               ->  Nested Loop Left Join  (cost=0.72..73.38 rows=28 width=46) (actual time=0.012..0.035 rows=7 loops=45)
                                     Buffers: shared hit=1366
                                     ->  Index Scan using request_ts_extension_d_rqst on request_ts_extension re  (cost=0.43..9.98 rows=28 width=24) (actual time=0.008..0.019 rows=7 loops=45)
                                           Index Cond: (id_request = rb.id)
                                           Buffers: shared hit=415
                                     ->  Index Scan using customer_organizations_pk on customer_organizations corg  (cost=0.28..2.26 rows=1 width=26) (actual time=0.001..0.001 rows=1 loops=317)
                                           Index Cond: (id = re.contractor)
                                           Buffers: shared hit=951
                   ->  Aggregate  (cost=3.40..3.41 rows=1 width=160) (actual time=0.005..0.005 rows=1 loops=45)
                         Buffers: shared hit=135
                         ->  Index Scan using request_ts_transport_d_rqst on request_ts_transport  (cost=0.42..3.33 rows=5 width=21) (actual time=0.004..0.004 rows=0 loops=45)
                               Index Cond: (id_request = rb.id)
                               Buffers: shared hit=135
             SubPlan 1
               ->  Index Scan using customer_organizations_pk on customer_organizations  (cost=0.28..2.50 rows=1 width=22) (actual time=0.000..0.000 rows=0 loops=45)
                     Index Cond: (rb.id_out_customer = id)
             SubPlan 2
               ->  Index Scan using organizations_pk on organizations  (cost=0.28..2.50 rows=1 width=34) (actual time=0.002..0.002 rows=1 loops=45)
                     Index Cond: (rb.id_own_cu

stomer = id_org)
                 Buffers: shared hit=135
Improve this question
6
  • Have you tried increasing work_mem, even if for this one query?
    – mustaccio
    Commented Aug 26 at 20:57
  • @mustaccio Yes, I increased the work_mem at the session level to 512MB, but it didn't help. Also work_mem at the server level is the same as on PG11.
    – Fahrenheit
    Commented Aug 26 at 23:46
  • plan for 15 seems to be malformed. Please double check. Maybe just an indenting issue.
    – jjanes
    Commented Aug 27 at 16:08
  • The plans return different numbers of rows, so clearly there has some been data divergence. This makes it hard to trace through things with confidence. Could you collect data from a system which is upgraded but otherwise undiverged?
    – jjanes
    Commented Aug 27 at 16:13
  • @jjanes no, unfortunately. The lines on the server with pg15 have already been added.
    – Fahrenheit
    Commented Aug 28 at 16:49

0

Reset to default

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.