Thread: First query on each connection is too slow

On 13.06.2018 12:55, Vadim Nevorotin wrote:

Nested Loop Left Join  (cost=0.82..26.41 rows=1 width=4) (actual time=49.290..49.297 rows=1 loops=1)

   Join Filter: ((s_2.connamespace = n.oid) AND (s_2.conrelid = c.oid) AND (a.attnum = ANY (s_2.conkey)))
   Buffers: shared hit=18
...
 Planning time: 2.589 ms
 Execution time: 49.467 ms

(45 rows)

And there are two questions: why this problem occurs and how can I fix it?

-- 
Regards,
Maksim Milyutin

Vadim Nevorotin schrieb am 13.06.2018 um 11:55:
> I have a very strange problem. I'm using PostgreSQL 9.6 with PostGIS
> 2.3 (both from Debian Strecth repos) to store DB for OSM server (but
> actually it doesn't matter). And I've noticed, that on each new
> connection to DB first query is much slower (10x) than all others.
> E.g.:
> 
> If I run others instances of psql in parallel, when the first is
> active - they has absolutely the same problem. In one instance of
> psql query is fast (if it's not the first query), in others - first
> query is slow, but all others is fast.

Do you have many(!) tables and schemas? 

Caching of schema information is done per connection, so maybe the 
lookup of the table in the system catalogs is what is taking so much time.

But I think you would need thousands of schemas with thousands of tables 
each schema in order to notice an impact there. 

On 06/13/2018 02:55 AM, Vadim Nevorotin wrote:
> I have a very strange problem. I'm using PostgreSQL 9.6 with PostGIS 2.3 
> (both from Debian Strecth repos) to store DB for OSM server (but 
> actually it doesn't matter). And I've noticed, that on each new 
> connection to DB first query is much slower (10x) than all others. E.g.:
> 
> $ psql test_gis
> psql (9.6.7)
> Type "help" for help.
> test_gis=# \timing
> Timing is on.
> test_gis=# SELECT srid FROM geometry_columns WHERE 
> f_table_name='planet_osm_polygon' AND f_geometry_column='way';
>   srid
> ------
>   3857
> (1 row)
> Time: 52.889 ms
> test_gis=# SELECT srid FROM geometry_columns WHERE 
> f_table_name='planet_osm_polygon' AND f_geometry_column='way';
>   srid
> ------
>   3857
> (1 row)
> Time: 2.070 ms
> test_gis=#
> 
> If I run others instances of psql in parallel, when the first is active 
> - they has absolutely the same problem. In one instance of psql query is 
> fast (if it's not the first query), in others - first query is slow, but 
> all others is fast.

The EXPLAIN plan below is for the exact query above, correct?

What is the EXPLAIN ANALYZE for the second run of the query?

Does the Postgres log show anything around the time you make the query 
that might relate?

> 
> EXPLAIN (ANALYZE, BUFFERS) for the first queryshows very strange timings:
>                                                                          
>                QUERY PLAN
> 
>
--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------
> 
>   Nested Loop Left Join  (cost=0.82..26.41 rows=1 width=4) *(actual 
> time=49.290..49.297 rows=1 loops=1)*
>     Join Filter: ((s_2.connamespace = n.oid) AND (s_2.conrelid = c.oid) 
> AND (a.attnum = ANY (s_2.conkey)))
>     Buffers: shared hit=18
>     ->  Nested Loop Left Join  (cost=0.82..25.28 rows=1 width=14) 
> (actual time=0.135..0.141 rows=1 loops=1)
>           Join Filter: ((s_1.connamespace = n.oid) AND (s_1.conrelid = 
> c.oid) AND (a.attnum = ANY (s_1.conkey)))
>           Buffers: shared hit=17
>           ->  Nested Loop Left Join  (cost=0.82..24.16 rows=1 width=14) 
> (actual time=0.126..0.132 rows=1 loops=1)
>                 Join Filter: ((s.connamespace = n.oid) AND (s.conrelid = 
> c.oid) AND (a.attnum = ANY (s.conkey)))
>                 Buffers: shared hit=16
>                 ->  Nested Loop  (cost=0.82..23.05 rows=1 width=14) 
> (actual time=0.083..0.089 rows=1 loops=1)
>                       Buffers: shared hit=15
>                       ->  Nested Loop  (cost=0.55..17.75 rows=1 
> width=18) (actual time=0.078..0.082 rows=1 loops=1)
>                             Join Filter: (c.relnamespace = n.oid)
>                             Rows Removed by Join Filter: 5
>                             Buffers: shared hit=12
>                             ->  Nested Loop  (cost=0.55..16.61 rows=1 
> width=18) (actual time=0.072..0.074 rows=1 loops=1)
>                                   Buffers: shared hit=11
>                                   ->  Index Scan using 
> pg_class_relname_nsp_index on pg_class c  (cost=0.27..8.30 rows=1 
> width=8) (actual time=0.049..0.050 rows=1 loops=1)
>                                         Index Cond: (relname = 
> 'planet_osm_polygon'::name)
>                                         Filter: ((NOT 
> pg_is_other_temp_schema(relnamespace)) AND has_table_privilege(oid, 
> 'SELECT'::text) AND (relkind = ANY ('{r,v,m,f}'::"char"[])))
>                                         Buffers: shared hit=8
>                                   ->  Index Scan using 
> pg_attribute_relid_attnam_index on pg_attribute a  (cost=0.28..8.30 
> rows=1 width=14) (actual time=0.021..0.021 rows=1 loops=1)
>                                         Index Cond: ((attrelid = c.oid) 
> AND (attname = 'way'::name))
>                                         Filter: (NOT attisdropped)
>                                         Buffers: shared hit=3
>                             ->  Seq Scan on pg_namespace n 
>   (cost=0.00..1.06 rows=6 width=4) (actual time=0.003..0.004 rows=6 loops=1)
>                                   Buffers: shared hit=1
>                       ->  Index Scan using pg_type_oid_index on pg_type 
> t  (cost=0.27..5.29 rows=1 width=4) (actual time=0.005..0.007 rows=1 
> loops=1)
>                             Index Cond: (oid = a.atttypid)
>                             Filter: (typname = 'geometry'::name)
>                             Buffers: shared hit=3
>                 ->  Seq Scan on pg_constraint s  (cost=0.00..1.09 rows=1 
> width=31) (actual time=0.041..0.041 rows=0 loops=1)
>                       Filter: (consrc ~~* '%geometrytype(% = %'::text)
>                       Rows Removed by Filter: 7
>                       Buffers: shared hit=1
>           ->  Seq Scan on pg_constraint s_1  (cost=0.00..1.09 rows=1 
> width=31) (actual time=0.009..0.009 rows=0 loops=1)
>                 Filter: (consrc ~~* '%ndims(% = %'::text)
>                 Rows Removed by Filter: 7
>                 Buffers: shared hit=1
>     ->  Seq Scan on pg_constraint s_2  (cost=0.00..1.09 rows=1 width=77) 
> (actual time=0.011..0.011 rows=0 loops=1)
>           Filter: (consrc ~~* '%srid(% = %'::text)
>           Rows Removed by Filter: 7
>           Buffers: shared hit=1
> * Planning time: 2.589 ms
>   Execution time: 49.467 ms*
> 
> (45 rows)
> 
> The same problem is when connecting to PostgreSQL from Mapnik, so it's 
> not a psql problem. We have a lot of memory (shared_buffers = 20GB, 
> work_mem = 100MB) and a very small db (we've upload to empty db data 
> only for one very small county). So I'm absolutely sure that it's the 
> problem of main PostgreSQL.
> 
> And there are two questions: why this problem occurs and how can I fix it?


-- 
Adrian Klaver
adrian.klaver@aklaver.com

Hi,

On 2018-06-13 15:55:05 +0530, Pavan Teja wrote:
> Too much of shared buffers allocation also causes problem. Read the
> documentation.

That's not in the docs.

- Andres

Hi,

On 2018-06-13 12:55:27 +0300, Vadim Nevorotin wrote:
> I have a very strange problem. I'm using PostgreSQL 9.6 with PostGIS 2.3
> (both from Debian Strecth repos) to store DB for OSM server (but actually
> it doesn't matter). And I've noticed, that on each new connection to DB
> first query is much slower (10x) than all others. E.g.:
> 
> $ psql test_gis
> psql (9.6.7)
> Type "help" for help.
> test_gis=# \timing
> Timing is on.
> test_gis=# SELECT srid FROM geometry_columns WHERE
> f_table_name='planet_osm_polygon' AND f_geometry_column='way';
>  srid
> ------
>  3857
> (1 row)
> Time: 52.889 ms
> test_gis=# SELECT srid FROM geometry_columns WHERE
> f_table_name='planet_osm_polygon' AND f_geometry_column='way';
>  srid
> ------
>  3857
> (1 row)
> Time: 2.070 ms
> test_gis=#
> 
> If I run others instances of psql in parallel, when the first is active -
> they has absolutely the same problem. In one instance of psql query is fast
> (if it's not the first query), in others - first query is slow, but all
> others is fast.

What you're seeing is likely a mix of
a) Operating system overhead of doing copy-on-write the first time
   memory is touched. This can be reduced to some degree by configuring
   huge pages.
b) Postgres' caches over catalog contents (i.e. how your tables look
   like) having to be filled on the first access.  There's not really
   much you can do about it.

Is the overhead of this prohibitive for you, or are you merely curious?

- Andres

Andres Freund <andres@anarazel.de> writes:
> On 2018-06-13 12:55:27 +0300, Vadim Nevorotin wrote:
>> I have a very strange problem. I'm using PostgreSQL 9.6 with PostGIS 2.3
>> (both from Debian Strecth repos) to store DB for OSM server (but actually
>> it doesn't matter). And I've noticed, that on each new connection to DB
>> first query is much slower (10x) than all others. E.g.:
>> test_gis=# SELECT srid FROM geometry_columns WHERE
>> f_table_name='planet_osm_polygon' AND f_geometry_column='way';

> What you're seeing is likely a mix of
> a) Operating system overhead of doing copy-on-write the first time
>    memory is touched. This can be reduced to some degree by configuring
>    huge pages.
> b) Postgres' caches over catalog contents (i.e. how your tables look
>    like) having to be filled on the first access.  There's not really
>    much you can do about it.

Seeing that this query seems to involve PostGIS, I suspect that there
might be a third cause: time to load the PostGIS shared library.
If so, you could probably alleviate the issue by adding postgis
to shared_preload_libraries.

If that doesn't fix it, (b) could perhaps be alleviated by adopting
connection pooling, though that has costs of its own.

            regards, tom lane

Hi Andres,

Please find the below link:

Link:  
http://wiki.postgresql.org/wiki/Tuning_Your_PostgreSQL_Server#shared_buffers
<http://wiki.postgresql.org/wiki/Tuning_Your_PostgreSQL_Server#shared_buffers>  

Regards,
Pavan



--
Sent from: http://www.postgresql-archive.org/PostgreSQL-general-f1843780.html

Hi,

On 2018-06-13 10:49:39 -0400, Tom Lane wrote:
> Andres Freund <andres@anarazel.de> writes:
> > On 2018-06-13 12:55:27 +0300, Vadim Nevorotin wrote:
> >> I have a very strange problem. I'm using PostgreSQL 9.6 with PostGIS 2.3
> >> (both from Debian Strecth repos) to store DB for OSM server (but actually
> >> it doesn't matter). And I've noticed, that on each new connection to DB
> >> first query is much slower (10x) than all others. E.g.:
> >> test_gis=# SELECT srid FROM geometry_columns WHERE
> >> f_table_name='planet_osm_polygon' AND f_geometry_column='way';
> 
> > What you're seeing is likely a mix of
> > a) Operating system overhead of doing copy-on-write the first time
> >    memory is touched. This can be reduced to some degree by configuring
> >    huge pages.
> > b) Postgres' caches over catalog contents (i.e. how your tables look
> >    like) having to be filled on the first access.  There's not really
> >    much you can do about it.
> 
> Seeing that this query seems to involve PostGIS, I suspect that there
> might be a third cause: time to load the PostGIS shared library.
> If so, you could probably alleviate the issue by adding postgis
> to shared_preload_libraries.

