1

Issue

I have a database with multiple big tables, each have over 0.5billion records, each record is very simple with just 5 text/float fields. I partitioned the table, and prepared a function to query the tables. But always the first time query is 10x slower than the latter queries. it happens to ALL the tables.

details

following the many posts here, I have tried below:

An analyze of the query process is below, after psql connection, I do a first query, then immediately a second query with different arguments:

postgres=> EXPLAIN (ANALYZE, BUFFERS) select * from myschema.myfunc(tableID,arg1, arg2) limit 1;
                                                             QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.25..0.26 rows=1 width=20) (actual time=4860.718..4860.718 rows=1 loops=1)
   Buffers: shared hit=4479 read=21
   I/O Timings: read=209.969
   ->  Function Scan on get_specific_point_data  (cost=0.25..0.35 rows=10 width=20) (actual time=4860.717..4860.717 rows=1 loops=1)
         Buffers: shared hit=4479 read=21
         I/O Timings: read=209.969
 Planning Time: 0.049 ms
 Execution Time: 4860.824 ms
(8 rows)

postgres=> EXPLAIN (ANALYZE, BUFFERS) select * from myschema.myfunc(tableID,arg3, arg4) limit 1;
                                                            QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------
 Limit  (cost=0.25..0.26 rows=1 width=20) (actual time=448.253..448.254 rows=1 loops=1)
   Buffers: shared hit=89 read=19
   I/O Timings: read=436.326
   ->  Function Scan on get_specific_point_data  (cost=0.25..0.35 rows=10 width=20) (actual time=448.252..448.252 rows=1 loops=1)
         Buffers: shared hit=89 read=19
         I/O Timings: read=436.326
 Planning Time: 0.051 ms
 Execution Time: 448.292 ms

configuration

the postgresql server is deployed on azure with 2 vCores CPU, ~600Gb storage. assuming it has 4Gb RAM. here are some configuration:

            name            | setting
----------------------------+---------
 autovacuum_work_mem        | -1
 dynamic_shared_memory_type | windows
 maintenance_work_mem       | 65536
 work_mem                   | 4096
 block_size                   | 8192
 effective_cache_size         | 393216  (?? units are not Kb? Azure portal say: "unit is 8kb"?
 log_rotation_size            | 102400
 max_wal_size                 | 1024
 min_parallel_index_scan_size | 64
 min_parallel_table_scan_size | 1024
 min_wal_size                 | 256
 segment_size                 | 131072
 track_activity_query_size    | 1024
 wal_block_size               | 8192
 wal_segment_size             | 16777216

I also turned on pg_prewarm addon in the Azure shared library, but not sure whether any further steps/settings needed to activate it.

any suggestion is appreciated!

update

some extra details according to comments from @jjanes and @Zegarek regarding the function that hides planning info. try prepare instead here. again I rerun the query from a new connection, 1st query slow, 2nd is 10x faster.

PREPARE                                                                              QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=452763.67..467166.58 rows=200 width=20) (actual time=1.977..2.196 rows=1604 loops=1)
Buffers: shared hit=114
   ->  Sort  (cost=452763.67..459965.12 rows=2880582 width=20) (actual time=1.976..2.031 rows=1604 loops=1)
         Sort Key: values_table_r1_h0.date
         Sort Method: quicksort  Memory: 126kB
         Buffers: shared hit=114
         ->  Nested Loop  (cost=273.05..25554.05 rows=2880582 width=20) (actual time=1.000..1.656 rows=1604 loops=1)
               Buffers: shared hit=111
               ->  Limit  (cost=272.62..272.62 rows=1 width=12) (actual time=0.955..0.956 rows=1 loops=1)
                     Buffers: shared hit=91
                     ->  Sort  (cost=272.62..272.64 rows=9 width=12) (actual time=0.952..0.953 rows=1 loops=1)
                           Sort Key: ((abs((id_table.field1 - '96.7'::double precision)) + abs((id_table.field2 - '50.7'::double precision))))
                           Sort Method: quicksort  Memory: 25kB
                           Buffers: shared hit=91
                           ->  Index Scan using id_table_id2_lat_idx on id_table   (cost=0.43..272.57 rows=9 width=12) (actual time=0.139..0.937 rows=9 loops=1)
                                 Buffers: shared hit=88
                                 Index Cond: ((field1 < '96.7'::double precision) AND (field1 > '96.7'::double precision))
                                 Filter: ((field2 < '50.7'::double precision) AND (field2 > '50.7'::double precision))
               ->  Append  (cost=0.43..9215.18 rows=166333 width=16) (actual time=0.020..0.514 rows=1604 loops=1)
                     Buffers: shared hit=20
                     ->  Bitmap Heap Scan on values_table_r1_h0  (cost=4.22..14.82 rows=1 width=16) (never executed)
                           Recheck Cond: (id = id_table.id)
                           Filter: (field3 = ANY  ('{6,7,8,9,10}'::integer[]))
                           ->  Bitmap Index Scan on values_table_r1_h0_pt_id_idx  (cost=0.00..4.22 rows=9 width=0) (never executed)
                                 Index Cond: (id = id_table.id)
                ...              
                    ->  Index Scan using values_table_r9_h8_pt_id_idx on values_table_r9_h8  (cost=0.43..77.42 rows=1522 width=16) (actual time=0.015..0.435 rows=1604 loops=1)
                           Index Cond: (pt_id = id_table.pt_id)
                           Filter: (field3 = ANY ('{6,7,8,9,10}'::integer[]))
                           Rows Removed by Filter: 280
