[pgsql-jp: 36546] JDBC+pgpool利用時の不具合(!?)について
YAMADA Toshio
toshi ＠ mx1.freemail.ne.jp
2005年 12月 14日 (水) 01:44:21 JST
初めまして、山田と申します。
当方でのシステム開発におきまして、下記のような環境・構成で、
デッドロックのような現象が発生しておりまして、回避方法等を
お伺いしたく、ご報告をさせていただきたいと思います。
＃長文・乱筆で失礼いたします。
・PostgreSQL 8.1.0
・pgpool v2.6.4
・JDBC：postgresql-8.1-404.jdbc3.jar
・OS：Redhat Linux ES 3 (全台同じ)
・下図のような冗長化構成を取っており、pgpoolはapp1, app2上で稼動。
・app1,app2上のJavaアプリケーションが、ローカルホストのpgpool
経由でDB(db1, db2)へデータを投入する。
+----------+ +----------+
| [app1] | | [app2] |
| pgpool | | pgpool |
+----------+ +----------+
| × |
+----------+ +----------+
| [db1] | | [db2] |
| master | | second |
+----------+ +----------+
テスト実行で用意したDB操作のJavaアプリケーションは、
(1)LOCK ：テーブルロック
(2)SELECT：IDカラム(自前のint)から最大値取得
(3)INSERT：新規行追加
(4)COMMIT
という、serialキーを自前で作成したようなよくある(?)ものです。
この処理を10000件繰り返しています。
このJavaアプリケーションを、app1, app2で同時に実行すると、発生の
タイミングはばらばらですが、(デッドロック発生のように)処理が
止まってしまい、pgpoolが縮退運転に入ります。
しかし、PerlでDBI/DBDにて同じ処理をするアプリケーションを作成し、
同じ方法で実行しても、この現象は発生せず正常に処理されます。
＃どちらも数回試しています。
db1, db2のPostgreSQLログにて処理しているSQLを調べてみると、
・JDBC経由のSQLは、すべてPREPAREで発行される。
・DBI経由のSQLは、(バインド値がなければ)直接発行される。
という様子でした。
なので、JDBCもPREPAREを使わないように発行できればいいのかな？と
思ったのですが、v8.1のJDBCではその方法が分かりませんでした。
＃PREPARE, BIND, EXECUTE(の3ステップ?)で実行されるのがまずいのか
＃なぁーという素人考えですが…。
とりあえず、JDBCを、そもそもPREPAREの概念がなかったv7.4 のものに
したところ、このJavaアプリケーションでも停止することなく正しく
実行できることが分かりました。
また、pgpoolを経由せず、単純に1台のPostgreSQLに2セッションで
同時投入しても正しく実行できました(…当たり前?)。
下記に関係する設定、ログを追記いたします。
なにかお気づきの点や回避できる設定方法をご存知の方がいらっしゃい
ましたら、ご教示いただければ助かります。
では、よろしくお願いいたします。
■(1)pgpool.conf (app1, app2共通)
----------------------------------------------------------------
listen_addresses = 'localhost'
port = 5432
socket_dir = '/tmp'
backend_host_name = 'db1'
backend_port = 5432
backend_socket_dir = '/tmp'
secondary_backend_host_name = 'db2'
secondary_backend_port = 5432
num_init_children = 21
max_pool = 3
child_life_time = 30
connection_life_time = 30
logdir = '/var/run'
replication_mode = true
replication_strict = true
replication_timeout = 50000
load_balance_mode = true
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 = false
health_check_timeout = 15
health_check_period = 30
health_check_user = 'postgres'
insert_lock = false
----------------------------------------------------------------
■(2)pgpoolログ(エラー発生時 app1)
----------------------------------------------------------------
2005-12-13 11:58:03 ERROR: pid 13284: pool_check_fd: data is not ready tp->tv_sec 50 tp->tp_usec 50000000
2005-12-13 11:58:03 ERROR: pid 13284: pool_process_query: secondary data is not ready at synchronous point. abort this session
2005-12-13 11:58:03 ERROR: pid 13284: pool_process_query: kind does not match between backends master(2) secondary(^@)
2005-12-13 11:58:03 LOG: pid 13284: notice_backend_error: master: 1 fail over request from pid 13284
2005-12-13 11:58:03 LOG: pid 8895: starting degeneration. shutdown master host db1(5432)
2005-12-13 11:58:03 LOG: pid 8895: degeneration done. shutdown master host db1(5432)
----------------------------------------------------------------
■(3)db1のPostgreSQLログ(11:57:13後 50秒(pgpool.conf設定)処理が停止)
----------------------------------------------------------------
：
2005-12-13 11:57:13 JST[26337 LOG: statement: EXECUTE <unnamed> [PREPARE: BEGIN]
2005-12-13 11:57:13 JST[26337 LOG: statement: PREPARE <unnamed> AS /*STRICT*/ LOCK t1
2005-12-13 11:57:13 JST[26337 LOG: statement: <BIND>
2005-12-13 11:57:13 JST[26337 LOG: statement: EXECUTE <unnamed> [PREPARE: /*STRICT*/ LOCK t1]
2005-12-13 11:58:03 JST[26337 LOG: unexpected EOF on client connection
2005-12-13 11:58:03 JST[26338 LOG: statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-13 11:58:03 JST[26338 LOG: statement: <BIND>
2005-12-13 11:58:03 JST[26338 LOG: statement: EXECUTE <unnamed> [PREPARE: SELECT MAX(id) AS max_id FROM t1]
2005-12-13 11:58:03 JST[26338 LOG: statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-13 11:58:03 JST[26338 LOG: statement: <BIND>
2005-12-13 11:58:03 JST[26338 LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-13 11:58:03 JST[26338 LOG: statement: <BIND>
2005-12-13 11:58:03 JST[26338 LOG: statement: EXECUTE <unnamed> [PREPARE: COMMIT]
：
----------------------------------------------------------------
■(4)db2のPostgreSQLログ(db1と同様)
----------------------------------------------------------------
：
2005-12-13 11:57:13 JST[25885 LOG: statement: <BIND>
2005-12-13 11:57:13 JST[25885 LOG: statement: EXECUTE <unnamed> [PREPARE: BEGIN]
2005-12-13 11:57:13 JST[25885 LOG: statement: PREPARE <unnamed> AS /*STRICT*/ LOCK t1
2005-12-13 11:57:13 JST[25885 LOG: statement: <BIND>
2005-12-13 11:57:13 JST[25885 LOG: statement: EXECUTE <unnamed> [PREPARE: /*STRICT*/ LOCK t1]
2005-12-13 11:58:03 JST[25886 LOG: statement: PREPARE <unnamed> AS SELECT MAX(id) AS max_id FROM t1
2005-12-13 11:58:03 JST[25886 LOG: statement: <BIND>
2005-12-13 11:58:03 JST[25886 LOG: statement: EXECUTE <unnamed> [PREPARE: SELECT MAX(id) AS max_id FROM t1]
2005-12-13 11:58:03 JST[25886 LOG: statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-13 11:58:03 JST[25886 LOG: statement: <BIND>
2005-12-13 11:58:03 JST[25886 LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-13 11:58:03 JST[25886 LOG: statement: <BIND>
2005-12-13 11:58:03 JST[25886 LOG: statement: EXECUTE <unnamed> [PREPARE: COMMIT]
2005-12-13 11:58:03 JST[25885 LOG: unexpected EOF on client connection
2005-12-13 11:58:03 JST[25886 LOG: statement: <BIND>
：
----------------------------------------------------------------
【参考】
■(5)DBI経由での処理ログ(抜粋)
----------------------------------------------------------------
2005-12-13 12:17:58 JST[26208 LOG: statement: begin
2005-12-13 12:17:58 JST[26208 LOG: statement: LOCK t1
2005-12-13 12:17:58 JST[26208 LOG: statement: SELECT MAX(id) AS max_id FROM t1
2005-12-13 12:17:58 JST[26208 LOG: statement: PREPARE <unnamed> AS INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)
2005-12-13 12:17:58 JST[26208 LOG: statement: <BIND>
2005-12-13 12:17:58 JST[26208 LOG: statement: EXECUTE <unnamed> [PREPARE: INSERT INTO t1 (id, server_id, counter) VALUES ($1, $2, $3)]
2005-12-13 12:17:58 JST[26208 LOG: statement: commit
----------------------------------------------------------------
■(6)テストアプリケーション(宣言部・例外処理等を除く抜粋)
----------------------------------------------------------------
for (int i = 0; i < 10000; i++) {
con.setAutoCommit(false);
stmt = con.createStatement();
stmt.executeUpdate("/*STRICT*/ LOCK t1");
int maxId = 1;
pstmt = con.prepareStatement("SELECT MAX(id) AS max_id FROM t1");
rs = pstmt.executeQuery();
if(rs.next() == true) {
maxId = rs.getInt("max_id");
}
rs.close();
pstmt = con.prepareStatement("INSERT INTO t1 (id, server_id, counter) VALUES (?, ?, ?)");
pstmt.setInt(1, maxId+1);
pstmt.setString(2, serverId);
pstmt.setInt(3, i);
pstmt.executeUpdate();
pstmt.close();
con.commit();
}
----------------------------------------------------------------
以上
--
by YAMADA Toshio <toshi ＠ mx1.freemail.ne.jp>
pgsql-jp メーリングリストの案内