Ah, good point. It recursively depends on quite a number of other
shared libraries, several of them large:

$ ldd /usr/lib/postgresql/10/lib/postgis-2.4.so|grep '=>'|awk '{print $3}'|xargs readlink -f|xargs size
   text       data        bss        dec        hex    filename
 523851       9512        864     534227      826d3    /usr/lib/liblwgeom-2.4.so.0.0.0
 191008       4528        296     195832      2fcf8    /usr/lib/x86_64-linux-gnu/libgeos_c.so.1.10.2
 474429      12904        512     487845      771a5    /usr/lib/x86_64-linux-gnu/libproj.so.13.1.0
  37408       1048         24      38480       9650    /lib/x86_64-linux-gnu/libjson-c.so.3.0.1
  30775        768          8      31551       7b3f    /usr/lib/x86_64-linux-gnu/libprotobuf-c.so.1.0.0
1795735      37356       5272    1838363     1c0d1b    /usr/lib/x86_64-linux-gnu/libxml2.so.2.9.4
1769027      20992      17152    1807171     1b9343    /lib/x86_64-linux-gnu/libc-2.27.so
1643118        956         12    1644086     191636    /lib/x86_64-linux-gnu/libm-2.27.so
1706242      60760        568    1767570     1af892    /usr/lib/x86_64-linux-gnu/libgeos-3.6.2.so
1511723      47328      13504    1572555     17fecb    /usr/lib/x86_64-linux-gnu/libstdc++.so.6.0.25
  90261        944        688      91893      166f5    /lib/x86_64-linux-gnu/libgcc_s.so.1
 100418       1840      16768     119026      1d0f2    /lib/x86_64-linux-gnu/libpthread-2.27.so
   8106        792        112       9010       2332    /lib/x86_64-linux-gnu/libdl-2.27.so
2691066      58376       3168    2752610     2a0062    /usr/lib/x86_64-linux-gnu/libicui18n.so.60.2
1715333      73880       7008    1796221     1b687d    /usr/lib/x86_64-linux-gnu/libicuuc.so.60.2
26901016        544          8    26901568    19a7c40    /usr/lib/x86_64-linux-gnu/libicudata.so.60.2
 113334       1272          8     114614      1bfb6    /lib/x86_64-linux-gnu/libz.so.1.2.11
 148548       2040          8     150596      24c44    /lib/x86_64-linux-gnu/liblzma.so.5.2.2


and with sizable writable mappings, too.  So yea,
shared_preload_libraries should help quite a bit.

Greetings,

Andres Freund