...
                     ->  Bitmap Heap Scan on values_table_r10_h9  (cost=4.22..14.82 rows=1 width=16) (never executed)
                           Recheck Cond: (id = id_table.id)
                           Filter: (field3 = ANY  ('{6,7,8,9,10}'::integer[]))
                           ->  Bitmap Index Scan on values_table_r10_h9_pt_id_idx  (cost=0.00..4.22 rows=9 width=0) (never executed)
                                 Index Cond: (id = id_table.id)
 Planning Time: 4199.297 ms
 Execution Time: 4.114 ms
(317 rows)

                                                                                       QUERY PLAN                                                                                       
---------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
 Unique  (cost=452745.97..467148.88 rows=200 width=20) (actual time=1.719..2.033 rows=1715 loops=1)
   ->  Sort  (cost=452745.97..459947.42 rows=2880582 width=20) (actual time=1.718..1.772 rows=1715 loops=1)
         Sort Key: values_table_r1_h0.date
         Sort Method: quicksort  Memory: 25kB
         ->  Nested Loop  (cost=255.34..25536.35 rows=2880582 width=20) (actual time=0.728..1.416 rows=1715 loops=1)
               ->  Limit  (cost=254.92..254.92 rows=1 width=12) (actual time=0.693..0.694 rows=1 loops=1)
                     ->  Sort  (cost=254.92..254.94 rows=9 width=12) (actual time=0.692..0.693 rows=1 loops=1)
                           Sort Key: ((abs((id_table.field1 - '97.4'::double precision)) + abs((id_table.field2 - '52.26'::double precision))))
                           Sort Method: quicksort  Memory: 25kB
                           ->  Index Scan using id_table_id2_lat_idx on id_table   (cost=0.43..254.87 rows=9 width=12) (actual time=0.184..0.688 rows=9 loops=1)
                                 Index Cond: ((field1 < '97.6'::double precision) AND (field1 > '97.4'::double precision))
                                 Filter: ((field2 < '52.3'::double precision) AND (field2 > '52.32'::double precision))
              ->  Append  (cost=0.43..9215.18 rows=166333 width=16) (actual time=0.019..0.532 rows=1715 loops=1)
                     ->  Bitmap Heap Scan on values_table_r1_h0  (cost=4.22..14.82 rows=1 width=16) (never executed)
                           Recheck Cond: (id = id_table.id)
                           Filter: (field3 = ANY  ('{6,7,8,9,10}'::integer[]))
                           ->  Bitmap Index Scan on values_table_r1_h0_pt_id_idx  (cost=0.00..4.22 rows=9 width=0) (never executed)
                                 Index Cond: (id = id_table.id)
...
                     ->  Index Scan using values_table_r5_h3_pt_id_idx on values_table_r5_h3  (cost=0.44..87.53 rows=1758 width=16) (actual time=0.016..0.470 rows=1715 loops=1)
                           Index Cond: (pt_id = pts_lake_id3.pt_id)
                           Filter: (month = ANY ('{6,7,8,9,10}'::integer[]))
                           Rows Removed by Filter: 281
...
                     ->  Bitmap Heap Scan on values_table_r10_h9  (cost=4.22..14.82 rows=1 width=16) (never executed)
                           Recheck Cond: (id = id_table.id)
                           Filter: (field3 = ANY  ('{6,7,8,9,10}'::integer[]))
                           ->  Bitmap Index Scan on values_table_r10_h9_pt_id_idx  (cost=0.00..4.22 rows=9 width=0) (never executed)
                                 Index Cond: (id = id_table.id)
 Planning Time: 5.590 ms
 Execution Time: 3.362 ms
(317 rows)

seems the extra time for the 1st query is that Planning Time: 4348.720 ms. one connection with multiple query show time sequence as:

 Planning Time: 4455.529 ms
 Execution Time: 267.157 ms
 Planning Time: 6.161 ms
 Execution Time: 177.163 ms
 Planning Time: 5.950 ms
 Execution Time: 279.961 ms
 Planning Time: 5.447 ms
 Execution Time: 180.953 ms
 Planning Time: 7.334 ms
 Execution Time: 571.524 ms
 Planning Time: 10.463 ms
 Execution Time: 1108.749 ms

