[pgpool-general-jp: 56] Re: pgpoolの縮退運転について
ktj ＠ mrj.biglobe.ne.jp
ktj ＠ mrj.biglobe.ne.jp
2006年 12月 14日 (木) 01:32:00 JST
浅羽さん
山崎と申します。
返答が遅くなり申し訳ございません。
> load_balance_mode = true の場合は考えられますが、通常はそのような挙動
> にはなりません。node2 で実行された SQL が pgpool のログには残っていま
> せんが、直接実行していないでしょうか？
すみません、あまりに同じようなSQLが多かったので見過ごしていましたが
よく見比べてみますと、node2 のみに出力されている、と言っていた
> Dec 5 16:21:57 postgres[19030]: [69709-1] LOG: statement: SELECT troubleId FROM troubleinfo
このSQLが pgpoolのログでは 16:21:49、node1のpostgresqlのログでも 16:21:49 に
記録されていました。
ということで、数十秒さかのぼってログを整理してみたところ、
以下のようになっておりました。
pgpool node1: postgresql node2: postgresql
time PID statement pid statement pid statement
16:21:34 24658 SELECT(1) 25579 SELECT(1) 19030 SELECT(1)
16:21:34 24658 SELECT(2) 25579 SELECT(2) 19030 SELECT(2)
16:21:34 24658 SELECT(3) 25579 SELECT(3) 19030 SELECT(3)
16:21:34 24658 SELECT(4) 25579 SELECT(4) 19030 SELECT(4)
16:21:34 24658 SELECT(5) 25579 SELECT(5) 19030 SELECT(5)
16:21:34 24658 SELECT(6) 25579 SELECT(6) 19030 SELECT(6)
16:21:34 24658 SELECT(7) 25579 SELECT(7) - ログ記録無し
16:21:35 24714 SELECT 25354 SELECT 18864 SELECT
16:21:35 24714 UPDATE 25354 UPDATE 18864 UPDATE
16:21:40 24714 SELECT 25354 SELECT 18864 SELECT
16:21:40 24714 UPDATE 25354 UPDATE 18864 UPDATE
16:21:40 24714 SELECT 25354 SELECT 18864 SELECT
16:21:40 24714 SELECT 25354 SELECT 18864 SELECT
16:21:42 - - - - 19030 SELECT(7) ←16:21:34のSQL
16:21:46 24714 SELECT 25354 SELECT 18864 SELECT
16:21:46 24714 UPDATE 25354 UPDATE 18864 UPDATE
16:21:46 24714 SELECT 25354 SELECT 18864 SELECT
16:21:49 24658 SELECT(8) 25579 SELECT(8) - ログ記録無し
16:21:53 24714 SELECT 25354 SELECT 18864 SELECT
16:21:53 24714 UPDATE 25354 UPDATE 18864 UPDATE
16:21:53 24715 SELECT 25432 SELECT 18946 SELECT
16:21:53 24715 begin; 25432 begin; 18946 begin;
16:21:53 24714 SELECT 25354 SELECT 18864 SELECT
16:21:53 21034 SELECT 22479 SELECT 11717 SELECT
16:21:53 24714 SELECT 25354 SELECT 18864 SELECT
16:21:53 24715 SELECT 25432 SELECT 18946 SELECT
16:21:53 24715 UPDATE 25432 UPDATE 18946 UPDATE
16:21:53 24715 INSERT(1) 25432 INSERT(1) 18946 INSERT(1)
16:21:53 24715 INSERT(2) 25432 INSERT(2) 18946 INSERT(2)
16:21:53 24715 INSERT(3) 25432 INSERT(3) 18946 INSERT(3)
16:21:53 24715 INSERT(4) 25432 INSERT(4) 18946 INSERT(4)
16:21:53 24715 DELETE 25432 DELETE 18946 DELETE
16:21:53 24715 INSERT(5) 25432 INSERT(5) 18946 INSERT(5)
16:21:53 24715 INSERT(6) 25432 INSERT(6) 18946 INSERT(6)
16:21:53 24715 INSERT(7) 25432 INSERT(7) 18946 INSERT(7)
16:21:53 24715 commit;begin; 25432 commit; begin; 18946 commit; begin;
16:21:53 24715 rollback;begin;25432 rollback; begin;18946 rollback; begin;
16:21:53 24715 end 25432 end 18946 end
16:21:57 - - - - 19030 SELECT(8) ←16:21:49のSQL
16:22:04 24658 pool_process_query: kind does not match between backends master(C) secondary(D)
16:22:04 24658 notice_backend_error: master: 1 fail over request from pid 24658
16:22:04 24586 starting degeneration. shutdown master host tmm1(5431)
16:22:04 24586 degeneration done. shutdown master host tmm1(5431)
16:22:04 - - - - 19030 unexpected EOF on client connection
16:22:04 - - 25432 unexpected EOF on client connection
16:22:04 - - - - 18946 unexpected EOF on client connection
16:22:04 - - 25354 unexpected EOF on client connection
16:22:04 - - - - 18864 unexpected EOF on client connection
16:22:04 - - 22479 unexpected EOF on client connection
16:22:04 - - - - 11717 unexpected EOF on client connection
ということで、mismatchが発生した経緯としては、
(1) 16:21:34 から PID: 24658 のpoolにてnode1(master)とnode2(secondary)の
Queryの結果が返ってくるのが８秒ほどずれるようになった。
(2) 16:21:49 に PID:24658 から発行されたSELECTがnode1からはすぐに
返ってきたので結果を保持。node2からの結果を待つ。
(3) 16:21:53 に PID: 24715 でテーブルが更新される。
(4) 16:21:57 にnode2 で実行された 19030 の SELECT(8)では
更新後のテーブルの結果を 24658 に返したところ、mismatch 発生。
というところだと推測しております。
この場合、pgpool側の設定は変えないで対処しようとするのであれば、
アプリケーション側でテーブルロックをかけないといけない、という
ことになりますでしょうか？
> PID 24658 のログをもう少し前のあたりをいただけると少し現象がわかるかも
> しれません。ログは残っていますでしょうか？
24658 についてはだいぶ遡らないとログがなかったので 16:21:34〜 からの部分を
抽出いたしました。
Dec 5 16:21:34 2006-12-05 16:21:34 LOG: pid 24658: statement: SELECT Code, ascnt, idcnt FROM table5
Dec 5 16:21:34 LEFT OUTER JOIN ( SELECT Code, COUNT(Id) AS idcnt FROM table1 WHERE Code = '1876622124')
Dec 5 16:21:34 LEFT OUTER JOIN ( SELECT Code, opcode, COUNT(Id) AS idcnt FROM table2 WHERE assigncode = 'CLOSED')
Dec 5 16:21:34 2006-12-05 16:21:34 LOG: pid 24658: statement: SELECT displayname, lastupdate FROM displaytable1 WHERE Code = '187622105'
Dec 5 16:21:34 2006-12-05 16:21:34 LOG: pid 24658: statement: SELECT id, name FROM table10 ORDER BY displayorder
Dec 5 16:21:34 2006-12-05 16:21:34 LOG: pid 24658: statement: SELECT id, name, url, width, height, type FROM table3 ORDER BY displayorder
Dec 5 16:21:34 2006-12-05 16:21:34 LOG: pid 24658: statement: SELECT Code, id, name, inTime, OutTime, comment FROM operatorgroup WHERE Code = '188723124'
Dec 5 16:21:34 2006-12-05 16:21:34 LOG: pid 24658: statement: SELECT count(*) FROM table1
Dec 5 16:21:34 WHERE table1.Code = '176262341' AND table1.inTime >= '2006-12-05 00:00'
Dec 5 16:21:34 node1 pgpool:
Dec 5 16:21:49 2006-12-05 16:21:49 LOG: pid 24658: statement: SELECT Id FROM table1
Dec 5 16:21:49 LEFT JOIN table2 ON table1.Code = table2.Code
Dec 5 16:21:49 WHERE table1.Code = '195542311' ORDER BY table2.table2dcode ASC, table1.line ASC
Dec 5 16:21:49 node1 pgpool:
Dec 5 16:22:04 ERROR: pid 24658: pool_process_query: kind does not match between backends master(C) secondary(D)
Dec 5 16:22:04 LOG: pid 24658: notice_backend_error: master: 1 fail over request from pid 24658
Dec 5 16:22:04 LOG: pid 24586: starting degeneration. shutdown master host node1(5431)
Dec 5 16:22:04 LOG: pid 5724: statement: set datestyle to 'ISO'; select version(), case when pg_encoding_to_char(1) = 'SQL_ASCII' then 'UNKNOWN' else getdatabaseencoding() end;
Dec 5 16:22:04 LOG: pid 5724: statement: set client_encoding = 'UNICODE'
Dec 5 16:22:04 LOG: pid 5724: statement: select count(*) from table4
Dec 5 16:22:04 LOG: pid 5724: statement: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
Dec 5 16:22:04 LOG: pid 5724: statement: SELECT code FROM table3 WHERE sessionid = '687FE87F4ECDC1B9F6A020FA5CE1B8F8' ORDER BY lastlogindate DESC
Dec 5 16:22:04 LOG: pid 24586: degeneration done. shutdown master host node1(5431)
Dec 5 16:22:04 LOG: pid 5724: statement: select count(*) from table2
Dec 5 16:22:04 LOG: pid 5724: statement: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
よろしくおねがいします。
pgpool-general-jp メーリングリストの案内