0

I'm running a select statement on a postgresql table (on an RDS instance) in order to sum up values across 2 mil rows. The select statement has about 100 parameters (mostly different countries we want to sum across).

When I run this query once from my application it'll execute in roughly 500ms. However when I execute it several times in a row, the query latency will suddenly increase by 10-20 times to roughly 5 to 10 seconds after 8 or 9 runs. (These measurements are server side from the RDS logs where I've enabled log_min_duration_statement).

What could possibly cause this jump in execution time? -- I'd expect the query to be slower on the initial run, but I'm surprised to see it increase in latency after several consequtive runs.

A few key observations:

  • Connection Pool: The exact connection pool doesn't seem to matter. The problem persists whether I use HikariCP or C3P0
  • Single Connection: This issue doesn't happen if I configure my connection pool to have only a single connection (so the application logic is not at fault)
  • PSQL: This issue also doesn't happen if I benchmark the query consequetively using psql to execute it.
  • Query Parameters: When I reduce the amount of query parameters to ~60 I don't see any issues. It's only when I query for 90+ territories that I run in to this behaviour.
  • Pool Reset: When I restart my application (and hence reset the connection pool), the queries go back to being fast (0.5s) for another 8-9 queries before being slow again (5s).

I've tried to look out for the usual suspects like RDS IOPS Burst throttling, database load, and memory consumption, available connections, but nothing looks suspicious on this front.

I've also made sure that the index the query is using and the rows returned from the table are cached.

The query I'm running has the following shape. I've truncated some of the 90 country IDs:

SELECT d.primary_title_no,
       SUM(d.cume) AS lifetime
  FROM schema.my_data AS d 
 WHERE d.currency = 'USD'
   AND d.date >= '2020-01-01'::date + (7 * (d.week - 1))
   AND d.date < '2021-01-01'::date + (7 * (d.week - 1))
   AND d.is_lifetime = TRUE
   AND d.ter_id IN ('AE','AM', ... (100 odd values) ...,'WA','ZA')
 GROUP BY d.primary_title_no 
 ORDER BY lifetime DESC
 LIMIT 250;

Importantly this problem only happens when the query has 90+ country IDs. I can run it for 50 countries without issue.

For reference here's the output from explain analyze on a query with a fast execution time:

+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| QUERY PLAN                                                                                                                                                                                                                                                                                                                                                                             |
|----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------|
| Limit  (cost=1218692.98..1218693.23 rows=100 width=12) (actual time=369.146..369.167 rows=100 loops=1)                                                                                                                                                                                                                                                                                 |
|   ->  Sort  (cost=1218692.98..1218697.34 rows=1742 width=12) (actual time=369.145..369.154 rows=100 loops=1)                                                                                                                                                                                                                                                                           |
|         Sort Key: (sum(cume)) DESC                                                                                                                                                                                                                                                                                                                                                     |
|         Sort Method: top-N heapsort  Memory: 33kB                                                                                                                                                                                                                                                                                                                                      |
|         ->  GroupAggregate  (cost=1218595.34..1218626.41 rows=1742 width=12) (actual time=366.250..368.653 rows=1959 loops=1)                                                                                                                                                                                                                                                          |
|               Group Key: primary_title_no                                                                                                                                                                                                                                                                                                                                              |
|               ->  Sort  (cost=1218595.34..1218599.89 rows=1820 width=12) (actual time=366.240..366.844 rows=5739 loops=1)                                                                                                                                                                                                                                                              |
|                     Sort Key: primary_title_no                                                                                                                                                                                                                                                                                                                                         |
|                     Sort Method: quicksort  Memory: 462kB                                                                                                                                                                                                                                                                                                                              |
|                     ->  Index Scan using idx_dailies_currency_ter_id_primary_title_no_lifetime on dailies d  (cost=0.43..1218496.79 rows=1820 width=12) (actual time=1.093..364.406 rows=5739 loops=1)                                                                                                                                                                                 |
|                           Index Cond: (((currency)::text = 'USD'::text) AND ((ter_id)::text = ANY ('{AE,AM,AR,AT,AU,AZ,BA,BE,BG,BH,BO,BR,BY,CH,CL,CN,CO,CR,CU,CZ,DE,DK,DO,EC,EE,EG,ES,FI,FR,GE,GR,GT,HK,HN,HR,HU,IL,IN,IQ,IS,IT,JP,KG,KR,KW,KZ,LB,LT,LU,LV,MD,MX,MY,MZ,NI,NL,NO,NZ,OM,PA,PE,PH,PL,PT,PY,QA,RO,RS,RU,SA,SE,SG,SI,SK,SV,TH,TJ,TM,TR,TT,TW,UK,UP,UY,UZ,WA,ZA}'::text[]))) |
|                           Filter: (((date - (7 * (week - 1))) >= '2020-01-01'::date) AND ((date - (7 * (week - 1))) < '2020-06-01'::date))                                                                                                                                                                                                                                             |
|                           Rows Removed by Filter: 314494                                                                                                                                                                                                                                                                                                                               |
| Planning Time: 0.613 ms                                                                                                                                                                                                                                                                                                                                                                |
| Execution Time: 369.213 ms                                                                                                                                                                                                                                                                                                                                                             |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+

