[pgpool-general: 4962] PGPool transactions hanging
Steven Livingstone
steven at livz.org
Wed Aug 31 18:28:36 JST 2016
Hi. I suspect this isn't a bug but rather the way PGPool works but i
am keen to understand it to see if i can resolve the problem.
I am using a [3rd party] library that wraps requests in a transaction
and uses unprepared/unnamed statements at the client.
I am finding that the queries are going through PGPool to Postgres but
just sit as "active" in the database and are never actually executed.
I am completely stuck as to why but hoping someone can shine some
light on what may be going on from the logs below.
Note that if i don't use PGPool and go direct to Postgres from the
client library, it all works fine.
I can't get round the problem so if i can figure out how to fix it i
will need to skip PGPool which would be a shame as i've put a lot of
effort into it :-(
many thanks,
steven
=====================
PGPool
====================
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-4] #011 FROM pg_attribute AS a
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-5] #011 WHERE
a.attrelid = t.typrelid AND a.attnum > 0 AND NOT a.attisdropped
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-6] #011 ORDER BY a.attnum
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-7] #011)
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-8] #011FROM pg_type AS t
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-9] #011LEFT JOIN
pg_range AS r ON r.rngtypid = t.oid
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [8-10] #011" message:
"StartTransactionCommand"
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [9-1] 2016-08-31
09:00:33: pid 19654: LOG: DB node id: 0 backend pid: 1762 statement:
Parse: CREATE TABLE IF NOT EXISTS "schema_migrations" ("version"
bigint, "inserted_at" timestamp, PRIMARY KEY ("version"))
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [10-1] 2016-08-31
09:00:33: pid 19654: LOG: pool_send_and_wait: Error or notice message
from backend: : DB node id: 0 backend pid: 1762 statement: "CREATE
TABLE IF NOT EXISTS "schema_migrations" ("version" bigint,
"inserted_at" timestamp, PRIMARY KEY ("version"))" message: "parse
<unnamed>: CREATE TABLE IF NOT EXISTS "schema_migrations" ("version"
bigint, "inserted_at" timestamp, PRIMARY KEY ("version"))"
Aug 31 09:00:33 data-ha-node-0 pgpool[19654]: [11-1] 2016-08-31
09:00:33: pid 19654: LOG: Parse: Error or notice message from
backend: : DB node id: 0 backend pid: 1762 statement: "CREATE TABLE IF
NOT EXISTS "schema_migrations" ("version" bigint, "inserted_at"
timestamp, PRIMARY KEY ("version"))" message: "parse <unnamed>: CREATE
TABLE IF NOT EXISTS "schema_migrations" ("version" bigint,
"inserted_at" timestamp, PRIMARY KEY ("version"))"
=====================
Postgres
=====================
Aug 31 09:00:32 enddata-master-0 postgres[1762]: [236-1] 2016-08-31
09:00:32 UTC LOG: duration: 40.591 ms
Aug 31 09:00:32 data-master-0 postgres[1762]: [237-1] 2016-08-31
09:00:32 UTC DEBUG: parse <unnamed>: CREATE TABLE IF NOT EXISTS
"schema_migrations" ("version" bigint, "inserted_at" timestamp,
PRIMARY KEY ("version"))
Aug 31 09:00:32 data-master-0 postgres[1762]: [237-2] 2016-08-31
09:00:32 UTC STATEMENT: CREATE TABLE IF NOT EXISTS
"schema_migrations" ("version" bigint, "inserted_at" timestamp,
PRIMARY KEY ("version"))
Aug 31 09:00:32 data-master-0 postgres[1762]: [238-1] 2016-08-31
09:00:32 UTC DEBUG: StartTransactionCommand
Aug 31 09:00:32 data-master-0 postgres[1762]: [238-2] 2016-08-31
09:00:32 UTC STATEMENT: CREATE TABLE IF NOT EXISTS
"schema_migrations" ("version" bigint, "inserted_at" timestamp,
PRIMARY KEY ("version"))
Aug 31 09:00:32 data-master-0 postgres[1762]: [239-1] 2016-08-31
09:00:32 UTC DEBUG: StartTransaction
Aug 31 09:00:32 data-master-0 postgres[1762]: [239-2] 2016-08-31
09:00:32 UTC STATEMENT: CREATE TABLE IF NOT EXISTS
"schema_migrations" ("version" bigint, "inserted_at" timestamp,
PRIMARY KEY ("version"))
Aug 31 09:00:32 data-master-0 postgres[1762]: [240-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: DEFAULT; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1762]: [240-2] 2016-08-31
09:00:32 UTC STATEMENT: CREATE TABLE IF NOT EXISTS
"schema_migrations" ("version" bigint, "inserted_at" timestamp,
PRIMARY KEY ("version"))
Aug 31 09:00:32 data-master-0 postgres[1762]: [241-1] 2016-08-31
09:00:32 UTC LOG: duration: 0.236 ms parse <unnamed>: CREATE TABLE
IF NOT EXISTS "schema_migrations" ("version" bigint, "inserted_at"
timestamp, PRIMARY KEY ("version"))
Aug 31 09:00:32 data-master-0 postgres[1619]: [113-1] 2016-08-31
09:00:32 UTC DEBUG: StartTransaction
Aug 31 09:00:32 data-master-0 postgres[1619]: [114-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: DEFAULT; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1619]: [115-1] 2016-08-31
09:00:32 UTC DEBUG: CommitTransaction
Aug 31 09:00:32 data-master-0 postgres[1619]: [116-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: STARTED; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1621]: [156-1] 2016-08-31
09:00:32 UTC DEBUG: received inquiry for database 0
Aug 31 09:00:32 data-master-0 postgres[1621]: [157-1] 2016-08-31
09:00:32 UTC DEBUG: writing stats file "pg_stat_tmp/global.stat"
Aug 31 09:00:32 data-master-0 postgres[1621]: [158-1] 2016-08-31
09:00:32 UTC DEBUG: writing stats file "pg_stat_tmp/db_0.stat"
Aug 31 09:00:32 data-master-0 postgres[1619]: [117-1] 2016-08-31
09:00:32 UTC DEBUG: StartTransaction
Aug 31 09:00:32 data-master-0 postgres[1619]: [118-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: DEFAULT; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1619]: [119-1] 2016-08-31
09:00:32 UTC DEBUG: CommitTransaction
Aug 31 09:00:32 data-master-0 postgres[1619]: [120-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: STARTED; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1764]: [218-1] 2016-08-31
09:00:32 UTC DEBUG: InitPostgres
Aug 31 09:00:32 data-master-0 postgres[1764]: [219-1] 2016-08-31
09:00:32 UTC DEBUG: my backend ID is 5
Aug 31 09:00:32 data-master-0 postgres[1764]: [220-1] 2016-08-31
09:00:32 UTC DEBUG: StartTransaction
Aug 31 09:00:32 data-master-0 postgres[1764]: [221-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: DEFAULT; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1764]: [222-1] 2016-08-31
09:00:32 UTC DEBUG: CommitTransaction
Aug 31 09:00:32 data-master-0 postgres[1764]: [223-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: STARTED; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1764]: [224-1] 2016-08-31
09:00:32 UTC DEBUG: autovacuum: processing database
"hello2_phoenix_dev"
Aug 31 09:00:32 data-master-0 postgres[1621]: [159-1] 2016-08-31
09:00:32 UTC DEBUG: received inquiry for database 16396
Aug 31 09:00:32 data-master-0 postgres[1621]: [160-1] 2016-08-31
09:00:32 UTC DEBUG: writing stats file "pg_stat_tmp/global.stat"
Aug 31 09:00:32 data-master-0 postgres[1621]: [161-1] 2016-08-31
09:00:32 UTC DEBUG: writing stats file "pg_stat_tmp/db_16396.stat"
Aug 31 09:00:32 data-master-0 postgres[1764]: [225-1] 2016-08-31
09:00:32 UTC DEBUG: StartTransaction
Aug 31 09:00:32 data-master-0 postgres[1764]: [226-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: DEFAULT; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1764]: [227-1] 2016-08-31
09:00:32 UTC DEBUG: pg_authid: vac: 2 (threshold 50), anl: 2
(threshold 50)
Aug 31 09:00:32 data-master-0 postgres[1764]: [228-1] 2016-08-31
09:00:32 UTC DEBUG: pg_attribute: vac: 0 (threshold 505), anl: 0
(threshold 277)
Aug 31 09:00:32 data-master-0 postgres[1764]: [229-1] 2016-08-31
09:00:32 UTC DEBUG: pg_class: vac: 0 (threshold 108), anl: 0
(threshold 79)
Aug 31 09:00:32 data-master-0 postgres[1764]: [230-1] 2016-08-31
09:00:32 UTC DEBUG: pg_index: vac: 0 (threshold 72), anl: 0
(threshold 61)
Aug 31 09:00:32 data-master-0 postgres[1764]: [231-1] 2016-08-31
09:00:32 UTC DEBUG: pg_opclass: vac: 0 (threshold 74), anl: 0
(threshold 62)
Aug 31 09:00:32 data-master-0 postgres[1764]: [232-1] 2016-08-31
09:00:32 UTC DEBUG: pg_am: vac: 0 (threshold 51), anl: 0 (threshold
50)
Aug 31 09:00:32 data-master-0 postgres[1764]: [233-1] 2016-08-31
09:00:32 UTC DEBUG: pg_amproc: vac: 0 (threshold 108), anl: 0
(threshold 79)
Aug 31 09:00:32 data-master-0 postgres[1764]: [234-1] 2016-08-31
09:00:32 UTC DEBUG: pg_database: vac: 3 (threshold 50), anl: 5
(threshold 50)
Aug 31 09:00:32 data-master-0 postgres[1764]: [235-1] 2016-08-31
09:00:32 UTC DEBUG: pg_tablespace: vac: 0 (threshold 50), anl: 0
(threshold 50)
Aug 31 09:00:32 data-master-0 postgres[1764]: [236-1] 2016-08-31
09:00:32 UTC DEBUG: pg_shdepend: vac: 0 (threshold 50), anl: 2
(threshold 50)
Aug 31 09:00:32 data-master-0 postgres[1764]: [237-1] 2016-08-31
09:00:32 UTC DEBUG: CommitTransaction
Aug 31 09:00:32 data-master-0 postgres[1764]: [238-1] 2016-08-31
09:00:32 UTC DEBUG: name: unnamed; blockState: STARTED; state:
INPROGR, xid/subid/cid: 0/1/0, nestlvl: 1, children:
Aug 31 09:00:32 data-master-0 postgres[1764]: [239-1] 2016-08-31
09:00:32 UTC DEBUG: shmem_exit(0): 8 callbacks to make
Aug 31 09:00:32 data-master-0 postgres[1764]: [240-1] 2016-08-31
09:00:32 UTC DEBUG: proc_exit(0): 2 callbacks to make
Aug 31 09:00:32 data-master-0 postgres[1764]: [241-1] 2016-08-31
09:00:32 UTC DEBUG: exit(0)
Aug 31 09:00:32 data-master-0 postgres[1764]: [242-1] 2016-08-31
09:00:32 UTC DEBUG: shmem_exit(-1): 0 callbacks to make
Aug 31 09:00:32 data-master-0 postgres[1764]: [243-1] 2016-08-31
09:00:32 UTC DEBUG: proc_exit(-1): 0 callbacks to make
Aug 31 09:00:32 data-master-0 postgres[1612]: [218-1] 2016-08-31
09:00:32 UTC DEBUG: reaping dead processes
Aug 31 09:00:32 data-master-0 postgres[1612]: [219-1] 2016-08-31
09:00:32 UTC DEBUG: server process (PID 1764) exited with exit code 0
Aug 31 09:00:40 data-master-0 postgres[1612]: [220-1] 2016-08-31
09:00:40 UTC DEBUG: forked new backend, pid=1765 socket=12
Aug 31 09:00:40 data-master-0 postgres[1765]: [220-1] 2016-08-31
09:00:40 UTC LOG: connection received: host=10.0.1.8 port=44810
Aug 31 09:00:40 data-master-0 postgres[1765]: [221-1] 2016-08-31
09:00:40 UTC DEBUG: postgres child[1765]: starting with (
Aug 31 09:00:40 data-master-0 postgres[1765]: [222-1] 2016-08-31
09:00:40 UTC DEBUG: #011postgres
Aug 31 09:00:40 data-master-0 postgres[1765]: [223-1] 2016-08-31
09:00:40 UTC DEBUG: )
More information about the pgpool-general
mailing list