Donor accepts query, which then blocks
Affects | Status | Importance | Assigned to | Milestone | |
---|---|---|---|---|---|
MySQL patches by Codership |
Fix Released
|
High
|
Alex Yurchenko | ||
5.1 |
Fix Committed
|
High
|
Alex Yurchenko | ||
5.5 |
Fix Released
|
High
|
Alex Yurchenko |
Bug Description
Hi
This is the same issue we discussed in Santa Clara, and also reported in this bug: https:/
But the test case is new.
I'm testing the loadbalancing feature of the MySQL JDBC driver. I created the following java program which inserts a single row each second:
*******
import java.sql.*;
public class MysqlTest
{
public static void main (String[] args)
{
Connection conn = null;
while(true)
{
// Connect to MySQL
try
{
}
catch (Exception e)
{
}
try
{
int count;
}
catch (SQLException e)
{
}
// Close connection
if (conn != null)
{
try
{
}
{
}
}
try { Thread.sleep(1000); } catch( Exception e ) { }
}
}
}
*******
I run this with: java -cp mysql-connector
When all 3 nodes are up, this results in following entries in the table:
| 31 | Inserted from Java code. | esitbi125lab.
| 34 | Inserted from Java code. | esitbi125lab.
| 37 | Inserted from Java code. | esitbi125lab.
| 39 | Inserted from Java code. | esitbi126lab.
| 43 | Inserted from Java code. | esitbi125lab.
| 44 | Inserted from Java code. | esitbi127lab.
| 45 | Inserted from Java code. | esitbi126lab.
| 49 | Inserted from Java code. | esitbi125lab.
| 51 | Inserted from Java code. | esitbi126lab.
| 55 | Inserted from Java code. | esitbi125lab.
| 56 | Inserted from Java code. | esitbi127lab.
| 57 | Inserted from Java code. | esitbi126lab.
Now, I stop node 127, delete grastate.dat, start node 127:
[root@esitbi127lab sqlclust]# /etc/init.d/mysql stop
Shutting down MySQL (Percona XtraDB Cluster)....... [ OK ]
[root@esitbi127lab sqlclust]# rm /data/pxc/
rm: remove regular file `/data/
[root@esitbi127lab sqlclust]# /etc/init.d/mysql start
Starting MySQL (Percona XtraDB Cluster).... [ OK ]
[root@esitbi127lab sqlclust]#
Node 125 during this time produces following log:
*******
120522 10:37:18 [Note] WSREP: declaring fa705874-
120522 10:37:18 [Note] WSREP: (050341a6-
120522 10:37:18 [Note] WSREP: view(view_
050341a6-
fa705874-
} joined {
} left {
} partitioned {
8b472f9c-
})
120522 10:37:18 [Note] WSREP: forgetting 8b472f9c-
120522 10:37:18 [Note] WSREP: (050341a6-
120522 10:37:18 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 2
120522 10:37:18 [Note] WSREP: STATE_EXCHANGE: sent state UUID: f5b2c462-
120522 10:37:18 [Note] WSREP: STATE EXCHANGE: sent state msg: f5b2c462-
120522 10:37:18 [Note] WSREP: STATE EXCHANGE: got state msg: f5b2c462-
120522 10:37:18 [Note] WSREP: STATE EXCHANGE: got state msg: f5b2c462-
120522 10:37:18 [Note] WSREP: Quorum results:
version = 2,
component = PRIMARY,
conf_id = 21,
members = 2/2 (joined/total),
act_id = 920,
last_appl. = 0,
protocols = 0/3/1 (gcs/repl/appl),
group UUID = ebeb1502-
120522 10:37:18 [Note] WSREP: Flow-control interval: [12, 23]
120522 10:37:18 [Note] WSREP: New cluster view: global state: ebeb1502-
120522 10:37:18 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
120522 10:37:18 [Note] WSREP: Assign initial position for certification: 920, protocol version: 2
120522 10:37:24 [Note] WSREP: cleaning up 8b472f9c-
120522 10:37:42 [Note] WSREP: (050341a6-
120522 10:37:42 [Note] WSREP: (050341a6-
120522 10:37:42 [Note] WSREP: declaring 04e8d7a0-
120522 10:37:42 [Note] WSREP: declaring fa705874-
120522 10:37:42 [Note] WSREP: view(view_
04e8d7a0-
050341a6-
fa705874-
} joined {
} left {
} partitioned {
})
120522 10:37:42 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 1, memb_num = 3
120522 10:37:42 [Note] WSREP: STATE EXCHANGE: Waiting for state UUID.
120522 10:37:42 [Note] WSREP: STATE EXCHANGE: sent state msg: 05359ea0-
120522 10:37:42 [Note] WSREP: STATE EXCHANGE: got state msg: 05359ea0-
120522 10:37:42 [Note] WSREP: STATE EXCHANGE: got state msg: 05359ea0-
120522 10:37:42 [Note] WSREP: STATE EXCHANGE: got state msg: 05359ea0-
120522 10:37:42 [Note] WSREP: Quorum results:
version = 2,
component = PRIMARY,
conf_id = 22,
members = 2/3 (joined/total),
act_id = 943,
last_appl. = 0,
protocols = 0/3/1 (gcs/repl/appl),
group UUID = ebeb1502-
120522 10:37:42 [Note] WSREP: Flow-control interval: [14, 28]
120522 10:37:42 [Note] WSREP: New cluster view: global state: ebeb1502-
120522 10:37:42 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
120522 10:37:42 [Note] WSREP: Assign initial position for certification: 943, protocol version: 2
120522 10:37:44 [Note] WSREP: Node 0 (esitbi127lab.
120522 10:37:44 [Note] WSREP: Shifting SYNCED -> DONOR/DESYNCED (TO: 945)
120522 10:37:44 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
120522 10:40:27 [Note] WSREP: 0 (esitbi127lab.
120522 10:40:27 [Note] WSREP: Member 0 (esitbi127lab.
120522 10:40:27 [Note] WSREP: 1 (esitbi125lab.
120522 10:40:27 [Note] WSREP: Shifting DONOR/DESYNCED -> JOINED (TO: 946)
120522 10:40:27 [Note] WSREP: Member 1 (esitbi125lab.
120522 10:40:27 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 946)
120522 10:40:27 [Note] WSREP: Synchronized with group, ready for connections
120522 10:40:27 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
*******
The JDBC driver correctly detects node 127 as gone, and uses only 125 and 126. However, when node 127 is joining and node 125 becomes donor, the insert on node 125 blocks for the duration of the SST.
| 151 | Inserted from Java code. | esitbi125lab.
| 152 | Inserted from Java code. | esitbi126lab.
| 155 | Inserted from Java code. | esitbi125lab.
| 157 | Inserted from Java code. | esitbi125lab.
| 159 | Inserted from Java code. | esitbi125lab.
| 162 | Inserted from Java code. | esitbi126lab.
| 165 | Inserted from Java code. | esitbi126lab.
| 167 | Inserted from Java code. | esitbi125lab.
| 168 | Inserted from Java code. | esitbi126lab.
| 171 | Inserted from Java code. | esitbi126lab.
| 174 | Inserted from Java code. | esitbi126lab.
| 175 | Inserted from Java code. | esitbi127lab.
| 177 | Inserted from Java code. | esitbi126lab.
| 180 | Inserted from Java code. | esitbi126lab.
As you can see above, as long as the jdbc loadbalancer is hitting node 126, everything is fine, but an insert on 125 blocks for 3 minutes at row id 167. This is also seen in SHOW PROCESSLIST:
| 17 | system user | | NULL | Sleep | 32 | committed 933 | NULL
| 18 | system user | | NULL | Sleep | 21 | committed 944 | NULL
| 405 | root | esitbi128lab.
| 406 | root | localhost:48432 | test | Query | 20 | Writing to net | SELECT /*!40001 SQL_NO_CACHE */
| 407 | root | esitbi126lab.
The blocked state is always "query end".
The sst method was mysqldump.
The desired behavior here is that a node in donor state, and using an sst method that is blocking (ie anything else than xtrabackup) should not accept incoming queries but should return an error (ie you typically return the Unknown error). This will allow the load balancer to detect the error and failover to another node. If the query is blocked, then the application/thread is stuck and can't do anything about it.
Henrik,
1) what about ongoing transactions, shall they be aborted? there is an option to wait for them to end, but it may last forever.
2) shall existing connections to donor be terminated? Or only errors should be returned?
3) shall this be a default behaviour?