[pgpool-general-jp: 45] pgpoolの縮退運転について

ktj @ mrj.biglobe.ne.jp ktj @ mrj.biglobe.ne.jp
2006年 12月 6日 (水) 09:39:20 JST


山崎と申します。

pgpool-I ですが、縮退運転が毎日1回ほど
発生してしまっており、困っております。

構成は以下の通りです。

・RHEL 4 Update 4
・pg74.216.jdbc3.jar
・pgpool 3.1.1
・postgreSQL 7.4.13

node1:   Tomcat(5.0.28) -> pgpool -> PostgreSQL
                               |
node2:                         `---> PostgreSQL

物理的に異なるnode1、node2でReplicationを組んでおります。
pgpool および postgresql で log_statement = true で
SQLを採取したところ、ログからは以下のような現象が発生している
ように読み取れました。

 16:21:57 の検索クエリがnode2のログだけに残っている
  → pgpool ⇒ node2にしかSQLが送られなかった?

  #  このSQLは内容からするとTomcat上のWebアプリが生成したもので
  #  誰かがlocalからpsqlなどでport=5433に直接実行した、という可能性は皆無です。

そもそも node1: master、node2: secondary で replication_strict = true の
運用をしているのに、まず secondary にSELECT文が送られるという可能性が
有りうるのでしょうか?
あるいは master側に先にSELECT文が送られたにも関わらず、実行されなかった為、
secondaryからの結果だけが戻ってきた結果、mismatch → 縮退 という事でしょうか?

DEBUGは取得できておりませんので情報不足は否めないのですが、
ログの量が膨大さと実行速度の面からDEBUG取得は困難な状況です。

原因として考えられる要素が何かあればご教授頂ければと思います。

宜しくお願いします。

#  以下、SQL文の中身はテーブル名など、一部ダミーに差し替えさせて頂いております。


---- pgpool.log

Dec  5 16:21:53  LOG:   pid 24715: statement: INSERT INTO table1 ( ... ) VALUES ( ... )
Dec  5 16:21:53  LOG:   pid 24715: statement: commit;begin;
Dec  5 16:21:53  LOG:   pid 24715: statement: rollback; begin;
Dec  5 16:21:53  LOG:   pid 24715: statement: end
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

---- node1: postgres.log

Dec  5 16:21:53 postgres[25432]: [27087-1] LOG:  statement: INSERT INTO table1 ( ... ) VALUES ( ... )
Dec  5 16:21:53 postgres[25432]: [27088-1] LOG:  statement: commit;begin;
Dec  5 16:21:53 postgres[25432]: [27089-1] LOG:  statement: rollback; begin;
Dec  5 16:21:53 postgres[25432]: [27090-1] LOG:  statement: end
Dec  5 16:22:04 postgres[5531]: [25-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[5530]: [37-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[5529]: [109-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[4931]: [13-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[2182]: [29-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[26428]: [6605-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[22460]: [18-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25099]: [228-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25581]: [3287-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[1462]: [6729-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[1460]: [43130-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[1459]: [41323-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25580]: [6486-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25515]: [7959-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25437]: [9775-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25432]: [27091-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25354]: [27871-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25033]: [228-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[24921]: [161-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[22479]: [32078-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[25355]: [52063-1] LOG:  unexpected EOF on client connection

---- node2: postgres.log

Dec  5 16:21:53 postgres[18946]: [27087-1] LOG:  statement: INSERT INTO table1 ( ... ) VALUES ( ... )
Dec  5 16:21:53 postgres[18946]: [27088-1] LOG:  statement: commit;begin;
Dec  5 16:21:53 postgres[18946]: [27089-1] LOG:  statement: rollback; begin;
Dec  5 16:21:53 postgres[18946]: [27090-1] LOG:  statement: end
Dec  5 16:21:57 postgres[19030]: [69709-1] LOG:  statement: SELECT troubleId FROM troubleinfo 
Dec  5 16:21:57 postgres[19030]: [69709-2] LOG:  statement: LEFT JOIN status ON troubleinfo.statuscode = status.statuscode
Dec  5 16:21:57 postgres[19030]: [69709-3] LOG:  statement: WHERE troubleinfo.matterCode = \'0000003005\'
Dec  5 16:21:57 postgres[19030]: [69709-4]        ORDER BY status.statusDisplayCode ASC, troubleinfo.deadLine ASC
Dec  5 16:22:04 postgres[19030]: [69710-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[15345]: [6605-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18745]: [228-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[23567]: [13-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[24170]: [37-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[24169]: [109-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[22599]: [29-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[12444]: [18-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[24171]: [25-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[19091]: [3287-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[21902]: [6729-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[19090]: [6486-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[19029]: [7959-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18947]: [9775-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18678]: [161-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[21900]: [43130-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[21899]: [41323-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18946]: [27091-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18864]: [27871-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18681]: [228-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[11717]: [32078-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[18865]: [52063-1] LOG:  unexpected EOF on client connection
Dec  5 16:22:04 postgres[24274]: [1-1] LOG:  statement: set datestyle to \'ISO\'; select version(), case when pg_encoding_to_char(1) = \'SQL_ASCII\' then \'UNKNOWN\' else
Dec  5 16:22:04 postgres[24274]: [1-2]  getdatabaseencoding() end;
Dec  5 16:22:04 postgres[24274]: [2-1] LOG:  statement: set client_encoding = \'UNICODE\'
Dec  5 16:22:04 postgres[24274]: [3-1] LOG:  statement: select count(*) from table4
Dec  5 16:22:04 postgres[24274]: [4-1] LOG:  statement: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
Dec  5 16:22:04 postgres[24274]: [5-1] LOG:  statement: SELECT code FROM table3 WHERE sessionid = \'687FE87F4ECDC1B9F6A020FA5CE1B8F8\' ORDER BY lastlogindate
Dec  5 16:22:04 postgres[24274]: [5-2]  DESC
Dec  5 16:22:04 postgres[24274]: [6-1] LOG:  statement: select count(*) from table4
Dec  5 16:22:04 postgres[24274]: [7-1] LOG:  statement: SET SESSION CHARACTERISTICS AS TRANSACTION ISOLATION LEVEL READ COMMITTED
Dec  5 16:22:04 postgres[24274]: [8-1] LOG:  statement: begin;

---- /etc/pgpool.conf

listen_addresses = 'localhost'
port = 5432
socket_dir = '/tmp'
backend_host_name = 'node1'
backend_port = 5431
backend_socket_dir = '/tmp'
secondary_backend_host_name = 'node2'
secondary_backend_port = 5433
num_init_children = 128
max_pool = 1
child_life_time = 300
connection_life_time = 0
child_max_connections = 0
logdir = '/tmp'
replication_mode = true
replication_strict = true
replication_timeout = 5000
load_balance_mode = false
weight_master = 0.5
weight_secondary = 0.5
replication_stop_on_mismatch = true
reset_query_list = 'ABORT; RESET ALL; SET SESSION AUTHORIZATION DEFAULT'
print_timestamp = true
master_slave_mode = false
connection_cache = true
health_check_timeout = 20
health_check_period = 300
health_check_user = 'postgres'
insert_lock = false
ignore_leading_white_space = false
log_statement = true

---- node1: /var/lib/pgsql/data/postgresql.conf

tcpip_socket = true
max_connections = 128
port = 5431
shared_buffers = 49152
syslog = 2
syslog_facility = 'LOCAL0'
log_statement = true
stats_start_collector = true
stats_command_string = true
stats_block_level = true
stats_row_level = true
stats_reset_on_server_start = true
lc_messages = 'C'
lc_monetary = 'C'
lc_numeric = 'C'
lc_time = 'C'

---- node2: /var/lib/pgsql/data/postgresql.conf

tcpip_socket = true
max_connections = 128
port = 5433
shared_buffers = 49152
syslog = 2
syslog_facility = 'LOCAL0'
log_statement = true
stats_start_collector = true
stats_command_string = true
stats_block_level = true
stats_row_level = true
stats_reset_on_server_start = true
lc_messages = 'C'
lc_monetary = 'C'
lc_numeric = 'C'
lc_time = 'C'




pgpool-general-jp メーリングリストの案内