Randomly slow queries using search.php

[stouch]

I've setup a full-planet admin styled planet (Nominatim 4.2 with docker). I've got a 32GB RAM + 2vCPU (https://pcr.cloud-mercato.com/providers/ovh/flavors/R2-30) and installed my data in an SSD external disk.

My queries through search.php are randomly slow (sometimes >5sec instead of 200ms for randomly new query terms).

I recently been waiting for 30 seconds so I repeatly tried SELECT pid, query, backend_start FROM pg_stat_activity; while it was stuck, to find some pending queries, and I found different ones, but this one for example :

EXPLAIN ANALYZE SELECT place_id, address_rank,  (  SELECT count(*) FROM (   SELECT unnest(ARRAY[4631092,3414840,669887])    INTERSECT   SELECT unnest(nameaddress_vector) ) s) as exactmatch FROM search_name WHERE name_vector @> ARRAY[669887] ORDER BY (CASE 
WHEN importance = 0 OR importance IS NULL THEN 0.75001-(search_rank::float/40) ELSE importance END) DESC, exactmatch DESC LIMIT 20;

which gave me:

                                                                                                                                        QUERY PLAN                                                                                                      
                                   
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------------------------------
 Limit  (cost=4071.50..4071.55 rows=20 width=26) (actual time=1052.214..1052.223 rows=20 loops=1)
   ->  Sort  (cost=4071.50..4073.85 rows=939 width=26) (actual time=1052.212..1052.218 rows=20 loops=1)
         Sort Key: (CASE WHEN ((search_name.importance = '0'::double precision) OR (search_name.importance IS NULL)) THEN ('0.75001'::double precision - ((search_name.search_rank)::double precision / '40'::double precision)) ELSE search_name.import
ance END) DESC, ((SubPlan 1)) DESC
         Sort Method: top-N heapsort  Memory: 27kB
         ->  Bitmap Heap Scan on search_name  (cost=31.28..4046.52 rows=939 width=26) (actual time=0.292..1052.090 rows=84 loops=1)
               Recheck Cond: (name_vector @> '{669887}'::integer[])
               Heap Blocks: exact=84
               ->  Bitmap Index Scan on idx_search_name_name_vector  (cost=0.00..31.04 rows=939 width=0) (actual time=0.101..0.102 rows=84 loops=1)
                     Index Cond: (name_vector @> '{669887}'::integer[])
               SubPlan 1
                 ->  Aggregate  (cost=0.37..0.38 rows=1 width=8) (actual time=0.141..0.141 rows=1 loops=84)
                       ->  Subquery Scan on s  (cost=0.00..0.36 rows=3 width=0) (actual time=0.140..0.140 rows=0 loops=84)
                             ->  HashSetOp Intersect  (cost=0.00..0.33 rows=3 width=8) (actual time=0.139..0.139 rows=0 loops=84)
                                   ->  Append  (cost=0.00..0.30 rows=13 width=8) (actual time=0.001..0.105 rows=226 loops=84)
                                         ->  Subquery Scan on "*SELECT* 1"  (cost=0.00..0.06 rows=3 width=8) (actual time=0.001..0.003 rows=3 loops=84)
                                               ->  ProjectSet  (cost=0.00..0.03 rows=3 width=4) (actual time=0.001..0.002 rows=3 loops=84)
                                                     ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.000..0.000 rows=1 loops=84)
                                         ->  Subquery Scan on "*SELECT* 2"  (cost=0.00..0.17 rows=10 width=8) (actual time=0.001..0.071 rows=223 loops=84)
                                               ->  ProjectSet  (cost=0.00..0.07 rows=10 width=4) (actual time=0.001..0.032 rows=223 loops=84)
                                                     ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.000..0.000 rows=1 loops=84)
 Planning Time: 0.346 ms
 Execution Time: 1052.348 ms
(22 rows)

Have you got any idea about what would be the cause of these slow queries?

Thanks

[lonvia]

It looks like Postgres is slow to retrieve the data. If you look at the actual time parts in the query, you' ll notice that almost all the time is spent here:

->  Bitmap Heap Scan on search_name  (cost=31.28..4046.52 rows=939 width=26) (actual time=0.292..1052.090 rows=84 loops=1)

This is when Postgres loads the rows from the items found matching in the index to recheck that they really match. In that case it takes almost a second to load the 84 matching rows from the disk. I suspect that your external SSD simply doesn't have the throughput required. You can offset slow disk with more RAM up to a certain point.