so I just need to try to reduce this planning time at the 1st query?

  • would add more resource (CPU,RAM) to the server help to reduce the 1st loading time?
  • would pg_prewarm helpful in such case?
  • if none of them works, could I query each table in the background when a user connects to the database from GUI, to invisible execute the 1st slow query, without affecting GUI response time?
Happy Life
  • 11
  • 3
  • 1
    Can you share the function definition? Have you considered rewriting it as a [`prepared statement`](https://www.postgresql.org/docs/current/sql-prepare.html)? Also, [this](https://stackoverflow.com/q/44808994/5298879) seems related. – Zegarek Mar 10 '23 at 20:22
  • 1
    The use of the function is obscuring whatever the problem may be. Unwrap the function and run the query directly to get usable plan info. – jjanes Mar 10 '23 at 20:33
  • Have you tried to run `select pg_prewarm('you_schemaname.your_tablename'); select autoprewarm_start_worker();`? Does the same query+params end up taking the same amount of time if you immediately repeat it, or if in a new session, you run these two in the opposite order? – Zegarek Mar 10 '23 at 20:45
  • @Zegarek, thank you for the answer. I tried connect postgres from an azure vm, and run the command you mentioned, received an error, seems `pg_prewarm` is not setup correctly. I only add the `pg_prewarm` in the Azure configuration page under `shared_library`. `select pg_prewarm('you_schemaname.your_tablename'); ERROR: function pg_prewarm(unknown) does not exist LINE 1: select pg_prewarm(...); ^ HINT: No function matches the given name and argument types. . ` every new session,1st query slow; same session: 1st query slow, fast.. query other table, back still fast – Happy Life Mar 10 '23 at 21:28
  • @Zegarek follow your suggestion to replace the function with a prepare statement, I updated the time breakdown updated in the question above. yes, the original question's content is basically followed [this](https://stackoverflow.com/q/44808994/5298879) post's comments – Happy Life Mar 11 '23 at 01:50
  • @jjanes , yes, updated with a `prepare statment` and result updated in the question. thx. – Happy Life Mar 11 '23 at 01:51

1 Answers1

0

It looks like the problem is with the time it takes to load the metadata about the objects (mostly partitions and partition indexes, I would guess) so it can do the planning. I don't think there is any solution to this, just work-arounds. Once you have a connection, hold on to it so the metadata loading doesn't need to be repeated next time. If that is not convenient, you could use an external connection pooler like pgbouncer to hold on to the connections for you.

jjanes
  • 37,812
  • 5
  • 27
  • 34
  • thank you! we further setup `node.js` API connection to the database, and can keep the connection after user open a webpage. but it is possible to "warmup" each table at the connection at the backend without affecting GUI response time? would add more resource (CPU,RAM) to the server help to reduce the 1st loading time? would [pg_prewarm](https://www.postgresql.org/docs/current/pgprewarm.html) helps? – Happy Life Mar 11 '23 at 13:23
  • @HappyLife If you use a new enough version and set track_io_timing to on, then the plans will show you how much of the planning time is spent reading buffers. The rest is presumably spent on parsing that data and stuff, which is where I assume most of the time is going. If this is happening very frequently, then I assume the data you need is already cached, while the CPU work does need to be repeated on every back-end. – jjanes Mar 12 '23 at 17:43
  • @HappyLife I don't think warming up each table in each connection ahead of time makes much sense in general. If the connections are created at-need, they can't do anything ahead of time because they don't exist ahead of time, while if they are kept in a pooler than the problem would (should) already be solved, except maybe right after the pooler is rebooted. – jjanes Mar 12 '23 at 17:45
  • thank you for the detailed reply! I tried the buffer analysis, and update the `buffering` output in the main question. my postgres is version `11` and `set track_io_timing ` is `on`. when run query with `EXPLAIN (ANALYZE, BUFFERS)`, interesting I only see: `Buffers: shared hit=xxx`, not include `... read=xxx`? Will add cpu/memory in such case will be helpful? – Happy Life Mar 13 '23 at 14:04
  • I am not very familiar with database techniques, so my though of "warmup" maybe naive. at initialization, our website that calls the database will maintain the db connection for 10mins if inactive as we set. so after initial connection, what about deliberately send a random query to each table in the background to finish the 1st slow query; then when users actually call the database from GUI, it will be fast? it would be an issue if we later need to expand the #of tables, as those 1st query will consume cpu and slow performance at webpage GUI loading? – Happy Life Mar 13 '23 at 14:11
  • It was not until v13 where buffer usage was reported for the planning stage. Before that they were only reported for the execution stage. – jjanes Mar 14 '23 at 18:15