4

I've been trying to debug a performance problem on PostgreSQL 10 on AWS Aurora.

Specifically I'm trying to understand performance problems on "cold" queries where the buffer cache does not contain cached pages.

I have a table with an index and when the planner uses the index the query is substantially slower (spending more time on IO from what I can tell). However, when I drop an index the query is faster, it uses a parallel sequential scan.

The Schema of the table:

CREATE TABLE max_test_2018_3
(
   timestamp_         timestamp,
   person_alias       varchar(128),
   visitor_id         varchar(128),
   session_id         varchar(24),
   page_title         varchar(1024),
   location_host      varchar(256),
   location_path      varchar(1024),
   location_query     varchar(1024),
   location_fragment  varchar(1024),
   referrer_host      varchar(256),
   referrer_path      varchar(1024),
   referrer_query     varchar(1024),
   referrer_fragment  varchar(1024),
   duration           integer,
   location_secure    boolean,
   referrer_secure    boolean,
   id                 uuid,
   person_id          uuid,
   custom_properties  jsonb
);

The index DDL is:

CREATE INDEX max_test_2018_3_ix   ON max_test_2018_3
  USING btree  ( location_path varchar_pattern_ops);

And the query is:

explain (analyze, buffers)
SELECT O.person_id, 1 as step1, min(timestamp_) AS timestamp_ 
FROM max_test_2018_3 O
WHERE O.location_path  like '/tax-calculator%' 
GROUP BY O.person_id

Check the following two explains - note that both explains show minimal or no buffer hits. One shows the execution with the index and the other shows execution after the index has been dropped:

No index -> https://explain.depesz.com/s/N4uo With index -> https://explain.depesz.com/s/69WS

The plan that includes the index scan takes 193 seconds vs 43 seconds for a sequential scan.

Why is step 2 in the "With-index" plan so slow? It reads in only 118372 buffers (about 118 MB of data), yet this step took 193 seconds. Why? When the buffer cache is warmed up the same with-index query takes a couple seconds. So we must concede that the IO is responsible for this extra time.

I've run this experiment several times on multiple similar datasets. Here is another example that demonstrates index scan operations that require IO and do not benefit from buffer cache.

No index -> https://explain.depesz.com/s/g6JU with Index ->https://explain.depesz.com/s/Sw6Q

Again, you can see that the index scan is unreasonably slow. The planner attempts to use the index because it believes it will speed up the query, yet such queries are consistently slower.

With regard to parameters that affecting the planner I've set the following two:

random_page_cost = 1    
seq_page_cost = 1 

The rationale being that for an SSD drive the random_page_cost does not require seeking and so can be set to the same value as seq_page_cost.

The table is vacuumed with statistics up-to date. The table max_test_2018_3 contains approximately 18 million rows and is about 9GB on disk. The above index on that table is 440 MB.

Why do the plans that use an index scan perform so poorly?

I/O Timing enabled Plans

Tweeking parallelism settings

The explains above have default parameter settings with respect to parallelism. The only two exceptions are:

max_parallel_workers = 8
max_parallel_workers_per_gather = 4

As per the suggestions, I've experimented with with the following settings:

parallel_setup_cost = 10
parallel_tuple_cost = 0.001

Defaults for these are 1000 and 0.1 respectively. These changes did not affect the plans and PostgreSQL still chose to use the index even though a parallel sequential scan is faster.

The index size is 440MB, far larger than the default min_parallel_index_scan_size of 512kB

7
  • 1
    Interesting, yes. Could you repeat the experiment with track_io_timing = on? Jul 15, 2019 at 19:09
  • Yes I will try. I've not used track_io_timing but after some brief reading I see how it can be useful so thanks for that. Do you recommend resetting the statistics before I start? Which views are you interested in? pg_statio_all_indexes? Jul 15, 2019 at 21:51
  • 1
    No, just another round of EXPLAIN (ANALYZE, BUFFERS). It should contain I/O statistics too. Jul 15, 2019 at 22:24
  • I've updated the description with explains containing IO timing. Jul 15, 2019 at 22:57
  • "The rationale being that for an SSD drive the random_page_cost does not require seeking and so can be set to the same value as seq_page_cost." Have you done low-level benchmarking to validate this? SSD might still benefit from read-ahead.
    – jjanes
    Jul 16, 2019 at 22:14

1 Answer 1

3

All your time is spent doing table I/O, which is to be expected in a test with a cold cache.

The index scan takes longer, but only because it is not parallelized. The sequential scan uses more total time, but since it is run on 5 cores in parallel, it finishes faster.

PostgreSQL v10 can perform parallel index scans, so the remaining riddle is why it doesn't. A side riddle is why the sequential scan uses so many parallel workers.

I suspect that you messed up the configuration parameters. The relevant parameters are:

  • max_parallel_workers_per_gather: limits how many workers can be used. You must have set this to 4 or more.

  • min_parallel_table_scan_size: if a table is bigger than that, a parallel worker is planned. If the table size exceeds 3n-1 times that value, n parallel workers are planned. So either your table is very big, or you reduced the parameter. Alternatively:

  • The storage parameter parallel_workers on the table overrides the calculation based on min_parallel_table_scan_size as described above, so maybe you set that.

  • Finally, min_parallel_index_scan_size governs when a parallel index scan is considered. Either the index is small, or you lowered the parameter.

I'd expect that the index scan will be faster once you set these parameters to good values.

8
  • bumping `random_page_cost' to 2 produced the following explain: explain.depesz.com/s/5Lxv You can see that the index read and creation of the bitmap is fast, the IO timing shows that the time spent is all in the Bitmap Heap Scan Jul 16, 2019 at 14:31
  • Thanks, we are getting closer. See my completely revised answer. Jul 16, 2019 at 15:17
  • @LaurenzAlbe He probably isn't getting a parallel index scan because the default setting for parallel_tuple_cost is quite high.
    – jjanes
    Jul 16, 2019 at 23:16
  • @jjames Maybe I'm missing something, but the number of tuples exchanged should be rge same with an index scan and a sequential scan. Jul 17, 2019 at 3:45
  • Updated the description with parallel settings and more tests. The weird thing is that buffer reads for index related operations are WAY slower than buffer reads for seq scans. You can see this in both the index scan plan and Bitmap Index Scan. In both cases the 72867 blocks read take 90-100 seconds. Do the math and you get a throughput of 6-7 MBps which is not even in the ballpark of SSD performance. Seq Scan operations (parallel or not) don't seem to demonstrate this performance degradation. Jul 17, 2019 at 18:02

Your Answer

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

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