[pgpool-general: 877] Bug when dealing with multiple SET statements through libpq
Kouber Saparev
kouber at saparev.com
Tue Aug 7 18:46:52 JST 2012
Hello,
I noticed an unwanted behaviour when passing multiple SET statements to
pgpool through the libpq PQexec() function (through the PHP pg_query()
wrapper actually).
If I pass the following queries to a single call of pg_query() in PHP,
then they're sent to the master only, leading to disastrous situations
when the slave connection is used further:
pg_query('SET search_path TO translated, public, lib; SET
statement_timeout TO 100000;');
Here's what arrives in the logs of both servers - the master and the slave:
Aug 7 10:49:20 MASTER postgres[31266]: [2-1] user=www,db=data LOG:
duration: 0.169 ms statement: SET search_path TO translated, public,
lib; SET statement_timeout TO 100000;
Aug 7 10:49:20 MASTER postgres[31266]: [3-1] user=www,db=data LOG:
duration: 0.020 ms statement: BEGIN
Aug 7 10:49:20 MASTER postgres[31266]: [4-1] user=www,db=data LOG:
duration: 0.023 ms statement: SET SESSION AUTHORIZATION DEFAULT
Aug 7 10:49:20 MASTER postgres[31266]: [5-1] user=www,db=data LOG:
duration: 0.020 ms statement: COMMIT
Aug 7 10:49:20 MASTER postgres[31266]: [6-1] user=www,db=data LOG:
duration: 0.017 ms statement: BEGIN
Aug 7 10:49:20 MASTER postgres[31266]: [7-1] user=www,db=data LOG:
duration: 0.018 ms statement: RESET ALL
Aug 7 10:49:20 MASTER postgres[31266]: [8-1] user=www,db=data LOG:
duration: 0.016 ms statement: COMMIT
Aug 7 10:49:20 MASTER postgres[31266]: [9-1] user=www,db=data LOG:
duration: 0.296 ms statement: SELECT pg_advisory_unlock_all()
Aug 7 10:49:20 MASTER postgres[31266]: [10-1] user=www,db=data LOG:
duration: 0.027 ms statement: DISCARD TEMP
Aug 7 10:49:20 SLAVE postgres[4182]: [2-1] user=www,db=data LOG:
duration: 0.073 ms statement: BEGIN
Aug 7 10:49:20 SLAVE postgres[4182]: [3-1] user=www,db=data LOG:
duration: 0.047 ms statement: SET SESSION AUTHORIZATION DEFAULT
Aug 7 10:49:20 SLAVE postgres[4182]: [4-1] user=www,db=data LOG:
duration: 0.022 ms statement: COMMIT
Aug 7 10:49:20 SLAVE postgres[4182]: [5-1] user=www,db=data LOG:
duration: 0.017 ms statement: BEGIN
Aug 7 10:49:20 SLAVE postgres[4182]: [6-1] user=www,db=data LOG:
duration: 0.017 ms statement: RESET ALL
Aug 7 10:49:20 SLAVE postgres[4182]: [7-1] user=www,db=data LOG:
duration: 0.015 ms statement: COMMIT
Aug 7 10:49:20 SLAVE postgres[4182]: [8-1] user=www,db=data LOG:
duration: 0.024 ms statement: DISCARD TEMP
The SET commands are not sent to the slave at all!
However if I divide the queries in two calls to pg_query(), then
everything goes well:
pg_query('SET search_path TO translated, public, lib');
pg_query('SET statement_timeout TO 100000');
The logs:
Aug 7 10:51:31 MASTER postgres[31686]: [2-1] user=www,db=data LOG:
duration: 0.060 ms statement: BEGIN
Aug 7 10:51:31 MASTER postgres[31686]: [3-1] user=www,db=data LOG:
duration: 0.094 ms statement: SET search_path TO translated, public, lib
Aug 7 10:51:31 MASTER postgres[31686]: [4-1] user=www,db=data LOG:
duration: 0.023 ms statement: COMMIT
Aug 7 10:51:31 MASTER postgres[31686]: [5-1] user=www,db=data LOG:
duration: 0.016 ms statement: BEGIN
Aug 7 10:51:31 MASTER postgres[31686]: [6-1] user=www,db=data LOG:
duration: 0.029 ms statement: SET statement_timeout TO 100000;
Aug 7 10:51:31 MASTER postgres[31686]: [7-1] user=www,db=data LOG:
duration: 0.018 ms statement: COMMIT
Aug 7 10:51:31 MASTER postgres[31686]: [8-1] user=www,db=data LOG:
duration: 0.018 ms statement: BEGIN
Aug 7 10:51:31 MASTER postgres[31686]: [9-1] user=www,db=data LOG:
duration: 0.022 ms statement: SET SESSION AUTHORIZATION DEFAULT
Aug 7 10:51:31 MASTER postgres[31686]: [10-1] user=www,db=data LOG:
duration: 0.017 ms statement: COMMIT
Aug 7 10:51:31 MASTER postgres[31686]: [11-1] user=www,db=data LOG:
duration: 0.018 ms statement: BEGIN
Aug 7 10:51:31 MASTER postgres[31686]: [12-1] user=www,db=data LOG:
duration: 0.018 ms statement: RESET ALL
Aug 7 10:51:31 MASTER postgres[31686]: [13-1] user=www,db=data LOG:
duration: 0.016 ms statement: COMMIT
Aug 7 10:51:31 MASTER postgres[31686]: [14-1] user=www,db=data LOG:
duration: 0.250 ms statement: SELECT pg_advisory_unlock_all()
Aug 7 10:51:31 MASTER postgres[31686]: [15-1] user=www,db=data LOG:
duration: 0.024 ms statement: DISCARD TEMP
Aug 7 10:51:31 SLAVE postgres[4605]: [2-1] user=www,db=data LOG:
duration: 0.082 ms statement: BEGIN
Aug 7 10:51:31 SLAVE postgres[4605]: [3-1] user=www,db=data LOG:
duration: 0.105 ms statement: SET search_path TO translated, public, lib
Aug 7 10:51:31 SLAVE postgres[4605]: [4-1] user=www,db=data LOG:
duration: 0.023 ms statement: COMMIT
Aug 7 10:51:31 SLAVE postgres[4605]: [5-1] user=www,db=data LOG:
duration: 0.018 ms statement: BEGIN
Aug 7 10:51:31 SLAVE postgres[4605]: [6-1] user=www,db=data LOG:
duration: 0.028 ms statement: SET statement_timeout TO 100000;
Aug 7 10:51:31 SLAVE postgres[4605]: [7-1] user=www,db=data LOG:
duration: 0.017 ms statement: COMMIT
Aug 7 10:51:31 SLAVE postgres[4605]: [8-1] user=www,db=data LOG:
duration: 0.021 ms statement: BEGIN
Aug 7 10:51:31 SLAVE postgres[4605]: [9-1] user=www,db=data LOG:
duration: 0.028 ms statement: SET SESSION AUTHORIZATION DEFAULT
Aug 7 10:51:31 SLAVE postgres[4605]: [10-1] user=www,db=data LOG:
duration: 0.019 ms statement: COMMIT
Aug 7 10:51:31 SLAVE postgres[4605]: [11-1] user=www,db=data LOG:
duration: 0.015 ms statement: BEGIN
Aug 7 10:51:31 SLAVE postgres[4605]: [12-1] user=www,db=data LOG:
duration: 0.019 ms statement: RESET ALL
Aug 7 10:51:31 SLAVE postgres[4605]: [13-1] user=www,db=data LOG:
duration: 0.016 ms statement: COMMIT
Aug 7 10:51:31 SLAVE postgres[4605]: [14-1] user=www,db=data LOG:
duration: 0.026 ms statement: DISCARD TEMP
The SET commands are sent to both servers, which is the expected
behaviour - both connections are properly initialised for further work.
I am using pgpool-II-3.2.0, PostgreSQL 9.1.3, libpq5 - 9.1.3-2, PHP 5.3.10.
The bug does not occur when working through psql directly:
data=> SET search_path TO translated, public, lib; SET statement_timeout
TO 100000;
SET
SET
Aug 7 10:53:21 MASTER postgres[31688]: [2-1] user=www,db=data LOG:
duration: 0.085 ms statement: BEGIN
Aug 7 10:53:21 MASTER postgres[31688]: [3-1] user=www,db=data LOG:
duration: 0.112 ms statement: SET search_path TO translated, public, lib;
Aug 7 10:53:21 MASTER postgres[31688]: [4-1] user=www,db=data LOG:
duration: 0.030 ms statement: COMMIT
Aug 7 10:53:21 MASTER postgres[31688]: [5-1] user=www,db=data LOG:
duration: 0.017 ms statement: BEGIN
Aug 7 10:53:21 MASTER postgres[31688]: [6-1] user=www,db=data LOG:
duration: 0.027 ms statement: SET statement_timeout TO 100000;
Aug 7 10:53:21 MASTER postgres[31688]: [7-1] user=www,db=data LOG:
duration: 0.018 ms statement: COMMIT
Aug 7 10:53:21 SLAVE postgres[4606]: [2-1] user=www,db=data LOG:
duration: 0.086 ms statement: BEGIN
Aug 7 10:53:21 SLAVE postgres[4606]: [3-1] user=www,db=data LOG:
duration: 0.140 ms statement: SET search_path TO translated, public, lib;
Aug 7 10:53:21 SLAVE postgres[4606]: [4-1] user=www,db=data LOG:
duration: 0.030 ms statement: COMMIT
Aug 7 10:53:21 SLAVE postgres[4606]: [5-1] user=www,db=data LOG:
duration: 0.018 ms statement: BEGIN
Aug 7 10:53:21 SLAVE postgres[4606]: [6-1] user=www,db=data LOG:
duration: 0.029 ms statement: SET statement_timeout TO 100000;
Aug 7 10:53:21 SLAVE postgres[4606]: [7-1] user=www,db=data LOG:
duration: 0.019 ms statement: COMMIT
--
Kouber Saparev
More information about the pgpool-general
mailing list