| Bug #30668 | connection pooling failures | ||
|---|---|---|---|
| Submitted: | 28 Aug 2007 13:03 | Modified: | 5 Sep 2007 15:57 |
| Reporter: | simon elliston ball | Email Updates: | |
| Status: | Closed | Impact on me: | |
| Category: | MySQL Proxy | Severity: | S3 (Non-critical) |
| Version: | 0.6.0 trunk | OS: | Any |
| Assigned to: | Jan Kneschke | CPU Architecture: | Any |
[28 Aug 2007 15:27]
simon elliston ball
Some more info about reproducing this bug:
I have some databases setup db1...db10 and users user1...user10, each db contains a table called test:
CREATE TABLE `test` (
`id` int(11) NOT NULL auto_increment,
`data` varchar(255) default NULL,
PRIMARY KEY (`id`)
)
The queries executed, with lua debug, are:
user1@db1 SELECT * FROM test;
[connect_server]
[1].connected_clients = 0
[1].idling_connections = 0
[1].type = 1
[1].state = 0
[1] open new connection
[connect_server]
[1].connected_clients = 1
[1].idling_connections = 0
[1].type = 1
[1].state = 1
[1] open new connection
[disconnect_client]
[read_query]
current backend = 0
client default db =
client username = user1
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
server default db:
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = EXPLAIN SELECT * FROM test
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query]
current backend = 0
client default db = db1
client username = user1
query = SELECT * FROM test
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query]
current backend = 0
client default db = db1
client username = user1
[disconnect_client]
user1@db1 SELECT * FROM test;
[connect_server]
[1].connected_clients = 0
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[2].connected_clients = 0
[2].idling_connections = 0
[2].type = 2
[2].state = 0
[2] open new connection
[connect_server]
[1].connected_clients = 0
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[2].connected_clients = 1
[2].idling_connections = 0
[2].type = 2
[2].state = 1
[2] open new connection
[disconnect_client]
[read_query]
current backend = 0
client default db =
client username = user1
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = EXPLAIN SELECT * FROM test
server default db:
client default db: db1
syncronizing
sending to backend : sqldb1.cromwells.co.uk:3306
is_slave : true
server default db:
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = SELECT * FROM test
sending to backend : sqldb1.cromwells.co.uk:3306
is_slave : true
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query]
current backend = 0
client default db = db1
client username = user1
[disconnect_client]
user2@db2 SELECT * FROM test;
[connect_server]
[1].connected_clients = 0
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[3].connected_clients = 0
[3].idling_connections = 0
[3].type = 2
[3].state = 0
[3] open new connection
[read_query]
current backend = 0
client default db =
client username = user2
network-conn-pool.c.75: no pool-entry for user2 found
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
(read_query) /usr/local/share/mysql-proxy/rw-splitting.lua:289: attempt to index local 's' (a nil value)
network-mysqld-proxy.c.2815: I have no server backend, closing connection
network-mysqld.c.1161: plugin_call(CON_STATE_READ_QUERY) failed
[disconnect_client]
[connect_server]
[1].connected_clients = 0
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[3].connected_clients = 0
[3].idling_connections = 1
[3].type = 2
[3].state = 1
opening new connection on: 1
[read_query]
current backend = 0
client default db =
client username = user2
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
server default db:
server username : user2
in_trans : false
in_calc_found : false
COM_QUERY : false
network-mysqld.c.1223: (store init-db) COM_INIT_DB: db2
[read_query]
current backend = 0
client default db = db2
client username = user2
query = EXPLAIN SELECT * FROM test
network-conn-pool.c.75: no pool-entry for user2 found
(read_query) /usr/local/share/mysql-proxy/rw-splitting.lua:276: attempt to index local 's' (a nil value)
network-mysqld-proxy.c.2815: I have no server backend, closing connection
network-mysqld.c.1161: plugin_call(CON_STATE_READ_QUERY) failed
[disconnect_client]
[30 Aug 2007 10:12]
simon elliston ball
With the latest trunk (rev 197) I seem to be having problems with the connected_clients field on the backend not being reduced properly, consequently the connect scripts do not work, leading to user not found in pool messages. The first backend will just grow more and more connections, while the read query will eventually fail with a lost connection error 2013 because it will try to use the second backend, which has never received a connection for the client's user due to the fact that there is never more than one idling connection on the main backend. See log below using rw-splitting.lua from r197. The queries were generated from a simple php client which was just requested repeatedly. Note the ever increasing [1].connected_clients = 1
[connect_server]
[1].connected_clients = 1
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[1].address = sqldb.example.com:3306
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[2].address = sqldb1.example.com:3306
opening new connection on: 1
[read_query]
current backend = 1
client default db =
client username = user1
sending to backend : sqldb.example.com:3306
is_slave : false
server default db:
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : false
[read_query_result]
releasing backend : 1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = SELECT * FROM test
sending to backend : sqldb1.example.com:3306
is_slave : true
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query_result]
releasing backend : 2
[read_query]
current backend = 0
client default db = db1
client username = user1
[disconnect_client]
[connect_server]
[1].connected_clients = 2
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[1].address = sqldb.example.com:3306
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[2].address = sqldb1.example.com:3306
opening new connection on: 1
[read_query]
current backend = 1
client default db =
client username = user1
sending to backend : sqldb.example.com:3306
is_slave : false
server default db:
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : false
[read_query_result]
releasing backend : 1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = SELECT * FROM test
sending to backend : sqldb1.example.com:3306
is_slave : true
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query_result]
releasing backend : 2
[read_query]
current backend = 0
client default db = db1
client username = user1
[disconnect_client]
[connect_server]
[1].connected_clients = 3
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[1].address = sqldb.example.com:3306
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[2].address = sqldb1.example.com:3306
opening new connection on: 1
[read_query]
current backend = 1
client default db =
client username = user1
sending to backend : sqldb.example.com:3306
is_slave : false
server default db:
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : false
[read_query_result]
releasing backend : 1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = SELECT * FROM test
sending to backend : sqldb1.example.com:3306
is_slave : true
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query_result]
releasing backend : 2
[read_query]
current backend = 0
client default db = db1
client username = user1
[disconnect_client]
[connect_server]
[1].connected_clients = 4
[1].idling_connections = 1
[1].type = 1
[1].state = 1
[1].address = sqldb.example.com:3306
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[2].address = sqldb1.example.com:3306
opening new connection on: 1
[read_query]
current backend = 1
client default db =
client username = user1
sending to backend : sqldb.example.com:3306
is_slave : false
server default db:
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : false
[read_query_result]
releasing backend : 1
[read_query]
current backend = 0
client default db = db1
client username = user1
query = SELECT * FROM test
sending to backend : sqldb1.example.com:3306
is_slave : true
server default db: db1
server username : user1
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query_result]
releasing backend : 2
[read_query]
current backend = 0
client default db = db1
client username = user1
[disconnect_client]
[31 Aug 2007 16:33]
simon elliston ball
I think I may have tracked down the source of this problem.
When the connect_server script checks for least_idle_connections, and assigns a discovered index to the proxy.connections.backend_ndx userdata field, the function network-mysqld-proxy.c:proxy_connection_set gets called. This will lead to a proxy_connection_pool_swap, which will increment the connected_clients field of the backend.
However, the end of the function will then allow a connect to continue on the backend, leading to network-mysqld-proxy.c:NETWORK_MYSQLD_PLUGIN_PROTO(proxy_connect_server) also increasing the backends connection count.
The read_auth successfully decrements on of these, but not the other, which means you will have a spare connection which always remains a 'connected' part of the pool and is not available either to queries, or to the disconnect client hook.
A transcript of the lua debug, with some extra debug inserted into network-mysqld-proxy.c shows the problem, and where the decrement is not happening. The backend index in the debug from the c code is incremented to match the lua indexes for clarity.
[connect_server]
[1].connected_clients = 0
[1].idling_connections = 4
[1].type = 1
[1].state = 1
[1].address = sqldb.cromwells.co.uk:3306
[2].connected_clients = 0
[2].idling_connections = 1
[2].type = 2
[2].state = 1
[2].address = sqldb1.cromwells.co.uk:3306
[3].connected_clients = 0
[3].idling_connections = 1
[3].type = 2
[3].state = 1
[3].address = sqldb.cromwells.co.uk:3306
Least idle connections on : 2 backend is 0
network-mysqld-proxy.c:634: proxy_connection_pool_swap: Connected clients increased on 2 to 1
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 2 to 0
network-mysqld-proxy.c:3624: proxy_connect_server: Connected client increased on 1 to 1
[read_auth_result]
backend : 1
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 1 to 0
[read_query]
current backend = 0
client default db =
client username = test
cmd = COM_INIT_DB
schema = db1
network-mysqld-proxy.c:634: proxy_connection_pool_swap: Connected clients increased on 1 to 1
running an init db : c= s= setting to db1
sending to backend : sqldb.cromwells.co.uk:3306
is_slave : false
server default db:
server username : test
in_trans : false
in_calc_found : false
COM_QUERY : false
[read_query_result]
inj.id : 1
inj.query : db1
(read_query_result) releasing backend 1
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 1 to 0
[read_query]
current backend = 0
client default db = db1
client username = test
cmd = COM_QUERY
query = SELECT * FROM test
network-mysqld-proxy.c:634: proxy_connection_pool_swap: Connected clients increased on 2 to 1
sending to backend : sqldb1.cromwells.co.uk:3306
is_slave : true
server default db: db1
server username : test
in_trans : false
in_calc_found : false
COM_QUERY : true
[read_query_result]
inj.id : 1
inj.query : SELECT * FROM test
(read_query_result) releasing backend 2
network-mysqld-proxy.c:576: proxy_connection_pool_add_connection: Connected clients reduced on 2 to 0
[read_query]
current backend = 0
client default db = db1
client username = test
cmd = COM_QUIT
[disconnect_client] 0
[5 Sep 2007 15:57]
Jan Kneschke
fixed in [210]
* addr.str per network_socket
- duplicate the string on network_socket_init()
- free on network_socket_free()
- moved addr.str for the client into the accept() call
- added proxy.connection.client.address to rw-splitting.lua
* leaking con->server when rw-splitting is used
- if proxy.connection.backend_ndx = ... is used in rw-splitting and we
have a idle connection in the pool con->server is set too
in proxy_connect_server() we were calling pool_get() a second time
and overwriting con->server. This leaked the con->server handles.
Description: network-conn-pool.c: network_connection_pool_get has an additional parameter GString *default_db which is not used, and should really be checked while finding a pool connection. In addition, the pool fails to pick up connections which it definitely has, because it appears to be failing to release connections properly once a query has been executed. For example: [connect_server] [1].connected_clients = 9 [1].idling_connections = 0 [1].type = 1 [1].state = 1 [1] open new connection [disconnect_client] [read_query] current backend = 0 client default db = client username = user2 sending to backend : sqldb.cromwells.co.uk:3306 is_slave : false server default db: server username : user2 in_trans : false in_calc_found : false COM_QUERY : false network-mysqld.c.1223: (store init-db) COM_INIT_DB: db2 [read_query] current backend = 0 client default db = db2 client username = user2 query = EXPLAIN SELECT * FROM test network-conn-pool.c.75: no pool-entry for user2 found (read_query) /usr/local/share/mysql-proxy/rw-splitting.lua:276: attempt to index local 's' (a nil value) network-mysqld-proxy.c.2815: I have no server backend, closing connection network-mysqld.c.1161: plugin_call(CON_STATE_READ_QUERY) failed This snapshot was taken while only one client was connected to the proxy, though the proxy seems to think 9 are, and has not released the connections it has into the idle pool. How to repeat: export LUA_PATH="/usr/local/share/mysql-proxy/?.lua" /usr/local/sbin/mysql-proxy --proxy-lua-script=/usr/local/share/mysql-proxy/rw-splitting.lua \ --proxy-backend-addresses=sqldb.example.com:3306 \ --proxy-read-only-backend-addresses=sqldb1.example.com:3306 \ --proxy-read-only-backend-addresses=sqldb2.example.com:3306 repeated select queries on different user/db combinations.