<div dir="ltr">Hi Tatsuo<div><br></div><div>Did you get a chance to look into this issue ? or the patch I have shared </div><div><br></div><div>Thanks</div><div>Usama </div></div><div class="gmail_extra"><br><br><div class="gmail_quote">
On Tue, May 20, 2014 at 6:11 PM, Muhammad Usama <span dir="ltr">&lt;<a href="mailto:m.usama@gmail.com" target="_blank">m.usama@gmail.com</a>&gt;</span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">
<div dir="ltr">Hi Tatsuo<div><br></div><div>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.</div>

<div>Can you please take a look at the attached patch if it can serve the purpose.</div><div>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.</div>

<div><br></div><div>Thanks</div><span class="HOEnZb"><font color="#888888"><div>Muhammad Usama</div></font></span></div><div class="HOEnZb"><div class="h5"><div class="gmail_extra"><br><br><div class="gmail_quote">On Tue, May 13, 2014 at 2:03 PM, Muhammad Usama <span dir="ltr">&lt;<a href="mailto:m.usama@gmail.com" target="_blank">m.usama@gmail.com</a>&gt;</span> wrote:<br>

<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex"><div dir="ltr"><div>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?</div>

<div><br></div>
<div>Thanks</div><span><font color="#888888"><div>Usama</div><div><br></div><div><br></div></font></span></div><div><div><div class="gmail_extra"><br><br><div class="gmail_quote">
On Mon, May 12, 2014 at 7:32 PM, Tatsuo Ishii <span dir="ltr">&lt;<a href="mailto:ishii@sraoss.co.jp" target="_blank">ishii@sraoss.co.jp</a>&gt;</span> wrote:<br>
<blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi Usama,<br>
<br>
It looks like the exact case for one of our FAQ items:<br>
<br>
<a href="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" target="_blank">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</a><br>



