response time is very long in PG9.5.5 using psql or jdbc - Mailing list pgsql-bugs

Hi,all

In our product database,we met a problem .when we login in the database using psql or jdbc ,the response time is very long.The sql is simple,get the rows of small table.Actualy ,the execution time is also not very long when using explan analyze to see it .So where is the time gone?

[postgres@cnlf081174:eits:5521 ~/tmp]$ psql -f t.sql eits

Timing is on.

                                                        QUERY PLAN                                                        

--------------------------------------------------------------------------------------------------------------------------

Aggregate  (cost=175.79..175.80 rows=1 width=0) (actual time=1.852..1.852 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.013..1.055 rows=8871 loops=1)

         Buffers: shared hit=64

Planning time: 0.646 ms

Execution time: 1.926 ms

(6 rows)

Time: 19479.081 ms

[postgres@cnlf081174:eits:5521 ~/tmp]$

[postgres@cnlf081174:eits:5521 ~/tmp]$

[postgres@cnlf081174:eits:5521 ~/tmp]$ psql -f t.sql eits

Timing is on.

                                                        QUERY PLAN                                                        

--------------------------------------------------------------------------------------------------------------------------

Aggregate  (cost=175.79..175.80 rows=1 width=0) (actual time=1.851..1.851 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.012..1.061 rows=8871 loops=1)

         Buffers: shared hit=64

Planning time: 0.459 ms

Execution time: 1.929 ms

(6 rows)

Time: 2400.550 ms

[postgres@cnlf081174:eits:5521 ~/tmp]$ psql -f t.sql eits

Timing is on.

                                                        QUERY PLAN                                                       

--------------------------------------------------------------------------------------------------------------------------

Aggregate  (cost=175.79..175.80 rows=1 width=0) (actual time=1.790..1.791 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.010..1.045 rows=8871 loops=1)

         Buffers: shared hit=64

Planning time: 0.415 ms

Execution time: 1.858 ms

(6 rows)

Time: 1991.484 ms

[postgres@cnlf081174:eits:5521 ~/tmp]$

[postgres@cnlf081174:eits:5521 ~/tmp]$

Then ,the next test is bellow , we login in the database,it is slow first time ,and next time it will be faster,I know it is about cache.may be ,this is normal.

[postgres@cnlf081174:eits:5521 ~/tmp]$ psql eits

Timing is on.

psql (9.5.5)

Type "help" for help.

[postgres:5521@eits] [02-12.17:49:32]=# \i t.sql

                                                        QUERY PLAN                                                       

--------------------------------------------------------------------------------------------------------------------------

Aggregate  (cost=175.79..175.80 rows=1 width=0) (actual time=1.899..1.899 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.013..1.084 rows=8871 loops=1)

         Buffers: shared hit=64

Planning time: 0.492 ms

Execution time: 1.977 ms

(6 rows)

Time: 7803.830 ms

[postgres:5521@eits] [02-12.17:49:43]=# \i t.sql

                                                        QUERY PLAN                                                       

--------------------------------------------------------------------------------------------------------------------------

Aggregate  (cost=175.79..175.80 rows=1 width=0) (actual time=3.194..3.194 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.658 rows=8871 loops=1)

         Buffers: shared hit=64

Planning time: 0.091 ms

Execution time: 3.237 ms

(6 rows)

Time: 3.748 ms

[postgres:5521@eits] [02-12.17:49:45]=# \i t.sql

                                                        QUERY PLAN                                                       

--------------------------------------------------------------------------------------------------------------------------

Aggregate  (cost=175.79..175.80 rows=1 width=0) (actual time=3.182..3.182 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.009..1.666 rows=8871 loops=1)

         Buffers: shared hit=64

Planning time: 0.095 ms

Execution time: 3.227 ms

(6 rows)

Time: 3.765 ms

Bellow is the table structure:

[02-12.18:11:50]=# \d+ tbl1_stats_prop_rt

                                                         Table "public.tbl1_stats_prop_rt"

  Column   |          Type          |                              Modifiers                               | Storage  | Stats target | Description

-----------+------------------------+----------------------------------------------------------------------+----------+--------------+-------------

prop_id   | bigint                 | not null default nextval('tbl1_stats_prop_rt_prop_id_seq'::regclass) | plain    |              |

 prop_name | character varying(50)  | default NULL::character varying                                      | extended |              |

 prop_val  | character varying(250) | default NULL::character varying                                      | extended |              |

Indexes:

    "tbl1_stats_prop_rt_pkey" PRIMARY KEY, btree (prop_id)

    "tbl1_stats_prop_rt_prop_name_val" btree (prop_name, prop_val)