[stouch]

Thanks!

My external disk (ovh high speed gen2) :

472G size.
77G avail.

sudo hdparm -Tt /dev/sdb

/dev/sdb:
 Timing cached reads:   21962 MB in  1.99 seconds = 11048.73 MB/sec
 Timing buffered disk reads: 730 MB in  3.00 seconds = 243.26 MB/sec

compared to local disk:

sudo hdparm -Tt /dev/sda

/dev/sda:
 Timing cached reads:   20500 MB in  1.99 seconds = 10311.21 MB/sec
 Timing buffered disk reads: 1620 MB in  3.00 seconds = 539.74 MB/sec

Surprisingly, I did not got any slow queries anymore since few hours.

My CPU seemed to be overused when I was meeting this issue.

My docker stats gives :

NAME                  CPU %      MEM USAGE / LIMIT    MEM %    NET I/O                BLOCK I/O        
nominatim              0.02%     9.679GiB / 28.67GiB   33.76%    761MB / 8.46MB    113GB / 97.8GB

[stouch]

Just retried and I got slow queries again, this is the read disk output :

sudo hdparm -Tt /dev/sdb

/dev/sdb:
 Timing cached reads:   20640 MB in  1.99 seconds = 10382.77 MB/sec
 Timing buffered disk reads: 100 MB in  6.90 seconds =  14.50 MB/sec

[20 minutes later] : Query speed came back, and read speed of the disk too... It looks you were right. Gonna check why my disk is randomly slow. Thanks a lot.

sudo hdparm -Tt /dev/sdb

/dev/sdb:
 Timing cached reads:   19874 MB in  1.99 seconds = 9993.62 MB/sec
 Timing buffered disk reads: 742 MB in  3.00 seconds = 247.32 MB/sec

[stouch]

I try to debug and find a reason why my queries still are randmoly slow :
If I run :

nominatim=# EXPLAIN ANALYSE SELECT place_id,0::int as exactmatch FROM search_name WHERE name_vector @> ARRAY[5639492] ORDER BY (CASE WHEN importance = 0 OR importance IS NULL THEN 0.75001-(search_rank::float/40) ELSE importance END) DESC LIMIT 20;
                                                                                                      QUERY PLAN                            
                                                                           
--------------------------------------------------------------------------------------------------------------------------------------------
---------------------------------------------------------------------------
 Limit  (cost=3770.55..3770.60 rows=20 width=20) (actual time=4.281..4.299 rows=1 loops=1)
   ->  Sort  (cost=3770.55..3772.93 rows=952 width=20) (actual time=4.279..4.296 rows=1 loops=1)
         Sort Key: (CASE WHEN ((importance = '0'::double precision) OR (importance IS NULL)) THEN ('0.75001'::double precision - ((search_ra
nk)::double precision / '40'::double precision)) ELSE importance END) DESC
         Sort Method: quicksort  Memory: 25kB
         ->  Bitmap Heap Scan on search_name  (cost=31.38..3745.22 rows=952 width=20) (actual time=4.221..4.224 rows=1 loops=1)
               Recheck Cond: (name_vector @> '{5639492}'::integer[])
               Heap Blocks: exact=1
               ->  Bitmap Index Scan on idx_search_name_name_vector  (cost=0.00..31.14 rows=952 width=0) (actual time=2.181..2.181 rows=1 lo
ops=1)
                     Index Cond: (name_vector @> '{5639492}'::integer[])
 Planning Time: 0.268 ms
 Execution Time: 4.361 ms
(11 rows)

and 2 minutes later :

 Limit  (cost=3770.55..3770.60 rows=20 width=20) (actual time=0.051..0.053 rows=1 loops=1)
   ->  Sort  (cost=3770.55..3772.93 rows=952 width=20) (actual time=0.050..0.051 rows=1 loops=1)
         Sort Key: (CASE WHEN ((importance = '0'::double precision) OR (importance IS NULL)) THEN ('0.75001'::double precision - ((search_rank)::double precision / '40'::
double precision)) ELSE importance END) DESC
         Sort Method: quicksort  Memory: 25kB
         ->  Bitmap Heap Scan on search_name  (cost=31.38..3745.22 rows=952 width=20) (actual time=0.037..0.039 rows=1 loops=1)
               Recheck Cond: (name_vector @> '{5639492}'::integer[])
               Heap Blocks: exact=1
               ->  Bitmap Index Scan on idx_search_name_name_vector  (cost=0.00..31.14 rows=952 width=0) (actual time=0.024..0.025 rows=1 loops=1)
                     Index Cond: (name_vector @> '{5639492}'::integer[])
 Planning Time: 0.264 ms
 Execution Time: 0.111 ms