<br>
Best regards,<br>
--<br>
Tatsuo Ishii<br>
SRA OSS, Inc. Japan<br>
English: <a href="http://www.sraoss.co.jp/index_en.php" target="_blank">http://www.sraoss.co.jp/index_en.php</a><br>
Japanese: <a href="http://www.sraoss.co.jp" target="_blank">http://www.sraoss.co.jp</a><br>
<br>
<br>
From: Muhammad Usama &lt;<a href="mailto:m.usama@gmail.com" target="_blank">m.usama@gmail.com</a>&gt;<br>
Subject: Backend process hangs with pgpool<br>
Date: Mon, 12 May 2014 18:35:08 +0500<br>
Message-ID: &lt;CAEJvTzUkCtQFsMH4yvudB=<a href="mailto:M3jVp_Qf5xrP8GoqCjQ2n-CKKOYw@mail.gmail.com" target="_blank">M3jVp_Qf5xrP8GoqCjQ2n-CKKOYw@mail.gmail.com</a>&gt;<br>
<div><div><br>
&gt; Hi Tatsuo<br>
&gt;<br>
&gt; I am looking at the problem faced by one of the customer.  He has reported<br>
&gt; that PostgreSQL backed is frequently getting stuck on the production<br>
&gt; environment. And the analysis till this point suggests that pgpool-II&#39;s<br>
&gt; internal query (&quot;SELECT count(*) FROM pg_catalog.pg_class AS c WHERE<br>
&gt; c.relname = &#39;foldershare&#39; AND c.relpersistence = &#39;u&#39; &quot;) is responsible for<br>
&gt; the backend to get stuck, by not issuing the necessary SYNC message when it<br>
&gt; is expected by backend.<br>
&gt; I am pasting all the information and discussion regarding the problem we<br>
&gt; have so far.<br>
&gt; Can you please suggest on what could be the problem and if the problem is<br>
&gt; correctly identified what should be the proper way to fix it.<br>
&gt; I am also attaching the not working patch (temp.patch) which tries to send<br>
&gt; the sync message to backend from do_query() but doesn&#39;t worked out<br>
&gt;<br>
&gt; Please find below for the discussion, and the information regarding this<br>
&gt; problem<br>
&gt; Log , configuration files and gdb trace is also attached with the mail<br>
&gt;<br>
&gt; #query info<br>
&gt; ============<br>
&gt; enterprisedb@edb# select * from pg_stat_activity where pid = 19497;<br>
&gt;<br>
&gt; -[ RECORD 1<br>
&gt; ]----+---------------------------------------------------------------------------------------------------------<br>
&gt; datid            | 1110943<br>
&gt; datname          | cloud<br>
&gt; pid              | 19497<br>
&gt; usesysid         | 16584<br>
&gt; usename          | cloud<br>
&gt; application_name |<br>
&gt; client_addr      | 10.27.28.241<br>
&gt; client_hostname  |<br>
&gt; client_port      | 2653<br>
&gt; backend_start    | 10-APR-14 08:36:26.454733 +09:00<br>
&gt; xact_start       | 10-APR-14 08:36:26.523032 +09:00<br>
&gt; query_start      | 10-APR-14 08:36:26.551021 +09:00<br>
&gt; state_change     | 10-APR-14 08:36:26.551022 +09:00<br>
&gt; waiting          | f<br>
&gt; state            | active<br>
&gt; query            | SELECT count(*) FROM pg_catalog.pg_class AS c WHERE<br>
&gt; c.relname = &#39;foldershare&#39; AND c.relpersistence = &#39;u&#39;<br>
&gt;<br>
&gt; # explain<br>
&gt;<br>
&gt; enterprisedb@edb# explain analyze SELECT count(*) FROM pg_catalog.pg_class<br>
&gt; AS c WHERE c.relname = &#39;foldershare&#39; AND c.relpersistence = &#39;u&#39;;<br>
&gt;                                                                QUERY PLAN<br>
&gt; ---------------------------------------------------------------------------------------------------------------------------------------------<br>
&gt; Aggregate  (cost=4.27..4.28 rows=1 width=0) (actual time=0.011..0.011<br>
&gt; rows=1 loops=1)<br>
&gt;<br>
&gt;   -&gt;  Index Scan using pg_class_relname_nsp_index on pg_class c<br>
&gt;  (cost=0.00..4.27 rows=1 width=0) (actual time=0.009..0.009 rows=0 loops=1)<br>
&gt;<br>
&gt;         Index Cond: (relname = &#39;foldershare&#39;::name)<br>
&gt;<br>
&gt;         Filter: (relpersistence = &#39;u&#39;::&quot;char&quot;)<br>
&gt;<br>
&gt; Total runtime: 0.050 ms<br>
&gt;<br>
&gt; (5 rows)<br>
&gt;<br>
&gt; #OS process<br>
&gt;<br>
&gt; [09:56:21 enterprisedb@cloud-post-mdb /db/pgdba/logs]$ ps -ef | grep 19497<br>
&gt;<br>
&gt; 534      19497  7260  0 08:36 ?        00:00:00 postgres: cloud cloud<br>
&gt; 10.27.28.241[2653] SELECT<br>
&gt;<br>
&gt;<br>
&gt; Internal discussion on the problem<br>
&gt; =============================<br>
&gt;<br>
&gt; Noah Misch Wrote:<br>
&gt; ============<br>
&gt;<br>
&gt; Looking at the customer&#39;s PPAS stack trace, it could be explained by PPAS<br>
&gt; not<br>
&gt; receiving a Sync message after a series of extended query protocol messages.<br>
&gt; When this happens, pg_stat_activity and the &quot;ps&quot; line will give the<br>
&gt; appearance<br>
&gt; of an active query. An affected backend will appear to ignore<br>
&gt; pg_cancel_backend(), but it will promptly respond to pg_terminate_backend().<br>
&gt; Assuming that&#39;s a correct diagnosis, I see three potential explanations:<br>
&gt;<br>
&gt; (1) A network problem between the pgpool server and the PPAS server cuts off<br>
&gt; the transfer in the middle of an extended query protocol message sequence.<br>
&gt; (Though I don&#39;t see that the customer ever stated it directly, the files<br>
&gt; provided suggest pgpool is on a separate system.)<br>
&gt;<br>
&gt; (2) pgpool, through some bug, omits a necessary Sync message.<br>
&gt;<br>
&gt; (3) The client software omits the Sync message, and pgpool just passes on<br>
&gt; that<br>
&gt; omission. I think we can discount this possibility, because one of the<br>
&gt; customer-reported hung queries is generated internally by pgpool:<br>
&gt; SELECT count(*) FROM pg_catalog.pg_class AS c WHERE c.relname = &#39;%s&#39; AND<br>
&gt; c.relpersistence = &#39;u&#39;<br>
&gt;<br>
&gt; Either (2) or (1) could be it. I feel (2) is more likely, because it is a<br>
&gt; stretch to believe that this would be the sole symptom of network trouble.<br>
&gt; Tracking down the bug behind (2) could be difficult, alas.<br>
&gt;<br>
&gt; I propose that support file a Redmine case against pgpool to investigate<br>
&gt; explanation (2). Usama, if you would like more detail from the customer to<br>
&gt; aid the pgpool team in such analysis, now is a good time to request it. Note<br>
&gt; that the customer is offering remote access to their system.<br>
&gt;<br>
&gt; One can exercise this hang situation on the PPAS backend side by having a<br>
&gt; client program call PQexecParams() with a libpq patched like so:<br>
&gt;<br>
&gt; -- a/src/interfaces/libpq/fe-exec.c<br>
&gt; +++ b/src/interfaces/libpq/fe-exec.c<br>
&gt; @ -1558,10 +1558,12 @ PQsendQueryGuts(PGconn *conn,<br>
&gt; pqPutMsgEnd(conn) &lt; 0)<br>
&gt; goto sendFailed;<br>
&gt;<br>
&gt; #if 0<br>
&gt; /* construct the Sync message */<br>
&gt; if (pqPutMsgStart(&#39;S&#39;, false, conn) &lt; 0 ||<br>
&gt; pqPutMsgEnd(conn) &lt; 0)<br>
&gt; goto sendFailed;<br>
&gt; #endif<br>
&gt;<br>
&gt; /* remember we are using extended query protocol */<br>
&gt;         conn-&gt;queryclass = PGQUERY_EXTENDED<br>
&gt;<br>
&gt;<br>
&gt;<br>
&gt; Noah Misch Wrote:<br>
&gt; ================<br>
&gt; The PostgreSQL wire protocol has two messages, &quot;Flush&quot; and &quot;Sync&quot;, for the<br>
&gt; client to signal that it is waiting for the result of its previous requests.<br>
&gt; Sync ends any implicit transaction; Flush does not.  Sync causes the session<br>
&gt; to show as &quot;idle&quot; in pg_stat_activity; Flush leaves it &quot;active&quot;.  pgpool<br>
&gt; uses<br>
&gt; Flush for certain internal queries, because it does not wish to disturb an<br>
&gt; outstanding implicit transaction.  The consequence for pg_stat_activity<br>
&gt; output<br>
&gt; is undesirable, but it is rightly considered more tolerable than closing a<br>
&gt; user-initiated implicit transaction.<br>
&gt;<br>
&gt; In the context of this support ticket, it&#39;s enough to say that the behavior<br>
&gt; is<br>
&gt; a known limitation of pg_stat_activity and does not indicate a malfunction.<br>
&gt;<br>
&gt; As far as improving the situation, two options come to mind.  The first<br>
&gt; option<br>
&gt; is to have pgpool track whether an implicit transaction could be open; when<br>
&gt; pgpool sees a ReadyForQuery message from the server, any implicit<br>
&gt; transaction<br>
&gt; is definitely closed.  For these internal metadata queries, it can then<br>
&gt; issue<br>
&gt; a Sync instead of a Flush if the session was idle (no implicit transaction)<br>
&gt; when the internal query began.  A second option is to change the server to<br>
&gt; report a pg_stat_activity.state value other than &quot;active&quot; (perhaps &quot;idle in<br>
&gt; transaction&quot; or a novel &quot;idle in implicit transaction&quot;) when a query has<br>
&gt; ended<br>
&gt; with a Flush.<br>
&gt;<br>
&gt;<br>
&gt; Thanks<br>
&gt; Usama<br>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>
</div></div></blockquote></div><br></div>