Postgresql Query 10x Slower After Migration from EC2 to RDS

user_1653949 0
Viewed 329

We migrated our postgresql db from EC2 (pg 12.1 running on Docker) into RDS (pg 12.6). We then notice some queries become very slow (10x slower)

Here's one of our query

SELECT cp."FirstName" ,
       cp."LastName" ,
       cp."DealerGroupId" ,
       count(*) AS "DuplicateCount"
FROM "sc_CustomerProfiles" cp
WHERE (cp."FirstName" IS NOT NULL
       OR cp."LastName" IS NOT NULL)
  AND cp."UpdatedDate" > '2020-07-01'
  AND EXISTS
    (SELECT 1
     FROM "sc_CustomerProfiles" scp
     WHERE scp."FirstName" = cp."FirstName"
       AND cp."LastName" = scp."LastName"
       AND cp."DealerGroupId" = scp."DealerGroupId"
       AND scp."ProfileId" < 0 )
GROUP BY cp."FirstName" ,
         cp."LastName" ,
         cp."DealerGroupId"
HAVING count(*) > 1

Running EXPLAIN ANALYZE on our old DB on EC2 gives below result

Finalize GroupAggregate  (cost=818304.54..922603.67 rows=196075 width=61) (actual time=1679.259..1931.629 rows=623 loops=1)
  Group Key: cp."FirstName", cp."LastName", cp."DealerGroupId"
  Filter: (count(*) > 1)
  Rows Removed by Filter: 2257
  ->  Gather Merge  (cost=818304.54..906894.61 rows=668500 width=61) (actual time=1678.763..1934.877 rows=3290 loops=1)
        Workers Planned: 2
        Workers Launched: 2
        ->  Partial GroupAggregate  (cost=817304.52..828733.10 rows=334250 width=61) (actual time=1637.652..1886.456 rows=1097 loops=3)
              Group Key: cp."FirstName", cp."LastName", cp."DealerGroupId"
              ->  Merge Semi Join  (cost=817304.52..822048.10 rows=334250 width=53) (actual time=1637.597..1886.015 rows=1212 loops=3)
                    Merge Cond: (((cp."FirstName")::text = (scp."FirstName")::text) AND ((cp."LastName")::text = (scp."LastName")::text) AND (cp."DealerGroupId" = scp."DealerGroupId"))
                    ->  Sort  (cost=564987.54..565957.09 rows=387821 width=53) (actual time=1632.503..1841.309 rows=284808 loops=3)
                          Sort Key: cp."FirstName", cp."LastName", cp."DealerGroupId"
                          Sort Method: external merge  Disk: 18248kB
                          Worker 0:  Sort Method: external merge  Disk: 18720kB
                          Worker 1:  Sort Method: external merge  Disk: 18720kB
                          ->  Parallel Seq Scan on "sc_CustomerProfiles" cp  (cost=0.00..515729.99 rows=387821 width=53) (actual time=575.396..1171.259 rows=284808 loops=3)
                                Filter: ((("FirstName" IS NOT NULL) OR ("LastName" IS NOT NULL)) AND ("UpdatedDate" > '2020-07-01 00:00:00+07'::timestamp with time zone))
                                Rows Removed by Filter: 2613490
                    ->  Sort  (cost=252316.98..252533.20 rows=86489 width=53) (actual time=4.940..5.162 rows=2937 loops=3)
                          Sort Key: scp."FirstName", scp."LastName", scp."DealerGroupId"
                          Sort Method: quicksort  Memory: 440kB
                          Worker 0:  Sort Method: quicksort  Memory: 440kB
                          Worker 1:  Sort Method: quicksort  Memory: 440kB
                          ->  Index Scan using "sc_CustomerProfiles_ProfileId" on "sc_CustomerProfiles" scp  (cost=0.43..242267.28 rows=86489 width=53) (actual time=0.018..1.700 rows=3055 loops=3)
                                Index Cond: ("ProfileId" < 0)
Planning Time: 1.337 ms
JIT:
  Functions: 79
  Options: Inlining true, Optimization true, Expressions true, Deforming true
  Timing: Generation 16.630 ms, Inlining 216.395 ms, Optimization 990.256 ms, Emission 518.330 ms, Total 1741.611 ms
Execution Time: 1992.259 ms

While running on our new DB on RDS give this result

