First query on each connection is too slow

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

First query on each connection is too slow

Vadim Nevorotin
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?
Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

pavan95
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 <[hidden email]> 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?
Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Maksim Milyutin-2
In reply to this post by Vadim Nevorotin

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?

You could catch a performance profile of this issue using perf tools and iterative executing this query in new sessions via pgbench, for example. This would greatly facilitate the search for the cause of your problem.

-- 
Regards,
Maksim Milyutin
Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Vadim Nevorotin
In reply to this post by pavan95


ср, 13 июн. 2018 г. в 13:25, Pavan Teja <[hidden email]>:
Too much of shared buffers allocation also causes problem. Read the documentation.

As I noticed ahead - it's not a shared buffers or memory problem, because it appears only on first query in each new connection, even if all data already loaded to caches by other connections.  And I've read documentation of course, and 20Gb is not too much for our server - we have 128Gb of RAM.


On Wed, Jun 13, 2018, 3:23 PM Vadim Nevorotin <[hidden email]> 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?
Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Thomas Kellerer
In reply to this post by Vadim Nevorotin
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.




Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Adrian Klaver-4
In reply to this post by Vadim Nevorotin
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
[hidden email]

Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Andres Freund
In reply to this post by pavan95
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

Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Andres Freund
In reply to this post by Vadim Nevorotin
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

Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Tom Lane-2
Andres Freund <[hidden email]> 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

Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

pavan95
In reply to this post by Andres Freund
Reply | Threaded
Open this post in threaded view
|

Re: First query on each connection is too slow

Andres Freund
In reply to this post by Tom Lane-2
Hi,

On 2018-06-13 10:49:39 -0400, Tom Lane wrote:

> Andres Freund <[hidden email]> 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

Previous Thread Next Thread