For a case where the query executes slowly the explain analyze output is the same, but 20 times the compute is spent in the innermost Index Scan step.

If anybody has any pointers to how I can troubleshoot this issue, I'd be all ears.

1 Answer 1

0

After looking in to the issue with parameters more, I found the following stackoverflow question suggesting that:

After running the query a few times, it decides that the generic plan is just as good as the custom plan, so switches to the generic plan. Apparently it is wrong about that. You can force it to use the custom plan always be setting plan_cache_mode.

In Postgresql's documentation, plan_cache_mode is documented as follows:

Prepared statements (either explicitly prepared or implicitly generated, for example by PL/pgSQL) can be executed using custom or generic plans. Custom plans are made afresh for each execution using its specific set of parameter values, while generic plans do not rely on the parameter values and can be re-used across executions. Thus, use of a generic plan saves planning time, but if the ideal plan depends strongly on the parameter values then a generic plan may be inefficient. The choice between these options is normally made automatically, but it can be overridden with plan_cache_mode. The allowed values are auto (the default), force_custom_plan and force_generic_plan. This setting is considered when a cached plan is to be executed, not when it is prepared. For more information see PREPARE.

When I executed the following statement inside a transaction with my select statement, it solved the problem:

(jdbc/with-db-transaction [connection (db/shared-db-ro)]
  (jdbc/execute! connection ["SET LOCAL plan_cache_mode = 'force_custom_plan'"])
  (execute-slow-query params {:connection connection}))))

Update: I think the issue happens in conjunction with having work_mem set to 4mb. My going hypothesis is that the generic plan takes up a bit more memory causing a bunch of swapping. Lifting this limit to 16mb also solves the issue:

(jdbc/with-db-transaction [connection (db/shared-db-ro)]
  (jdbc/execute! connection ["SET LOCAL work_mem = '16mb'"])
  (execute-slow-query params {:connection connection}))))
3
  • PostgreSQL only caches plans 1) for prepared statements or 2) for statements in PL/pgSQL code. So unless you hid that detail in your question, that cannot be the explanation. The slowdown from a bad generic plan could only be seen from the sixth execution on. My guess would have been that your hosting provider throttles your I/O after a while (you could see that with EXPLAIN (ANALYZE, BUFFERS) if you set track_io_timing = on). Commented Feb 16 at 6:56
  • @LaurenzAlbe I agree that the explanation is not entirely satisfying, but I have verified that fixing the plan type does solve the issue. I think the issue happens in conjunction with having work_mem set to 4mb. My going hypothesis is that the generic plan takes up a bit more memory causing a bunch of swapping. Lifting this limit to 16gb also solves the issue.
    – Arnfred
    Commented Feb 19 at 9:25
  • I meant 16mb of course
    – Arnfred
    Commented Feb 21 at 12:09

Your Answer

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

Not the answer you're looking for? Browse other questions tagged or ask your own question.