Finalize GroupAggregate  (cost=744995.34..848665.34 rows=195480 width=61) (actual time=144257.571..194501.899 rows=621 loops=1)
  Group Key: cp."FirstName", cp."LastName", cp."DealerGroupId"
  Filter: (count(*) > 1)
  Rows Removed by Filter: 2261
  ->  Gather Merge  (cost=744995.34..833031.15 rows=664296 width=61) (actual time=144214.280..194498.590 rows=3190 loops=1)
        Workers Planned: 2
        Workers Launched: 2
        ->  Partial GroupAggregate  (cost=743995.31..755354.88 rows=332148 width=61) (actual time=139429.298..187940.480 rows=1063 loops=3)
              Group Key: cp."FirstName", cp."LastName", cp."DealerGroupId"
              ->  Merge Semi Join  (cost=743995.31..748711.92 rows=332148 width=53) (actual time=139405.473..187938.320 rows=1212 loops=3)
                    Merge Cond: (((cp."FirstName")::text = (scp."FirstName")::text) AND ((cp."LastName")::text = (scp."LastName")::text) AND (cp."DealerGroupId" = scp."DealerGroupId"))
                    ->  Sort  (cost=493373.41..494335.55 rows=384857 width=53) (actual time=138424.282..182706.702 rows=285254 loops=3)
                          Sort Key: cp."FirstName", cp."LastName", cp."DealerGroupId"
                          Sort Method: external merge  Disk: 19464kB
                          Worker 0:  Sort Method: external merge  Disk: 17672kB
                          Worker 1:  Sort Method: external merge  Disk: 18616kB
                          ->  Parallel Seq Scan on "sc_CustomerProfiles" cp  (cost=0.00..444513.80 rows=384857 width=53) (actual time=0.048..1509.801 rows=285255 loops=3)
                                Filter: ((("FirstName" IS NOT NULL) OR ("LastName" IS NOT NULL)) AND ("UpdatedDate" > '2020-07-01 00:00:00+07'::timestamp with time zone))
                                Rows Removed by Filter: 2613405
                    ->  Sort  (cost=250621.90..250838.81 rows=86762 width=53) (actual time=977.557..978.400 rows=2940 loops=3)
                          Sort Key: scp."FirstName", scp."LastName", scp."DealerGroupId"
                          Sort Method: quicksort  Memory: 441kB
                          Worker 0:  Sort Method: quicksort  Memory: 441kB
                          Worker 1:  Sort Method: quicksort  Memory: 441kB
                          ->  Index Scan using "sc_CustomerProfiles_ProfileId" on "sc_CustomerProfiles" scp  (cost=0.43..240537.35 rows=86762 width=53) (actual time=0.079..3.373 rows=3057 loops=3)
                                Index Cond: ("ProfileId" < 0)
Planning Time: 31.569 ms
Execution Time: 194505.100 ms

I notice that the 'scan' parts have a similar duration but the 'sort' parts are far apart. The instance specs are not same but I don't see high CPU or memory utilization. What could the root cause of this or how should I investigate this issue?

Solution

Turn out the root cause is the bug only for the Thai language in glibc collation function (https://sourceware.org/bugzilla/show_bug.cgi?id=18441). The reason this was working on EC2 is that we were using a postgres alpine docker image which uses musl instead of glibc.

Since we do not actually need to order columns in Thai, changing the LC_COLLATE to 'C' does solve the problem. Note that if we need to, we could also use ICU collation instead.

amazon-rds amazon-web-services postgresql sql
2 Answers

The difference is probably the I/O speed when writing and reading temporary files that are required to sort the 300000 rows.

To be certain, change the parameter track_io_timing to on and use EXPLAIN (ANALYZE, BUFFERS). That will show you the I/O times as well.

To avoid temporary files, you can increase work_mem (try 100MB or thereabouts), that should improve performance considerably.

This index could also be beneficial:

CREATE INDEX ON "sc_CustomerProfiles" ("UpdatedDate")
   WHERE "FirstName" IS NOT NULL OR "LastName" IS NOT NULL;

(If "FirstName" and "LastName" are usually not NULL, you can omit the WHERE clause.)

user_64643080

Turn out the root cause is the bug only for the Thai language in glibc collation function (https://sourceware.org/bugzilla/show_bug.cgi?id=18441). The reason this was working on EC2 is that we were using a postgres alpine docker image which uses musl instead of glibc.

Since we do not actually need to order columns in Thai, changing the LC_COLLATE to 'C' does solve the problem. Note that if we need to, we could also use ICU collation instead.

user_16539490
Related