[pgpool-general-jp: 1541] Re: regression test 070のテストが完了しない事象について
Ono, Kyohei
ono.kyohei ＠ jp.fujitsu.com
2018年 5月 30日 (水) 13:13:08 JST
大野です。
お世話になっております。
> クエリキャッシュ処理で、レプリケーション遅延が起きることに対する考慮が
> 足りなかったのが問題の原因です。修正に関しては、これから考えますが、た
> だいま出張中のため、少し時間をいただくことになると思います。
ご確認ありがとうございます。
原因について承知致しました。
修正についても目処が付きましたら教えて頂けると幸いです。
以上です。よろしくお願いいます。
> -----Original Message-----
> From: Tatsuo Ishii [mailto:ishii ＠ sraoss.co.jp]
> Sent: Wednesday, May 30, 2018 11:55 AM
> To: Ono, Kyohei/大野 恭平
> Cc: pgpool-general-jp ＠ sraoss.jp
> Subject: Re: [pgpool-general-jp: 1534] regression test 070のテストが完
> 了しない事象について
>
> 石井です。
>
> ログから判断すると、以下のような状況になっていると思われます。
>
> 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_me
> mqcache/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_me
> mqcache/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_me
> mqcache/testdir/etc/pgpool.conf -F
> /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_me
> mqcache/testdir/etc/pcp.conf -a
> /tmp/OSS/pgpool2/src/test/regression/tests/070.memory_leak_extended_me
> mqcache/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
> >
pgpool-general-jp メーリングリストの案内