<div dir="ltr"><div dir="ltr"><div dir="ltr">Hi Ishii-San</div><div dir="ltr"><div><br></div><div>Please find the attached the debug log and pgpool.conf </div><div><br></div><div>The output of the stack trace, session context and query context is pasted below</div><div><br></div><div><b>--STACK-TRACE--</b></div><div><div><font face="monospace, monospace">#0  0x00007f3d5d218c53 in __select_nocancel () at ../sysdeps/unix/syscall-template.S:81<br></font></div><div><font face="monospace, monospace">#1  0x000000000042e086 in pool_check_fd (cp=cp@entry=0x7f3d5efb43a0) at protocol/pool_process_query.c:696</font></div><div><font face="monospace, monospace">#2  0x000000000042e356 in pool_check_fd (cp=cp@entry=0x7f3d5efb43a0) at protocol/pool_process_query.c:728</font></div><div><font face="monospace, monospace">#3  0x000000000045fafc in pool_read (cp=0x7f3d5efb43a0, buf=buf@entry=0x7fffbc4830b5, len=len@entry=1) at utils/pool_stream.c:166</font></div><div><font face="monospace, monospace">#4  0x000000000043303b in read_kind_from_backend (frontend=frontend@entry=0x2314e98, backend=backend@entry=0x7f3d5efaf750, decided_kind=decided_kind@entry=0x7fffbc4834ba &quot;D&quot;)</font></div><div><font face="monospace, monospace">    at protocol/pool_process_query.c:3379</font></div><div><font face="monospace, monospace">#5  0x000000000043f402 in ProcessBackendResponse (frontend=frontend@entry=0x2314e98, backend=backend@entry=0x7f3d5efaf750, state=state@entry=0x7fffbc483524, </font></div><div><font face="monospace, monospace">    num_fields=num_fields@entry=0x7fffbc483522) at protocol/pool_proto_modules.c:2663</font></div><div><font face="monospace, monospace">#6  0x0000000000431ea7 in pool_process_query (frontend=0x2314e98, backend=0x7f3d5efaf750, reset_request=reset_request@entry=0) at protocol/pool_process_query.c:320</font></div><div><font face="monospace, monospace">#7  0x000000000042cd49 in do_child (fds=fds@entry=0x23134b0) at protocol/child.c:388</font></div><div><font face="monospace, monospace">#8  0x00000000004090a5 in fork_a_child (fds=0x23134b0, id=0) at main/pgpool_main.c:659</font></div><div><font face="monospace, monospace">#9  0x000000000040fb73 in PgpoolMain (discard_status=discard_status@entry=0 &#39;\000&#39;, clear_memcache_oidmaps=clear_memcache_oidmaps@entry=0 &#39;\000&#39;) at main/pgpool_main.c:378</font></div><div><font face="monospace, monospace">#10 0x0000000000407777 in main (argc=&lt;optimized out&gt;, argv=&lt;optimized out&gt;) at main/main.c:349</font></div><div><br></div></div><div><b>--SESSION CONTEXT--</b><br></div><div><div><font face="monospace, monospace">(gdb) print *session_context</font></div><div><font face="monospace, monospace">$4 = {process_context = 0x77c260 &lt;process_context_d&gt;, frontend = 0x2314e98, backend = 0x7f3d5efaf750, in_progress = 0 &#39;\000&#39;, doing_extended_query_message = 0 &#39;\000&#39;, </font></div><div><font face="monospace, monospace">  need_to_restore_where_to_send = 0 &#39;\000&#39;, where_to_send_save = &quot;\001&quot;, &#39;\000&#39; &lt;repeats 126 times&gt;, command_success = 1 &#39;\001&#39;, writing_transaction = 0 &#39;\000&#39;, </font></div><div><font face="monospace, monospace">  failed_transaction = 0 &#39;\000&#39;, skip_reading_from_backends = 0 &#39;\000&#39;, ignore_till_sync = 0 &#39;\000&#39;, transaction_isolation = POOL_UNKNOWN, query_context = 0x248d418, </font></div><div><font face="monospace, monospace">  memory_context = 0x22f2558, uncompleted_message = 0x231aeb8, message_list = {capacity = 64, size = 63, sent_messages = 0x2351f70}, load_balance_node_id = 0, </font></div><div><font face="monospace, monospace">  mismatch_ntuples = 0 &#39;\000&#39;, ntuples = {0, -1, 0 &lt;repeats 126 times&gt;}, reset_context = 0 &#39;\000&#39;, query_cache_array = 0x0, num_selects = 0, pending_messages = 0x231b020, </font></div><div><font face="monospace, monospace">  previous_message_exists = 0 &#39;\000&#39;, previous_message = {type = POOL_EXECUTE, contents = 0x24704f0 &quot;SS_13&quot;, contents_len = 5, query = &quot;COMMIT&quot;, &#39;\000&#39; &lt;repeats 1017 times&gt;, </font></div><div><font face="monospace, monospace">    statement = &quot;\000_46&quot;, &#39;\000&#39; &lt;repeats 123 times&gt;, portal = &#39;\000&#39; &lt;repeats 127 times&gt;, is_rows_returned = 0 &#39;\000&#39;, not_forward_to_frontend = 0 &#39;\000&#39;, node_ids = {0, -1}, </font></div><div><font face="monospace, monospace">    query_context = 0x242ff68}, major = 3, minor = 0}</font></div><div><font face="monospace, monospace"><br></font></div><div><b>--QEURY-TRACE--</b><font face="monospace, monospace"><br></font></div><div><span style="font-family:monospace,monospace">(gdb) print *session_context-&gt;query_context</span><br></div><div><font face="monospace, monospace">$5 = {original_query = 0x248e0e8 &quot;BEGIN&quot;, rewritten_query = 0x0, original_length = 6, rewritten_length = -1, parse_tree = 0x248e038, rewritten_parse_tree = 0x0, </font></div><div><font face="monospace, monospace">  where_to_send = &quot;\001&quot;, &#39;\000&#39; &lt;repeats 126 times&gt;, virtual_master_node_id = 0, query_state = {POOL_UNPARSED &lt;repeats 128 times&gt;}, is_cache_safe = 0 &#39;\000&#39;, temp_cache = 0x0, </font></div><div><font face="monospace, monospace">  is_multi_statement = 0 &#39;\000&#39;, dboid = 0, query_w_hex = 0x0, is_parse_error = 0 &#39;\000&#39;, num_original_params = -1, pg_terminate_backend_conn = 0x0, skip_cache_commit = 0 &#39;\000&#39;, </font></div><div><font face="monospace, monospace">  memory_context = 0x7f3d5efbff20}</font></div><div><br></div></div><div>Thanks<font face="monospace, monospace"><br></font></div><div>Best Regards</div><div>Muhammad Usama</div><div><br></div></div></div></div><br><div class="gmail_quote"><div dir="ltr">On Fri, Dec 7, 2018 at 3:49 AM Tatsuo Ishii &lt;<a href="mailto:ishii@sraoss.co.jp">ishii@sraoss.co.jp</a>&gt; wrote:<br></div><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi Usama,<br>
<br>
I need:<br>
<br>
- exact Pgpool-II version<br>
- pgpool.conf<br>
- gdb print command result of *pool_session_context when Pgpool-II hangs<br>
<br>
Also a full debug log will be helpful.<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" rel="noreferrer" target="_blank">http://www.sraoss.co.jp/index_en.php</a><br>
Japanese:<a href="http://www.sraoss.co.jp" rel="noreferrer" target="_blank">http://www.sraoss.co.jp</a><br>
<br>
&gt; Hi Ishii San<br>
&gt; <br>
&gt; Thanks for looking into this, As discussed over the call please find the<br>
&gt; attached pgpool log and stack trace for the stuck issue.<br>
&gt; I am currently not able to trim down the test case so sorry for throwing a<br>
&gt; huge log file.<br>
&gt; There is no special configuration on PostgreSQL server side and this issue<br>
&gt; only happens when the load balance node and the primary node are same<br>
&gt; and as you can see from the stack trace the stuck happens in the<br>
&gt; read_kind_from_backend() function and the reason for that is<br>
&gt; the function is trying to read response from the backend node 1(standby)<br>
&gt; while it has only sent the query to the backend node 0 (primary)<br>
&gt; <br>
&gt; --stack-trace--<br>
&gt; #0  0x00007f1775216c53 in __select_nocancel () at<br>
&gt; ../sysdeps/unix/syscall-template.S:81<br>
&gt; #1  0x000000000042def6 in pool_check_fd (cp=cp@entry=0x7f1776fb2328) at<br>
&gt; protocol/pool_process_query.c:696<br>
&gt; #2  0x000000000042e1c6 in pool_check_fd (cp=cp@entry=0x7f1776fb2328) at<br>
&gt; protocol/pool_process_query.c:728<br>
&gt; #3  0x000000000045f92c in pool_read (cp=0x7f1776fb2328,<br>
&gt; buf=buf@entry=0x7ffebb5f2345,<br>
&gt; len=len@entry=1) at utils/pool_stream.c:166<br>
&gt; #4  0x0000000000432eab in read_kind_from_backend<br>
&gt; (frontend=frontend@entry=0x2292e88,<br>
&gt; backend=backend@entry=0x7f1776fad6d8,<br>
&gt; decided_kind=decided_kind@entry=0x7ffebb5f274a<br>
&gt; &quot;D&quot;)<br>
&gt;     at protocol/pool_process_query.c:3379<br>
&gt; #5  0x000000000043f232 in ProcessBackendResponse<br>
&gt; (frontend=frontend@entry=0x2292e88,<br>
&gt; backend=backend@entry=0x7f1776fad6d8, state=state@entry=0x7ffebb5f27b4,<br>
&gt;     num_fields=num_fields@entry=0x7ffebb5f27b2) at<br>
&gt; protocol/pool_proto_modules.c:2653<br>
&gt; #6  0x0000000000431d17 in pool_process_query (frontend=0x2292e88,<br>
&gt; backend=0x7f1776fad6d8, reset_request=reset_request@entry=0) at<br>
&gt; protocol/pool_process_query.c:320<br>
&gt; #7  0x000000000042cbb9 in do_child (fds=fds@entry=0x2291370) at<br>
&gt; protocol/child.c:387<br>
&gt; #8  0x00000000004090a5 in fork_a_child (fds=0x2291370, id=2) at<br>
&gt; main/pgpool_main.c:659<br>
&gt; #9  0x000000000040fb73 in PgpoolMain (discard_status=discard_status@entry=0<br>
&gt; &#39;\000&#39;, clear_memcache_oidmaps=clear_memcache_oidmaps@entry=0 &#39;\000&#39;) at<br>
&gt; main/pgpool_main.c:378<br>
&gt; #10 0x0000000000407777 in main (argc=&lt;optimized out&gt;, argv=&lt;optimized out&gt;)<br>
&gt; at main/main.c:361<br>
&gt; <br>
&gt; Thanks<br>
&gt; Best Regards<br>
&gt; Muhammad Usama<br>
&gt; <br>
&gt; <br>
&gt; <br>
&gt; On Thu, Dec 6, 2018 at 3:52 AM Tatsuo Ishii &lt;<a href="mailto:ishii@sraoss.co.jp" target="_blank">ishii@sraoss.co.jp</a>&gt; wrote:<br>
&gt; <br>
&gt;&gt; &gt; Hi Ishii San<br>
&gt;&gt; &gt;<br>
&gt;&gt; &gt; I was investigating the issue faced by one of Pgpool-II user who reported<br>
&gt;&gt; &gt; that after executing a certain transaction (large amount of data DELETE /<br>
&gt;&gt; &gt; INSERT / UPDATE, COMMIT), the next execution of the BEGIN statement<br>
&gt;&gt; &gt; hangs(using the extended query protocol).<br>
&gt;&gt; &gt;<br>
&gt;&gt; &gt; I think the problem is in pool_is_node_to_be_sent_in_current_query()<br>
&gt;&gt; &gt; function. The issue is in streaming replication mode, when<br>
&gt;&gt; &gt; pool_is_query_in_progress is not set, the function always returns true.<br>
&gt;&gt; Now<br>
&gt;&gt; &gt; consider that we have two backend servers 1 primary and one standby. And<br>
&gt;&gt; &gt; for a particular session the primary node gets selected as a load balance<br>
&gt;&gt; &gt; node. So effectively that session should only be sending queries and<br>
&gt;&gt; &gt; reading responses from primary server alone. But with the current<br>
&gt;&gt; &gt; implementation of pool_is_node_to_be_sent_in_current_query() the<br>
&gt;&gt; &gt; VALID_BACKEND macro will return true for standby node as well when the<br>
&gt;&gt; &gt; query in progress flag is not set(which is wrong when standby node is not<br>
&gt;&gt; &gt; selected for load balancing). and if this happens in let say<br>
&gt;&gt; &gt; read_kind_from_backend() function we will get a stuck, since the<br>
&gt;&gt; &gt; read_kind_from_backend() will be trying to read the response from standby<br>
&gt;&gt; &gt; node while we have never sent any query to that node.<br>
&gt;&gt; &gt;<br>
&gt;&gt; &gt;<br>
&gt;&gt; &gt; Can you please take a look at the attached patch, I am not sure if it<br>
&gt;&gt; will<br>
&gt;&gt; &gt; have some side effects or not.<br>
&gt;&gt;<br>
&gt;&gt; Unfortunately the patch would not help and probably would break many<br>
&gt;&gt; cases which are working today.<br>
&gt;&gt;<br>
&gt;&gt; For the scenario you mentioned is already handled by<br>
&gt;&gt; pool_pending_message_* functions defined in<br>
&gt;&gt; context/query_context.c. When a message, for example parse, is sent<br>
&gt;&gt; from frontend and forwarded to backends, the info is recorded in an<br>
&gt;&gt; FIFO queue by pool_pending_message_add() along with info which of<br>
&gt;&gt; backend the message is forwarded to. When the parse message will be<br>
&gt;&gt; replied back with &quot;parse complete message&quot; from the backend,<br>
&gt;&gt; read_kind_message_from_backend() can know from which of backend it<br>
&gt;&gt; should read a message by looking at the head of the queue.  Once the<br>
&gt;&gt; message is retrieved (in this example parse complete message), an<br>
&gt;&gt; entry in the queue (in this example parse message) is pulled out and<br>
&gt;&gt; removed.<br>
&gt;&gt;<br>
&gt;&gt; This mechanism usually works well unless backend sends unpredicted<br>
&gt;&gt; message. Recently one of such a case was reported:<br>
&gt;&gt; <a href="https://www.pgpool.net/mantisbt/view.php?id=448" rel="noreferrer" target="_blank">https://www.pgpool.net/mantisbt/view.php?id=448</a><br>
&gt;&gt;<br>
&gt;&gt; In the report PostgreSQL sends an error message caused by<br>
&gt;&gt; idle_in_transaction_timeout setting which Pgpool-II does not expect.<br>
&gt;&gt;<br>
&gt;&gt; Does the user has any uncommon setting in postgresql.conf?<br>
&gt;&gt;<br>
&gt;&gt; Best regards,<br>
&gt;&gt; --<br>
&gt;&gt; Tatsuo Ishii<br>
&gt;&gt; SRA OSS, Inc. Japan<br>
&gt;&gt; English: <a href="http://www.sraoss.co.jp/index_en.php" rel="noreferrer" target="_blank">http://www.sraoss.co.jp/index_en.php</a><br>
&gt;&gt; Japanese:<a href="http://www.sraoss.co.jp" rel="noreferrer" target="_blank">http://www.sraoss.co.jp</a><br>
&gt;&gt;<br>
</blockquote></div>