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@gmail.com> wrote:

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

ср, 13 июн. 2018 г. в 13:25, Pavan Teja <pavan.postgresdba@gmail.com>:

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.

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&gt;

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