Re: First query on each connection is too slow

Hi Vadim,

Too much of shared buffers allocation also causes problem. Read the
documentation.

Regards,
Pavan

On Wed, Jun 13, 2018, 3:23 PM Vadim Nevorotin <nevorotin(at)gmail(dot)com> 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.
>
> EXPLAIN (ANALYZE, BUFFERS) for the first query shows 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?
>