(11 rows)

And if I try this query, (below) whenever I try it it gives me about 25sec of exec time :

EXPLAIN ANALYZE  SELECT place_id, address_rank,  (  SELECT count(*) FROM (   SELECT unnest(ARRAY[576918,3414840,426110])    INTERSECT   SELECT unnest(nameaddress_vector) ) s) as exactmatch FROM search_name WHERE name_vector @> ARRAY[426110] ORDER BY (CASE WHEN importance = 0 OR importance IS NULL THEN 0.75001-(search_rank::float/40) ELSE importance END) DESC, exactmatch DESC LIMIT 20;

                                                                                                                                        QUERY PLAN                                                                                                         
                                
-----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
--------------------------------
 Limit  (cost=4127.55..4127.60 rows=20 width=26) (actual time=25.999..26.004 rows=20 loops=1)
   ->  Sort  (cost=4127.55..4129.93 rows=952 width=26) (actual time=25.997..26.001 rows=20 loops=1)
         Sort Key: (CASE WHEN ((search_name.importance = '0'::double precision) OR (search_name.importance IS NULL)) THEN ('0.75001'::double precision - ((search_name.search_rank)::double precision / '40'::double precision)) ELSE search_name.importanc
e END) DESC, ((SubPlan 1)) DESC
         Sort Method: top-N heapsort  Memory: 26kB
         ->  Bitmap Heap Scan on search_name  (cost=31.38..4102.22 rows=952 width=26) (actual time=0.536..25.817 rows=232 loops=1)
               Recheck Cond: (name_vector @> '{426110}'::integer[])
               Heap Blocks: exact=229
               ->  Bitmap Index Scan on idx_search_name_name_vector  (cost=0.00..31.14 rows=952 width=0) (actual time=0.230..0.230 rows=243 loops=1)
                     Index Cond: (name_vector @> '{426110}'::integer[])
               SubPlan 1
                 ->  Aggregate  (cost=0.37..0.38 rows=1 width=8) (actual time=0.102..0.102 rows=1 loops=232)
                       ->  Subquery Scan on s  (cost=0.00..0.36 rows=3 width=0) (actual time=0.101..0.101 rows=0 loops=232)
                             ->  HashSetOp Intersect  (cost=0.00..0.33 rows=3 width=8) (actual time=0.101..0.101 rows=0 loops=232)
                                   ->  Append  (cost=0.00..0.30 rows=13 width=8) (actual time=0.001..0.077 rows=227 loops=232)
                                         ->  Subquery Scan on "*SELECT* 1"  (cost=0.00..0.06 rows=3 width=8) (actual time=0.001..0.002 rows=3 loops=232)
                                               ->  ProjectSet  (cost=0.00..0.03 rows=3 width=4) (actual time=0.001..0.001 rows=3 loops=232)
                                                     ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.000..0.000 rows=1 loops=232)
                                         ->  Subquery Scan on "*SELECT* 2"  (cost=0.00..0.17 rows=10 width=8) (actual time=0.001..0.053 rows=224 loops=232)
                                               ->  ProjectSet  (cost=0.00..0.07 rows=10 width=4) (actual time=0.001..0.024 rows=224 loops=232)
                                                     ->  Result  (cost=0.00..0.01 rows=1 width=0) (actual time=0.000..0.000 rows=1 loops=232)
 Planning Time: 3.310 ms
 Execution Time: 26.205 ms
(22 rows)

While my IOPS are very good :

root@geoplanet:/mnt/nominatim# fio --name=rand-write --ioengine=libaio --iodepth=32 --rw=randwrite --invalidate=1 --bsrange=4k:4k,4k:4k --size=512m --runtime=120 --time_based --do_verify=1 --direct=1 --group_reporting --numjobs=2 |grep iops
   iops        : min= 9256, max=16834, avg=12670.65, stdev=590.56, samples=479

but maybe it is the delay between my docker container data (internal disk) read/write data onto the postgre data (external disk) ?

Is there a way to run a container docker entirely on a specific disk @lonvia ?

[stouch]

I've setup a postgres-tuning.conf through a -v docker volume with :

# https://github.com/mediagis/nominatim-docker/issues/267
max_parallel_workers_per_gather = 0
jit = off

And for now it fixed this issue.