Logging at debug5, hopefully it will mean more to you than to me. Local connection connects and I quit in a few seconds. -h localhost takes 90+ seconds to be closed by the server. In the longer duration there is a lot more logged, seems like unrelated auto chatter. I turned autovacuum off in postgresql.conf in the hope that it would reduce the chatter, seems unsuccesful. psql -Umyuser -dmydb 2015-07-22 12:00:51.175 CEST DEBUG: forked new backend, pid=5923 socket=12 2015-07-22 12:00:51.175 CEST [unknown] LOG: connection received: host=[local] 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: postgres child[5923]: starting with ( 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: postgres 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: ) 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: InitPostgres 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: my backend ID is 2 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: StartTransaction 2015-07-22 12:00:51.175 CEST myuser [local]DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:00:51.176 CEST myuser [local]LOG: connection authorized: user=myuser database=mydb 2015-07-22 12:00:51.179 CEST myuser [local]DEBUG: CommitTransaction 2015-07-22 12:00:51.179 CEST myuser [local]DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:00:59.896 CEST myuser [local]DEBUG: shmem_exit(0): 1 before_shmem_exit callbacks to make 2015-07-22 12:00:59.896 CEST myuser [local]DEBUG: shmem_exit(0): 6 on_shmem_exit callbacks to make 2015-07-22 12:00:59.896 CEST myuser [local]DEBUG: proc_exit(0): 4 callbacks to make 2015-07-22 12:00:59.897 CEST myuser [local]LOG: disconnection: session time: 0:00:08.721 user=myuser database=mydb host=[local] 2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: exit(0) 2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2015-07-22 12:00:59.897 CEST myuser [local]DEBUG: proc_exit(-1): 0 callbacks to make 2015-07-22 12:00:59.898 CEST DEBUG: reaping dead processes 2015-07-22 12:00:59.898 CEST DEBUG: server process (PID 5923) exited with exit code 0 **************************************************************************** psql -Umyuser -dmyuser -h localhost 2015-07-22 12:02:20.422 CEST DEBUG: forked new backend, pid=5941 socket=12 2015-07-22 12:02:20.422 CEST [unknown] LOG: connection received: host=::1 port=51255 2015-07-22 12:02:27.393 CEST DEBUG: StartTransaction 2015-07-22 12:02:27.393 CEST DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:02:27.393 CEST DEBUG: CommitTransaction 2015-07-22 12:02:27.393 CEST DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:02:27.393 CEST DEBUG: received inquiry for database 0 2015-07-22 12:02:27.393 CEST DEBUG: writing stats file "pg_stat_tmp/global.stat" 2015-07-22 12:02:27.394 CEST DEBUG: writing stats file "pg_stat_tmp/db_0.stat" 2015-07-22 12:02:27.406 CEST DEBUG: InitPostgres 2015-07-22 12:02:27.406 CEST DEBUG: my backend ID is 2 2015-07-22 12:02:27.407 CEST DEBUG: StartTransaction 2015-07-22 12:02:27.407 CEST DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:02:27.411 CEST DEBUG: CommitTransaction 2015-07-22 12:02:27.411 CEST DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:02:27.411 CEST DEBUG: autovacuum: processing database “mydb” 2015-07-22 12:02:27.411 CEST DEBUG: received inquiry for database 16384 2015-07-22 12:02:27.411 CEST DEBUG: writing stats file "pg_stat_tmp/global.stat" 2015-07-22 12:02:27.411 CEST DEBUG: writing stats file "pg_stat_tmp/db_16384.stat" 2015-07-22 12:02:27.422 CEST DEBUG: StartTransaction 2015-07-22 12:02:27.423 CEST DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:02:27.423 CEST DEBUG: pg_statistic: vac: 0 (threshold 130), anl: 0 (threshold 90) 2015-07-22 12:02:27.423 CEST DEBUG: pg_type: vac: 0 (threshold 118), anl: 0 (threshold 84) 2015-07-22 12:02:27.423 CEST DEBUG: pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50) 2015-07-22 12:02:27.423 CEST DEBUG: pg_attribute: vac: 0 (threshold 512), anl: 0 (threshold 281) 2015-07-22 12:02:27.423 CEST DEBUG: pg_proc: vac: 0 (threshold 587), anl: 0 (threshold 318) 2015-07-22 12:02:27.423 CEST DEBUG: pg_index: vac: 0 (threshold 73), anl: 0 (threshold 61) 2015-07-22 12:02:27.423 CEST DEBUG: pg_opclass: vac: 0 (threshold 76), anl: 0 (threshold 63) 2015-07-22 12:02:27.423 CEST DEBUG: pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50) 2015-07-22 12:02:27.423 CEST DEBUG: pg_amop: vac: 0 (threshold 137), anl: 0 (threshold 94) 2015-07-22 12:02:27.423 CEST DEBUG: pg_amproc: vac: 0 (threshold 119), anl: 0 (threshold 84) 2015-07-22 12:02:27.423 CEST DEBUG: pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50) 2015-07-22 12:02:27.423 CEST DEBUG: pg_cast: vac: 0 (threshold 90), anl: 0 (threshold 70) 2015-07-22 12:02:27.423 CEST DEBUG: pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51) 2015-07-22 12:02:27.423 CEST DEBUG: pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50) 2015-07-22 12:02:27.423 CEST DEBUG: pg_class: vac: 0 (threshold 109), anl: 0 (threshold 80) 2015-07-22 12:02:27.423 CEST DEBUG: CommitTransaction 2015-07-22 12:02:27.423 CEST DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(0): 1 before_shmem_exit callbacks to make 2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(0): 7 on_shmem_exit callbacks to make 2015-07-22 12:02:27.423 CEST DEBUG: proc_exit(0): 2 callbacks to make 2015-07-22 12:02:27.423 CEST DEBUG: exit(0) 2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2015-07-22 12:02:27.423 CEST DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2015-07-22 12:02:27.423 CEST DEBUG: proc_exit(-1): 0 callbacks to make 2015-07-22 12:02:27.424 CEST DEBUG: reaping dead processes 2015-07-22 12:02:27.424 CEST DEBUG: server process (PID 5943) exited with exit code 0 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: shmem_exit(1): 0 before_shmem_exit callbacks to make 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: shmem_exit(1): 0 on_shmem_exit callbacks to make 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: proc_exit(1): 1 callbacks to make 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: exit(1) 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: shmem_exit(-1): 0 before_shmem_exit callbacks to make 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: shmem_exit(-1): 0 on_shmem_exit callbacks to make 2015-07-22 12:03:20.426 CEST [unknown] ::1(51255)DEBUG: proc_exit(-1): 0 callbacks to make 2015-07-22 12:03:20.426 CEST DEBUG: reaping dead processes 2015-07-22 12:03:20.426 CEST DEBUG: server process (PID 5941) exited with exit code 1 2015-07-22 12:03:27.395 CEST DEBUG: StartTransaction 2015-07-22 12:03:27.396 CEST DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:03:27.396 CEST DEBUG: CommitTransaction 2015-07-22 12:03:27.396 CEST DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:03:27.396 CEST DEBUG: received inquiry for database 0 2015-07-22 12:03:27.396 CEST DEBUG: writing stats file "pg_stat_tmp/global.stat" 2015-07-22 12:03:27.396 CEST DEBUG: writing stats file "pg_stat_tmp/db_0.stat" 2015-07-22 12:03:27.409 CEST DEBUG: InitPostgres 2015-07-22 12:03:27.409 CEST DEBUG: my backend ID is 2 2015-07-22 12:03:27.409 CEST DEBUG: StartTransaction 2015-07-22 12:03:27.409 CEST DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:03:27.413 CEST DEBUG: CommitTransaction 2015-07-22 12:03:27.413 CEST DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:03:27.413 CEST DEBUG: autovacuum: processing database "mydb" 2015-07-22 12:03:27.413 CEST DEBUG: received inquiry for database 16384 2015-07-22 12:03:27.413 CEST DEBUG: writing stats file "pg_stat_tmp/global.stat" 2015-07-22 12:03:27.413 CEST DEBUG: writing stats file "pg_stat_tmp/db_16384.stat" 2015-07-22 12:03:27.424 CEST DEBUG: StartTransaction 2015-07-22 12:03:27.424 CEST DEBUG: name: unnamed; blockState: DEFAULT; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:03:27.425 CEST DEBUG: pg_statistic: vac: 0 (threshold 130), anl: 0 (threshold 90) 2015-07-22 12:03:27.425 CEST DEBUG: pg_type: vac: 0 (threshold 118), anl: 0 (threshold 84) 2015-07-22 12:03:27.425 CEST DEBUG: pg_authid: vac: 0 (threshold 50), anl: 0 (threshold 50) 2015-07-22 12:03:27.425 CEST DEBUG: pg_attribute: vac: 0 (threshold 512), anl: 0 (threshold 281) 2015-07-22 12:03:27.425 CEST DEBUG: pg_proc: vac: 0 (threshold 587), anl: 0 (threshold 318) 2015-07-22 12:03:27.425 CEST DEBUG: pg_index: vac: 0 (threshold 73), anl: 0 (threshold 61) 2015-07-22 12:03:27.425 CEST DEBUG: pg_opclass: vac: 0 (threshold 76), anl: 0 (threshold 63) 2015-07-22 12:03:27.425 CEST DEBUG: pg_am: vac: 0 (threshold 51), anl: 0 (threshold 50) 2015-07-22 12:03:27.425 CEST DEBUG: pg_amop: vac: 0 (threshold 137), anl: 0 (threshold 94) 2015-07-22 12:03:27.425 CEST DEBUG: pg_amproc: vac: 0 (threshold 119), anl: 0 (threshold 84) 2015-07-22 12:03:27.425 CEST DEBUG: pg_database: vac: 0 (threshold 50), anl: 0 (threshold 50) 2015-07-22 12:03:27.425 CEST DEBUG: pg_cast: vac: 0 (threshold 90), anl: 0 (threshold 70) 2015-07-22 12:03:27.425 CEST DEBUG: pg_namespace: vac: 0 (threshold 51), anl: 0 (threshold 51) 2015-07-22 12:03:27.425 CEST DEBUG: pg_tablespace: vac: 0 (threshold 50), anl: 0 (threshold 50) 2015-07-22 12:03:27.425 CEST DEBUG: pg_class: vac: 0 (threshold 109), anl: 0 (threshold 80) 2015-07-22 12:03:27.425 CEST DEBUG: CommitTransaction 2015-07-22 12:03:27.425 CEST DEBUG: name: unnamed; blockState: STARTED; state: INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children: 2015-07-22 12:03:27.425 CEST DEBUG: shmem_exit(0): 1 before_shmem_exit callbacks to make 2015-07-22 12:03:27.425 CEST DEBUG: shmem_exit(0): 7 on_shmem_exit callbacks to make 2015-07-22 12:03:27.425 CEST DEBUG: proc_exit(0): 2 callbacks to make 2015-07-22 12:03:27.425 CEST DEBUG: exit(0) Fritz On Wed, Jul 22, 2015 at 12:05 AM, Adrian Klaver <adrian.klaver@xxxxxxxxxxx> wrote: > On 07/21/2015 01:58 PM, Fritz Meissner wrote: >>> >>> 2) I know in your original post you did a which on psql, but is there >>> more >>> then one instance/install of Postgres on this machine? >>> >>> The reason I ask is this from the original post: >>> >>> psql -Umyuser -d mydb >>> sql (9.3.5) >>> Type "help" for help. >>> >>> myuser=# >>> >> >> Yeah sorry, that's a copy/paste from before I upgraded out of >> desperation. Same thing was happening on 9.3.5 and 9.4.4. Currently: >> >> psql (9.4.4) >> Type "help" for help. >> >> myuser=# >> > > Well that would have been too easy. > > Have you tried Tom's suggestion?: > > > "However, assuming that that's not your problem, I'd suggest cranking up > log_min_messages to DEBUG5 and seeing if anything more gets reported > in the postmaster log. > " > > -- > Adrian Klaver > adrian.klaver@xxxxxxxxxxx -- Sent via pgsql-general mailing list (pgsql-general@xxxxxxxxxxxxxx) To make changes to your subscription: http://www.postgresql.org/mailpref/pgsql-general
