[pgpool-general-jp: 1540] Re: regression test 070のテストが完了しない事象について

2018年 5月 30日 (水) 11:54:39 JST

石井です。

ログから判断すると、以下のような状況になっていると思われます。

1) 理由は不明だが、プライマリとスタンバイの間のレプリケーション遅延が大
   きくなっており、ロードバランスができない状態になった。

2018-05-28 11:51:49: pid 32250: DEBUG:  could not load balance because of too much replication delay

2) この状態で、以下のSELECTをExecuteした。Executeは、1)の理由でプライ
マリに送られた（これ自体は正しい）。

2018-05-28 11:51:49: pid 32250: DEBUG:  pool_pending_message_add: message type:Descripbe message len:2 query:SELECT abalance FROM pgbench_accounts WHERE aid = $1; statement: portal: node_ids[0]:0 node_ids[1]:-1

3) このSELECTに対してクエリキャッシュが存在したので、キャッシュデータ
をクライアントに返そうとした（これも正しい）

2018-05-28 11:51:49: pid 32250: DEBUG:  fetching from cache storage

4) その処理の中で、バックエンド1に対して、ペンディングデータがあれば送
   信を要求するためにフラッシュメッセージを送信した（正しくない）

2018-05-28 11:51:49: pid 32250: DEBUG:  pool_write: to backend: 1 kind:H

5) しかし、実際にはノード1にExecuteは送られていないため、4)の結果の受信待ちでハングした。

というわけで、a) ロードバランスノードが1、b) レプリケーション遅延が発
生、c) クエリキャッシュがヒットした、という条件が揃った時にのみハング
が起きるようです。

クエリキャッシュ処理で、レプリケーション遅延が起きることに対する考慮が
足りなかったのが問題の原因です。修正に関しては、これから考えますが、た
だいま出張中のため、少し時間をいただくことになると思います。
--
Tatsuo Ishii
SRA OSS, Inc. Japan
English: http://www.sraoss.co.jp/index_en.php
Japanese:http://www.sraoss.co.jp

> 大野です。
> お世話になっております。
> 
>> いえ、
>> > tests/070.memory_leak_extended_memqcache/testdir/log/pgpool.log
>> このログです。ただ、見せていただきたいのは、セッションに対応するプロセ
>> スのログの部分です。
>> 以前のメールではそこが見られませんでしたので。
> お教えいただきありがとうございます。
>> 
>> pgpool.log全体を見せていただければ、セッションに対応するプロセスのログ
>> の部分も含まれます。
> 現象発生時のpgpool.logを添付致します。ご確認をお願い致します。
> 以下の★印のプロセスがセッションに対応するプロセスのログに該当すると考えています。
> # このプロセスをkillすることでテストが動き出し、終了する
> ossuser ＠ linux-mtko:~> ps -ef | grep pgpool
> ossuser       4817 32764  0 13:00 pts/1    00:00:00 grep --color=auto pgpool
> ossuser      31607 24294  0 11:49 pts/0    00:00:00 sh rt_pgpool2.sh 070.memory_leak_extended_memqcache
> ossuser      32222     1  0 11:51 pts/0    00:00:00 /opt/postgres/bin/postgres -D /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_memqcache/testdir/data0
> ossuser      32236     1  0 11:51 pts/0    00:00:00 /opt/postgres/bin/postgres -D /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_memqcache/testdir/data1
> ossuser      32246     1  0 11:51 pts/0    00:00:00 /opt/postgres/bin/pgpool -d -D -n -f /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_memqcache/testdir/etc/pgpool.conf -F /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_memqcache/testdir/etc/pcp.conf -a /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_memqcache/testdir/etc/pool_hba.conf
> ★ossuser      32250 32246  0 11:51 pts/0    00:00:04 pgpool: ossuser test  idle
> ossuser      32252 32246  0 11:51 pts/0    00:00:00 pgpool: PCP: wait for connection request
> ossuser      32253 32246  0 11:51 pts/0    00:00:00 pgpool: worker process
> ossuser      32254 32246  0 11:51 pts/0    00:00:00 pgpool: health check process(0)
> ossuser      32255 32246  0 11:51 pts/0    00:00:00 pgpool: health check process(1)
> 
> 以上です。よろしくお願いします。
>> -----Original Message-----
>> From: Tatsuo Ishii [mailto:ishii ＠ sraoss.co.jp]
>> Sent: Saturday, May 26, 2018 10:10 AM
>> To: Ono, Kyohei/大野 恭平
>> Cc: pgpool-general-jp ＠ sraoss.jp
>> Subject: Re: [pgpool-general-jp: 1534] regression test 070のテストが完
>> 了しない事象について
>> 
>> > 大野です。
>> > お世話になっております。
>> >
>> >> 最新のPgpool-II 3.7.3にアップグレードしても再現するでしょうか？
>> > 今回は諸事情により対象バージョンは3.7.1固定としています。
>> > そのため最新バージョンでの確認が直ぐにはできない状況です。申し訳ござ
>> いません。
>> >
>> >> また、停止している間の、セッションに対応するPgpool-IIのプロセスのデ
>> バ
>> >> ッ
>> >> グログがあれば何か分かるかもしれません。
>> > tests/070.memory_leak_extended_memqcache/testdir/log/pgpool.logとは
>> > 別のログという認識でよろしいでしょうか。
>> > その場合、不勉強で申し訳ないのですがログの採取方法がわかりません。
>> > お手数ですが、採取方法を教えて頂けないでしょうか。
>> 
>> いえ、
>> > tests/070.memory_leak_extended_memqcache/testdir/log/pgpool.log
>> このログです。ただ、見せていただきたいのは、セッションに対応するプロセ
>> スのログの部分です。
>> 以前のメールではそこが見られませんでしたので。
>> 
>> pgpool.log全体を見せていただければ、セッションに対応するプロセスのログ
>> の部分も含まれます。
>> 
>> >> これはちょっと不思議ですね。"-T 30"が指定されているので、Pgpool-II
>> 側で
>> >> 何があろうと、pgbenchは30秒たったら終了するはずですが...
>> > 070のテストはnum_init_childrenが1に設定されるようなので
>> > 何かがpgpool-IIに対して接続しており、
>> > pgbenchが実行待ちの状態になっているのでは、と予想しています。
>> 
>> もしくは、pgbench -T 30の前に実行していたpgbench -T 1自体は完了してい
>> るが、対応するpgpoolの子プロセスが終了していない（ハングしている？）た
>> めに、pgbench -T 30が接続待ちになっている可能性があります。
>> --
>> Tatsuo Ishii
>> SRA OSS, Inc. Japan
>> English: http://www.sraoss.co.jp/index_en.php
>> Japanese:http://www.sraoss.co.jp
>