Sorry,not reply in time because of Chinese New Year.
We didn`t use pgbouncer or any other connection pool.
Current running system:
[postgres:5521@eits] [02-22.09:49:47]=# select schemaname,relname,n_live_tup,n_dead_tup,n_mod_since_analyze from pg_stat_all_tables where relname in ('pg_attribute','pg_class','pg_index');
schemaname | relname | n_live_tup | n_dead_tup | n_mod_since_analyze
------------+--------------+------------+------------+---------------------
pg_catalog | pg_attribute | 2079332 | 278247 | 74682
pg_catalog | pg_class | 538945 | 66687 | 11788
pg_catalog | pg_index | 427668 | 35464 | 15902
(3 rows)
Time: 270.579 ms
[postgres:5521@eits] [02-22.09:50:38]=# select pg_size_pretty(pg_total_relation_size('pg_attribute'));
pg_size_pretty
----------------
723 MB
(1 row)
Time: 0.842 ms
[postgres:5521@eits] [02-22.09:51:33]=# SHOW ignore_system_indexes;
ignore_system_indexes
-----------------------
off
(1 row)
[postgres:5521@eits] [02-22.09:55:30]=# \dx
List of installed extensions
Name | Version | Schema | Description
--------------------+---------+------------+-------------------------------------------------------------------
pg_buffercache | 1.1 | public | examine the shared buffer cache
pg_pathman | 1.3 | public | Partitioning tool
pg_stat_statements | 1.3 | public | track execution statistics of all SQL statements executed
pg_trgm | 1.1 | public | text similarity measurement and index searching based on trigrams
pgstattuple | 1.3 | public | show tuple-level statistics
plpgsql | 1.0 | pg_catalog | PL/pgSQL procedural language
tablefunc | 1.0 | public | functions that manipulate whole tables, including crosstab
uuid-ossp | 1.0 | public | generate universally unique identifiers (UUIDs)
(8 rows)
[postgres@cnlf081174:eits:5521 ~/tmp]$ psql -d eits
Timing is on.
psql (9.5.5)
Type "help" for help.
[postgres:5521@eits] [02-22.10:02:07]=# SET log_parser_stats = true; //when fist connection ,set still spend a long time.
SET
Time: 2189.852 ms
[postgres:5521@eits] [02-22.10:02:22]=# SET log_planner_stats = true;
SET
Time: 0.439 ms
[postgres:5521@eits] [02-22.10:02:31]=# SET client_min_messages = log;
SET
Time: 0.394 ms
[postgres:5521@eits] [02-22.10:02:38]=# \i t.sql
psql:t.sql:1: LOG: PARSER STATISTICS
DETAIL: ! system usage stats:
! 0.000063 elapsed 0.000000 user 0.000000 system sec
! [1.735736 user 0.396939 sys total]
! 0/0 [0/16] filesystem blocks in/out
! 0/32 [0/276464] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [5784/227] voluntary/involuntary context switches
psql:t.sql:1: LOG: PARSE ANALYSIS STATISTICS
DETAIL: ! system usage stats:
! 0.000423 elapsed 0.000000 user 0.000000 system sec
! [1.735736 user 0.396939 sys total]
! 0/0 [0/16] filesystem blocks in/out
! 0/116 [0/276581] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [5784/227] voluntary/involuntary context switches
psql:t.sql:1: LOG: REWRITER STATISTICS
DETAIL: ! system usage stats:
! 0.000001 elapsed 0.000000 user 0.000000 system sec
! [1.735736 user 0.396939 sys total]
! 0/0 [0/16] filesystem blocks in/out
! 0/0 [0/276581] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/0 [5784/227] voluntary/involuntary context switches
psql:t.sql:1: LOG: PLANNER STATISTICS
DETAIL: ! system usage stats:
! 0.000751 elapsed 0.000999 user 0.000000 system sec
! [1.736735 user 0.396939 sys total]
! 0/0 [0/16] filesystem blocks in/out
! 0/137 [0/276729] page faults/reclaims, 0 [0] swaps
! 0 [0] signals rcvd, 0/0 [0/0] messages rcvd/sent
! 0/1 [5784/228] voluntary/involuntary context switches
QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=175.79..175.80 rows=1 width=0) (actual time=2.840..2.840 rows=1 loops=1)
Buffers: shared hit=64
-> Seq Scan on tbl1_stats_prop_rt (cost=0.00..153.43 rows=8943 width=0) (actual time=0.014..1.628 rows=8897 loops=1)
Buffers: shared hit=64
Planning time: 0.793 ms
Execution time: 2.908 ms
(6 rows)
Time: 4.640 ms
-----邮件原件-----
发件人: Tomas Vondra [mailto:tomas.vondra@2ndquadrant.com]
发送时间: 2018年2月14日 7:53
收件人: Andres Freund <andres@anarazel.de>; David Gould <daveg@sonic.net>
抄送: Tom Lane <tgl@sss.pgh.pa.us>; 石勇虎 <SHIYONGHU651@pingan.com.cn>; pgsql-bugs@postgresql.org
主题: Re: response time is very long in PG9.5.5 using psql or jdbc
On 02/13/2018 10:31 PM, Andres Freund wrote:
> Hi,
>
> On 2018-02-13 13:24:47 -0800, David Gould wrote:
>> I see this problem fairly frequently. Typically the problem catalog
>> is pg_attribute as it has the most rows. However the problem really
>> arises when the catalogs become bloated. Once the total size of the
>> catalogs that get read at start up approaches the size of shared
>> buffers, and especially if several processes start at the same time, it becomes quite noticeable.
>
> I can obviously see problems with a bloated catalog, but how does that
> cause massive slowdowns in *individual* queries as we see here? The
> OP's problem isn't the connection establishment performance afaict,
> but the first query using specific pieces of catalog data. And that
> should be ok-ish performancewise, even if there's bloat.
>
What if the first connection does not actually go to PostgreSQL, but to some sort of connection pool (like pgbouncer)? That would be consistent with the observed behavior, I think - the first connection would likely have to open connection to a backend, paying all the price.
Obviously, this is just a stab in the dark ...
regards
--
PostgreSQL Development, 24x7 Support, Remote DBA, Training & Services