[pgpool-general: 8232] Re: Pg_stat_activity hung queries issue
Avi Raboah
avi.raboah at gmail.com
Tue Jun 21 21:59:36 JST 2022
Pgpool.conf-
listen_addresses = '*'
port = '9999'
socket_dir = '/var/run/pgpool'
pcp_socket_dir = '/var/run/pgpool'
wd_ipc_socket_dir = '/var/run/pgpool'
pid_file_name = '/var/run/pgpool/pgpool.pid'
backend_hostname0 = db_instance
backend_port0 = '5432'
backend_flag0 = 'ALLOW_TO_FAILOVER'
backend_weight0 = '1'
connection_cache = on
num_init_children = 200
child_life_time = 0
max_pool = 4
log_destination = 'stderr'
log_line_prefix = '%m: %a pid %p: '
log_connections = off
log_disconnections = off
log_statement = off
log_client_messages = on
client_min_messages = info
log_min_messages = debug
logging_collector = on
log_directory = '/tmp/pgpool_logs'
log_filename = 'pgpool-%Y-%m-%d_%H%M%S.log'
log_file_mode = 0600
log_truncate_on_rotation = off
log_rotation_age = 1d
log_rotation_size = 200MB
sr_check_user = 'user'
sr_check_password = 'password'
sr_check_period = '10'
memory_cache_enabled = 'on'
memqcache_total_size = 64MB
memqcache_max_num_cache = 1000000
memqcache_maxcache = 400kB
memqcache_cache_block_size = 1MB
memqcache_oiddir = '/var/log/pgpool/oiddir'
cache_safe_memqcache_table_list = ''
cache_unsafe_memqcache_table_list = ''
check_unlogged_table = on
health_check_period = '10'
health_check_user = 'user'
failover_on_backend_error = 'off'
On Tue, 21 Jun 2022 at 10:51 Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> Please share the log with log_client_messages = on so that I can see
> what your client actually is sending. Also I need pgpool.conf.
>
> > We are using asyncPg module in python in order to send our queries the
> > difference between that module to psycopg is that asyncpg using extended
> > queries.
> > And I can see that the issue is reproduced in case transaction aborted
> and
> > the catalog queries are launched.
> >
> > I checked in the code and found that check_transaction_state_and_abort
> > happens only in simpleQuery process.
> >
> > Thanks,
> >
> > Avi
> >
> > On Tue, 21 Jun 2022 at 6:43 Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> >
> >> Can you elaborate more?
> >>
> >> I tried following case and pgpool ignores all queries from client
> >> after a parse error occurs as expected.
> >>
> >> pgproto -d test -p 11000 -f ../pgproto.data
> >> FE=> Parse(stmt="", query="BEGIN")
> >> FE=> Bind(stmt="", portal="")
> >> FE=> Execute(portal="")
> >> FE=> Parse(stmt="", query="INSERT INTO non_existing_table values(1)")
> >> FE=> Bind(stmt="", portal="")
> >> FE=> Execute(portal="")
> >> FE=> Parse(stmt="", query="END")
> >> FE=> Bind(stmt="", portal="")
> >> FE=> Execute(portal="")
> >> FE=> Sync
> >> <= BE ParseComplete
> >> <= BE BindComplete
> >> <= BE CommandComplete(BEGIN)
> >> <= BE ErrorResponse(S ERROR V ERROR C 42P01 M relation
> >> "non_existing_table" does not exist P 13 F parse_relation.c L 1381 R
> >> parserOpenTable )
> >> <= BE ReadyForQuery(E)
> >> FE=> Terminate
> >>
> >> > Hi,
> >> >
> >> > After investigating the code I found that the patch you provided is
> >> fixing
> >> > the problem only for simple query. In extended query the issue still
> >> exist.
> >> >
> >> > Do you know where is the right place to add the transaction failure
> >> > verification in extended query process?
> >> > On Mon, 9 May 2022 at 16:17 Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
> >> >
> >> >> The patch (plus more fix) has been committed to master and 4.3 stable
> >> >> branches.
> >> >>
> >> >>
> https://www.pgpool.net/pipermail/pgpool-committers/2022-May/008592.html
> >> >>
> https://www.pgpool.net/pipermail/pgpool-committers/2022-May/008591.html
> >> >>
> >> >> The patches will appear in the next release (May 19, 2022).
> >> >>
> >> >> I have not pushed to other stable branches because the fix is not
> >> >> small and I wanted to minimize risks.
> >> >>
> >> >> > Thanks a lot for the patch have a great weekend
> >> >> >
> >> >> > On Sat, 7 May 2022 at 13:35 Tatsuo Ishii <ishii at sraoss.co.jp>
> wrote:
> >> >> >
> >> >> >> > Hi,
> >> >> >> >
> >> >> >> > Still thinking.
> >> >> >> >
> >> >> >> > Best reagards,
> >> >> >> > --
> >> >> >> > Tatsuo Ishii
> >> >> >> > SRA OSS, Inc. Japan
> >> >> >> > English: http://www.sraoss.co.jp/index_en.php
> >> >> >> > Japanese:http://www.sraoss.co.jp
> >> >> >> >
> >> >> >> >
> >> >> >> >> Hi,
> >> >> >> >>
> >> >> >> >> Any news about this thread?
> >> >> >> >>
> >> >> >> >> Thanks,
> >> >> >> >> Avi.
> >> >> >> >>
> >> >> >> >> On Mon, 25 Apr 2022 at 11:13 Avi Raboah <avi.raboah at gmail.com>
> >> >> wrote:
> >> >> >> >>
> >> >> >> >>> It will be perfect thanks a lot!
> >> >> >> >>>
> >> >> >> >>> On Mon, 25 Apr 2022 at 10:47 Tatsuo Ishii <ishii at sraoss.co.jp
> >
> >> >> wrote:
> >> >> >> >>>
> >> >> >> >>>> > No, it doesn't.
> >> >> >> >>>> > In that case when you make the select statement, piggy
> >> internal
> >> >> >> queries
> >> >> >> >>>> > failed and the session rebooted
> >> >> >> >>>>
> >> >> >> >>>> I see it now.
> >> >> >> >>>>
> >> >> >> >>>> test=# begin;
> >> >> >> >>>> BEGIN
> >> >> >> >>>> test=*# insert into ttt values(1);
> >> >> >> >>>> ERROR: relation "ttt" does not exist
> >> >> >> >>>> LINE 1: insert into ttt values(1);
> >> >> >> >>>> ^
> >> >> >> >>>> test=!# select * from t1;
> >> >> >> >>>> FATAL: Backend throw an error message
> >> >> >> >>>> DETAIL: Exiting current session because of an error from
> >> backend
> >> >> >> >>>> HINT: BACKEND Error: "current transaction is aborted,
> commands
> >> >> >> ignored
> >> >> >> >>>> until end of transaction block"
> >> >> >> >>>> server closed the connection unexpectedly
> >> >> >> >>>> This probably means the server terminated abnormally
> >> >> >> >>>> before or while processing the request.
> >> >> >> >>>> The connection to the server was lost. Attempting reset:
> >> Succeeded.
> >> >> >> >>>>
> >> >> >> >>>> I think pgpool could remember that current transaction is in
> >> abort
> >> >> >> >>>> status and does not issue the piggyback query when the selec
> is
> >> >> >> >>>> issued. Let me see what we can do for this.
> >> >> >>
> >> >> >> I have come up with a patch. In this patch pgpool checks if
> current
> >> >> >> transaction is in abort status. If so, it does not accept new
> query
> >> at
> >> >> >> all and just reply back frontend with the message:
> >> >> >>
> >> >> >> "current transaction is aborted, commands ignored until end of
> >> >> transaction
> >> >> >> block"
> >> >> >>
> >> >> >> until commit or abort command is sent from frontend. After
> applying
> >> >> >> the patch the example session above looks like this:
> >> >> >>
> >> >> >> test=# begin;
> >> >> >> BEGIN
> >> >> >> test=*# insert into ttt values(1);
> >> >> >> ERROR: relation "ttt" does not exist
> >> >> >> LINE 1: insert into ttt values(1);
> >> >> >> ^
> >> >> >> test=!# select * from t1;
> >> >> >> ERROR: current transaction is aborted, commands ignored until
> end of
> >> >> >> transaction block
> >> >> >>
> >> >> >> The patch was tested in master branch, but I believe it can be
> >> >> >> applied to 4.3 stable branch as well.
> >> >> >>
> >> >> >> Best reagards,
> >> >> >> --
> >> >> >> Tatsuo Ishii
> >> >> >> SRA OSS, Inc. Japan
> >> >> >> English: http://www.sraoss.co.jp/index_en.php
> >> >> >> Japanese:http://www.sraoss.co.jp
> >> >> >>
> >> >>
> >>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.pgpool.net/pipermail/pgpool-general/attachments/20220621/631daaca/attachment-0001.htm>
-------------- next part --------------
LOG: Parse message from frontend.
2022-06-21 12:34:38.330: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_1__", query: "BEGIN"
2022-06-21 12:34:38.330: [unknown] pid 238: LOG: Describe message from frontend.
2022-06-21 12:34:38.330: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_1__"
2022-06-21 12:34:38.330: [unknown] pid 238: LOG: Flush message from frontend.
2022-06-21 12:34:38.393: [unknown] pid 238: LOG: Bind message from frontend.
2022-06-21 12:34:38.393: [unknown] pid 238: DETAIL: portal: "", statement: "__asyncpg_stmt_1__"
2022-06-21 12:34:38.393: [unknown] pid 238: LOG: Execute message from frontend.
2022-06-21 12:34:38.393: [unknown] pid 238: DETAIL: portal: ""
2022-06-21 12:34:38.393: [unknown] pid 238: LOG: Sync message from frontend.
2022-06-21 12:34:38.456: [unknown] pid 238: LOG: Parse message from frontend.
2022-06-21 12:34:38.456: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_2__", query: "select ****"
2022-06-21 12:34:38.459: [unknown] pid 238: LOG: Describe message from frontend.
2022-06-21 12:34:38.459: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_2__"
2022-06-21 12:34:38.459: [unknown] pid 238: LOG: Flush message from frontend.
2022-06-21 12:34:38.526: [unknown] pid 238: LOG: Parse message from frontend.
2022-06-21 12:34:38.526: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_3__", query: "WITH RECURSIVE typeinfo_tree(
oid, ns, name, kind, basetype, elemtype, elemdelim,
range_subtype, attrtypoids, attrnames, depth)
AS (
SELECT
ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
ti.elemtype, ti.elemdelim, ti.range_subtype,
ti.attrtypoids, ti.attrnames, 0
FROM
(
SELECT
t.oid AS oid,
ns.nspname AS ns,
t.typname AS name,
t.typtype AS kind,
(CASE WHEN t.typtype = 'd' THEN
(WITH RECURSIVE typebases(oid, depth) AS (
SELECT
t2.typbasetype AS oid,
0 AS depth
FROM
pg_type t2
WHERE
t2.oid = t.oid
UNION ALL
SELECT
t2.typbasetype AS oid,
tb.depth + 1 AS depth
FROM
pg_type t2,
typebases tb
WHERE
tb.oid = t2.oid
AND t2.typbasetype != 0
) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
ELSE NULL
END) AS basetype,
t.typelem AS elemtype,
elem_t.typdelim AS elemdelim,
range_t.rngsubtype AS range_subtype,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.atttypid ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)
ELSE NULL
END) AS attrtypoids,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.attname::text ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)
ELSE NULL
END) AS attrnames
FROM
pg_catalog.pg_type AS t
INNER JOIN pg_catalog.pg_namespace ns ON (
ns.oid = t.typnamespace)
LEFT JOIN pg_type elem_t ON (
t.typlen = -1 AND
t.typelem != 0 AND
t.typelem = elem_t.oid
)
LEFT JOIN pg_range range_t ON (
t.oid = range_t.rngtypid
)
)
AS ti
WHERE
ti.oid = any($1::oid[])
UNION ALL
SELECT
ti.oid, ti.ns, ti.name, ti.kind, ti.basetype,
ti.elemtype, ti.elemdelim, ti.range_subtype,
ti.attrtypoids, ti.attrnames, tt.depth + 1
FROM
(
SELECT
t.oid AS oid,
ns.nspname AS ns,
t.typname AS name,
t.typtype AS kind,
(CASE WHEN t.typtype = 'd' THEN
(WITH RECURSIVE typebases(oid, depth) AS (
SELECT
t2.typbasetype AS oid,
0 AS depth
FROM
pg_type t2
WHERE
t2.oid = t.oid
UNION ALL
SELECT
t2.typbasetype AS oid,
tb.depth + 1 AS depth
FROM
pg_type t2,
typebases tb
WHERE
tb.oid = t2.oid
AND t2.typbasetype != 0
) SELECT oid FROM typebases ORDER BY depth DESC LIMIT 1)
ELSE NULL
END) AS basetype,
t.typelem AS elemtype,
elem_t.typdelim AS elemdelim,
range_t.rngsubtype AS range_subtype,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.atttypid ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)
ELSE NULL
END) AS attrtypoids,
(CASE WHEN t.typtype = 'c' THEN
(SELECT
array_agg(ia.attname::text ORDER BY ia.attnum)
FROM
pg_attribute ia
INNER JOIN pg_class c
ON (ia.attrelid = c.oid)
WHERE
ia.attnum > 0 AND NOT ia.attisdropped
AND c.reltype = t.oid)
ELSE NULL
END) AS attrnames
FROM
pg_catalog.pg_type AS t
INNER JOIN pg_catalog.pg_namespace ns ON (
ns.oid = t.typnamespace)
LEFT JOIN pg_type elem_t ON (
t.typlen = -1 AND
t.typelem != 0 AND
t.typelem = elem_t.oid
)
LEFT JOIN pg_range range_t ON (
t.oid = range_t.rngtypid
)
)
ti,
typeinfo_tree tt
WHERE
(tt.elemtype IS NOT NULL AND ti.oid = tt.elemtype)
OR (tt.attrtypoids IS NOT NULL AND ti.oid = any(tt.attrtypoids))
OR (tt.range_subtype IS NOT NULL AND ti.oid = tt.range_subtype)
)
SELECT DISTINCT
*,
basetype::regtype::text AS basetype_name,
elemtype::regtype::text AS elemtype_name,
range_subtype::regtype::text AS range_subtype_name
FROM
typeinfo_tree
ORDER BY
depth DESC
"
2022-06-21 12:34:38.527: [unknown] pid 238: LOG: Describe message from frontend.
2022-06-21 12:34:38.527: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_3__"
2022-06-21 12:34:38.527: [unknown] pid 238: LOG: Flush message from frontend.
2022-06-21 12:34:38.591: [unknown] pid 238: LOG: Bind message from frontend.
2022-06-21 12:34:38.591: [unknown] pid 238: DETAIL: portal: "", statement: "__asyncpg_stmt_3__"
2022-06-21 12:34:38.591: [unknown] pid 238: LOG: Execute message from frontend.
2022-06-21 12:34:38.591: [unknown] pid 238: DETAIL: portal: ""
2022-06-21 12:34:38.592: [unknown] pid 238: LOG: Sync message from frontend.
2022-06-21 12:34:38.657: [unknown] pid 238: LOG: Bind message from frontend.
2022-06-21 12:34:38.657: [unknown] pid 238: DETAIL: portal: "", statement: "__asyncpg_stmt_2__"
2022-06-21 12:34:38.657: [unknown] pid 238: LOG: Execute message from frontend.
2022-06-21 12:34:38.657: [unknown] pid 238: DETAIL: portal: ""
2022-06-21 12:34:38.660: [unknown] pid 238: LOG: Sync message from frontend.
2022-06-21 12:34:38.724: [unknown] pid 238: LOG: Parse message from frontend.
2022-06-21 12:34:38.724: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_4__", query: "insert into **** RETURNING *"
2022-06-21 12:34:38.725: [unknown] pid 238: LOG: Describe message from frontend.
2022-06-21 12:34:38.725: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_4__"
2022-06-21 12:34:38.725: [unknown] pid 238: LOG: Flush message from frontend.
2022-06-21 12:34:38.795: [unknown] pid 238: LOG: Bind message from frontend.
2022-06-21 12:34:38.795: [unknown] pid 238: DETAIL: portal: "", statement: "__asyncpg_stmt_4__"
2022-06-21 12:34:38.795: [unknown] pid 238: LOG: Execute message from frontend.
2022-06-21 12:34:38.795: [unknown] pid 238: DETAIL: portal: ""
2022-06-21 12:34:38.795: [unknown] pid 238: LOG: Sync message from frontend.
2022-06-21 12:34:38.797: [unknown] pid 238: LOG: Error message from backend: DB node id: 0 message: "duplicate key value violates unique constraint "email_unique""
2022-06-21 12:34:38.857: [unknown] pid 238: LOG: Parse message from frontend.
2022-06-21 12:34:38.857: [unknown] pid 238: DETAIL: statement: "__asyncpg_stmt_5__", query: "select * from "group" limit 1"
2022-06-21 12:34:38.858: [unknown] pid 238: FATAL: Backend throw an error message
2022-06-21 12:34:38.858: [unknown] pid 238: DETAIL: Exiting current session because of an error from backend
2022-06-21 12:34:38.858: [unknown] pid 238: HINT: BACKEND Error: "current transaction is aborted, commands ignored until end of transaction block"
2022-06-21 12:34:38.858: [unknown] pid 238: CONTEXT: while searching system catalog, When relcache is missed
2022-06-21 12:34:38.859: main pid 1: LOG: child process with pid: 238 exits with status 256
2022-06-21 12:34:38.859: main pid 1: LOG: fork a new child process with pid: 270
More information about the pgpool-general
mailing list