[pgpool-hackers: 524] Re: Backend process hangs with pgpool
Muhammad Usama
m.usama at gmail.com
Tue May 20 22:11:20 JST 2014
Hi Tatsuo
I am trying to fix the issue of backend hangs happens because of missing
sync message pgpool while doing extended protocol. Although I believe this
should ideally be fixed on PostgreSQL backend side but till the time I
tried to get around this problem by sending the sync message instead of
flush message from the do_query function when backend transaction state is
IDLE.
Can you please take a look at the attached patch if it can serve the
purpose.
I am getting the clean regression with the patch and this patch is also
apparently fixing the backend state active issue. But I am not sure if this
approach might break some other scenarios which are not covered by the
regression.
Thanks
Muhammad Usama
On Tue, May 13, 2014 at 2:03 PM, Muhammad Usama <m.usama at gmail.com> wrote:
> Thanks for looking into it. So this is the known issue, which needs to be
> fixed on PostgreSQL backend side. Or is there any way possible to get
> around this in production environment?
>
> Thanks
> Usama
>
>
>
>
> On Mon, May 12, 2014 at 7:32 PM, Tatsuo Ishii <ishii at sraoss.co.jp> wrote:
>
>> Hi Usama,
>>
>> It looks like the exact case for one of our FAQ items:
>>
>>
>> http://www.pgpool.net/mediawiki/index.php/FAQ#When_I_check_pg_stat_activity_view.2C_I_see_a_query_like_.22SELECT_count.28.2A.29_FROM_pg_catalog.pg_class_AS_c_WHERE_c.oid_.3D_pgpool_regclass.28.27pgbench_accounts.27.29_AND_c.relpersistence_.3D_.27u.27.22_in_active_state_for_very_long_time._Why.3F
>>
>> Best regards,
>> --
>> Tatsuo Ishii
>> SRA OSS, Inc. Japan
>> English: http://www.sraoss.co.jp/index_en.php
>> Japanese: http://www.sraoss.co.jp
>>
>>
>> From: Muhammad Usama <m.usama at gmail.com>
>> Subject: Backend process hangs with pgpool
>> Date: Mon, 12 May 2014 18:35:08 +0500
>> Message-ID: <CAEJvTzUkCtQFsMH4yvudB=
>> M3jVp_Qf5xrP8GoqCjQ2n-CKKOYw at mail.gmail.com>
>>
>> > Hi Tatsuo
>> >
>> > I am looking at the problem faced by one of the customer. He has
>> reported
>> > that PostgreSQL backed is frequently getting stuck on the production
>> > environment. And the analysis till this point suggests that pgpool-II's
>> > internal query ("SELECT count(*) FROM pg_catalog.pg_class AS c WHERE
>> > c.relname = 'foldershare' AND c.relpersistence = 'u' ") is responsible
>> for
>> > the backend to get stuck, by not issuing the necessary SYNC message
>> when it
>> > is expected by backend.
>> > I am pasting all the information and discussion regarding the problem we
>> > have so far.
>> > Can you please suggest on what could be the problem and if the problem
>> is
>> > correctly identified what should be the proper way to fix it.
>> > I am also attaching the not working patch (temp.patch) which tries to
>> send
>> > the sync message to backend from do_query() but doesn't worked out
>> >
>> > Please find below for the discussion, and the information regarding this
>> > problem
>> > Log , configuration files and gdb trace is also attached with the mail
>> >
>> > #query info
>> > ============
>> > enterprisedb at edb# select * from pg_stat_activity where pid = 19497;
>> >
>> > -[ RECORD 1
>> >
>> ]----+---------------------------------------------------------------------------------------------------------
>> > datid | 1110943
>> > datname | cloud
>> > pid | 19497
>> > usesysid | 16584
>> > usename | cloud
>> > application_name |
>> > client_addr | 10.27.28.241
>> > client_hostname |
>> > client_port | 2653
>> > backend_start | 10-APR-14 08:36:26.454733 +09:00
>> > xact_start | 10-APR-14 08:36:26.523032 +09:00
>> > query_start | 10-APR-14 08:36:26.551021 +09:00
>> > state_change | 10-APR-14 08:36:26.551022 +09:00
>> > waiting | f
>> > state | active
>> > query | SELECT count(*) FROM pg_catalog.pg_class AS c WHERE
>> > c.relname = 'foldershare' AND c.relpersistence = 'u'
>> >
>> > # explain
>> >
>> > enterprisedb at edb# explain analyze SELECT count(*) FROM
>> pg_catalog.pg_class
>> > AS c WHERE c.relname = 'foldershare' AND c.relpersistence = 'u';
>> > QUERY
>> PLAN
>> >
>> ---------------------------------------------------------------------------------------------------------------------------------------------
>> > Aggregate (cost=4.27..4.28 rows=1 width=0) (actual time=0.011..0.011
>> > rows=1 loops=1)
>> >
>> > -> Index Scan using pg_class_relname_nsp_index on pg_class c
>> > (cost=0.00..4.27 rows=1 width=0) (actual time=0.009..0.009 rows=0
>> loops=1)
>> >
>> > Index Cond: (relname = 'foldershare'::name)
>> >
>> > Filter: (relpersistence = 'u'::"char")
>> >
>> > Total runtime: 0.050 ms
>> >
>> > (5 rows)
>> >
>> > #OS process
>> >
>> > [09:56:21 enterprisedb at cloud-post-mdb /db/pgdba/logs]$ ps -ef | grep
>> 19497
>> >
>> > 534 19497 7260 0 08:36 ? 00:00:00 postgres: cloud cloud
>> > 10.27.28.241[2653] SELECT
>> >
>> >
>> > Internal discussion on the problem
>> > =============================
>> >
>> > Noah Misch Wrote:
>> > ============
>> >
>> > Looking at the customer's PPAS stack trace, it could be explained by
>> PPAS
>> > not
>> > receiving a Sync message after a series of extended query protocol
>> messages.
>> > When this happens, pg_stat_activity and the "ps" line will give the
>> > appearance
>> > of an active query. An affected backend will appear to ignore
>> > pg_cancel_backend(), but it will promptly respond to
>> pg_terminate_backend().
>> > Assuming that's a correct diagnosis, I see three potential explanations:
>> >
>> > (1) A network problem between the pgpool server and the PPAS server
>> cuts off
>> > the transfer in the middle of an extended query protocol message
>> sequence.
>> > (Though I don't see that the customer ever stated it directly, the files
>> > provided suggest pgpool is on a separate system.)
>> >
>> > (2) pgpool, through some bug, omits a necessary Sync message.
>> >
>> > (3) The client software omits the Sync message, and pgpool just passes
>> on
>> > that
>> > omission. I think we can discount this possibility, because one of the
>> > customer-reported hung queries is generated internally by pgpool:
>> > SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = '%s' AND
>> > c.relpersistence = 'u'
>> >
>> > Either (2) or (1) could be it. I feel (2) is more likely, because it is
>> a
>> > stretch to believe that this would be the sole symptom of network
>> trouble.
>> > Tracking down the bug behind (2) could be difficult, alas.
>> >
>> > I propose that support file a Redmine case against pgpool to investigate
>> > explanation (2). Usama, if you would like more detail from the customer
>> to
>> > aid the pgpool team in such analysis, now is a good time to request it.
>> Note
>> > that the customer is offering remote access to their system.
>> >
>> > One can exercise this hang situation on the PPAS backend side by having
>> a
>> > client program call PQexecParams() with a libpq patched like so:
>> >
>> > -- a/src/interfaces/libpq/fe-exec.c
>> > +++ b/src/interfaces/libpq/fe-exec.c
>> > @ -1558,10 +1558,12 @ PQsendQueryGuts(PGconn *conn,
>> > pqPutMsgEnd(conn) < 0)
>> > goto sendFailed;
>> >
>> > #if 0
>> > /* construct the Sync message */
>> > if (pqPutMsgStart('S', false, conn) < 0 ||
>> > pqPutMsgEnd(conn) < 0)
>> > goto sendFailed;
>> > #endif
>> >
>> > /* remember we are using extended query protocol */
>> > conn->queryclass = PGQUERY_EXTENDED
>> >
>> >
>> >
>> > Noah Misch Wrote:
>> > ================
>> > The PostgreSQL wire protocol has two messages, "Flush" and "Sync", for
>> the
>> > client to signal that it is waiting for the result of its previous
>> requests.
>> > Sync ends any implicit transaction; Flush does not. Sync causes the
>> session
>> > to show as "idle" in pg_stat_activity; Flush leaves it "active". pgpool
>> > uses
>> > Flush for certain internal queries, because it does not wish to disturb
>> an
>> > outstanding implicit transaction. The consequence for pg_stat_activity
>> > output
>> > is undesirable, but it is rightly considered more tolerable than
>> closing a
>> > user-initiated implicit transaction.
>> >
>> > In the context of this support ticket, it's enough to say that the
>> behavior
>> > is
>> > a known limitation of pg_stat_activity and does not indicate a
>> malfunction.
>> >
>> > As far as improving the situation, two options come to mind. The first
>> > option
>> > is to have pgpool track whether an implicit transaction could be open;
>> when
>> > pgpool sees a ReadyForQuery message from the server, any implicit
>> > transaction
>> > is definitely closed. For these internal metadata queries, it can then
>> > issue
>> > a Sync instead of a Flush if the session was idle (no implicit
>> transaction)
>> > when the internal query began. A second option is to change the server
>> to
>> > report a pg_stat_activity.state value other than "active" (perhaps
>> "idle in
>> > transaction" or a novel "idle in implicit transaction") when a query has
>> > ended
>> > with a Flush.
>> >
>> >
>> > Thanks
>> > Usama
>>
>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://www.sraoss.jp/pipermail/pgpool-hackers/attachments/20140520/7a9d3017/attachment-0001.html>
-------------- next part --------------
diff --git a/src/protocol/pool_process_query.c b/src/protocol/pool_process_query.c
index f479626..17846b4 100644
--- a/src/protocol/pool_process_query.c
+++ b/src/protocol/pool_process_query.c
@@ -2280,9 +2280,10 @@ POOL_STATUS do_query(POOL_CONNECTION *backend, char *query, POOL_SELECT_RESULT *
#define COMMAND_COMPLETE_RECEIVED (1 << 3)
#define ROW_DESCRIPTION_RECEIVED (1 << 4)
#define DATA_ROW_RECEIVED (1 << 5)
+#define READY_FOR_QUERY_RECEIVED (1 << 6)
#define STATE_COMPLETED (PARSE_COMPLETE_RECEIVED | BIND_COMPLETE_RECEIVED |\
CLOSE_COMPLETE_RECEIVED | COMMAND_COMPLETE_RECEIVED | \
- ROW_DESCRIPTION_RECEIVED | DATA_ROW_RECEIVED)
+ ROW_DESCRIPTION_RECEIVED | DATA_ROW_RECEIVED | READY_FOR_QUERY_RECEIVED)
int i;
int len;
@@ -2417,10 +2418,27 @@ POOL_STATUS do_query(POOL_CONNECTION *backend, char *query, POOL_SELECT_RESULT *
pool_write(backend, "P", 1);
pool_write(backend, prepared_name, pname_len);
- /*
- * Send flush message
- */
- pool_write(backend, "H", 1);
+ if(backend->tstate == 'I' && doing_extended)
+ {
+ /*
+ * If the backend state was idle and we are doing
+ * extended protocol. Send the sync message
+ */
+ pool_write(backend, "S", 1);
+ }
+ else
+ {
+ /*
+ * Send flush message
+ */
+ pool_write(backend, "H", 1);
+ /*
+ * If we are not sending the flush message we may not receive
+ * ReadyForQuery message from the server
+ */
+ state |= READY_FOR_QUERY_RECEIVED;
+ }
+
len = htonl(sizeof(len));
pool_write_and_flush(backend, &len, sizeof(len));
}
@@ -2508,6 +2526,7 @@ POOL_STATUS do_query(POOL_CONNECTION *backend, char *query, POOL_SELECT_RESULT *
{
case 'Z': /* Ready for query */
pool_debug("do_query: Ready for query");
+ state |= READY_FOR_QUERY_RECEIVED;
if (!doing_extended)
return POOL_CONTINUE;
break;
More information about the pgpool-hackers
mailing list