Bug #87335 queryTimeout dose not work in connector/J loadbalance mode
Submitted: 7 Aug 2017 6:08 Modified: 7 Aug 2017 9:02
Reporter: Haixing Weng (OCA) Email Updates:
Status: Can't repeat Impact on me:
None 
Category:Connector / J Severity:S3 (Non-critical)
Version:5.1.40 OS:Any
Assigned to: CPU Architecture:Any
Tags: jdbc, loadbalance, queryTimeout

[7 Aug 2017 6:08] Haixing Weng
Description:
Interface setQueryTimeout does not work when called in loadbalance mode. It seems like that disconnect will only depends on socketTimeout, and what's worse, connector/J cannot kill query which timeout  so that MySQL will continue handle the sql query.

How to repeat:
When we use jdbc connect a standalone mysql server, it can run normally when setQueryTimeout, for example:  

            conn =                    DriverManager.getConnection("jdbc:mysql://172.21.101.91:50001/test?connectTimeout=30000&socketTimeout=30000&user=whx&password=123");

            stmt = conn.createStatement();

            stmt.setQueryTimeout(30);

            stmt.executeQuery("SELECT SLEEP(3600);");

After 30 seconds, connection will be closed by jdbc, jdbc will send a kill query to mysql, with a message like that(I dumped the network message):

0x00000000 (00000)   01000001 012c0000 02036465 66000000   .....,....def...
0x00000010 (00016)   16404073 65737369 6f6e2e74 785f7265   .@@session.tx_re
0x00000020 (00032)   61645f6f 6e6c7900 0c3f0001 00000008   ad_only..?......
0x00000030 (00048)   80000000 00050000 03fe0000 02000200   ................
0x00000040 (00064)   00040130 05000005 fe000002 00         ...0.........
get packet from client, session:19, datalen:21.

0x00000000 (00000)   11000000 034b494c 4c205155 45525920   .....KILL QUERY 
0x00000010 (00016)   36383931 34                           68914
get packet from server, session:19, datalen:11.

But things is query different in load balance mode:

conn =
                    DriverManager.getConnection("jdbc:mysql:loadbalance://172.21.101.91:50001,172.21.101.91:50002,172.21.101.91:50003/test?" +
                            "user=whx&password=123&connectTimeout=40000&socketTimeout=40000");

stmt = conn.createStatement();

            stmt.setQueryTimeout(30);
            stmt.executeQuery("SELECT SLEEP(3600);");

And you will find that:

1. setQueryTimeout does not work at all, the query will be timeout and session will be closed in 40 seconds(which is socketTimeout value)。

2. jdbc dose not kill timeout query when timeout,I dumped network message in 3 servers,and found no "Kill Query" message.(Interestingly,when detect timout, jdbc will establish a new session in a random mysql servers and close it immediately)

mysql> show processlist;
+-------+---------+---------------------+------+---------+------+------------+--------------------+
| Id    | User    | Host                | db   | Command | Time | State      | Info               |
+-------+---------+---------------------+------+---------+------+------------+--------------------+
| 68880 | cup_dba | localhost           | NULL | Query   |    0 | init       | show processlist   |
| 68917 | whx     | 172.21.101.91:43519 | test | Query   |  103 | User sleep | SELECT SLEEP(3600) |
+-------+---------+---------------------+------+---------+------+------------+--------------------+
2 rows in set (0.00 sec)

Cannot kill query after timeout is a serious bug, it means that we cannot terminate a sql query which  might consume computing resource so much.

Suggested fix:
Yet I have no idea about how to fix it.
[7 Aug 2017 7:53] Chiranjeevi Battula
Hello Haixing Weng,

Thank you for the bug report and test case.
I tried to reproduce the issue at my end using MySQL Connector / J 5.1.43 and MySQL 5.7.19 but not seeing any issues in connectTimeout and socketTimeout.

Thanks,
Chiranjeevi.
[7 Aug 2017 7:54] Chiranjeevi Battula
mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+--------------------+
| Id | User | Host            | db   | Command | Time | State      | Info               |
+----+------+-----------------+------+---------+------+------------+--------------------+
| 26 | root | localhost:63161 | test | Sleep   |  331 |            | NULL               |
| 27 | root | localhost:63162 | test | Sleep   |  331 |            | NULL               |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting   | show processlist   |
| 41 | root | localhost:63208 | test | Query   |    1 | User sleep | SELECT SLEEP(3600) |
+----+------+-----------------+------+---------+------+------------+--------------------+
4 rows in set (0.00 sec)

mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+--------------------+
| Id | User | Host            | db   | Command | Time | State      | Info               |
+----+------+-----------------+------+---------+------+------------+--------------------+
| 26 | root | localhost:63161 | test | Sleep   |  334 |            | NULL               |
| 27 | root | localhost:63162 | test | Sleep   |  334 |            | NULL               |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting   | show processlist   |
| 41 | root | localhost:63208 | test | Query   |    4 | User sleep | SELECT SLEEP(3600) |
+----+------+-----------------+------+---------+------+------------+--------------------+
4 rows in set (0.00 sec)

mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+--------------------+
| Id | User | Host            | db   | Command | Time | State      | Info               |
+----+------+-----------------+------+---------+------+------------+--------------------+
| 26 | root | localhost:63161 | test | Sleep   |  339 |            | NULL               |
| 27 | root | localhost:63162 | test | Sleep   |  339 |            | NULL               |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting   | show processlist   |
| 41 | root | localhost:63208 | test | Query   |    9 | User sleep | SELECT SLEEP(3600) |
+----+------+-----------------+------+---------+------+------------+--------------------+
4 rows in set (0.00 sec)

mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+--------------------+
| Id | User | Host            | db   | Command | Time | State      | Info               |
+----+------+-----------------+------+---------+------+------------+--------------------+
| 26 | root | localhost:63161 | test | Sleep   |  346 |            | NULL               |
| 27 | root | localhost:63162 | test | Sleep   |  346 |            | NULL               |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting   | show processlist   |
| 41 | root | localhost:63208 | test | Query   |   16 | User sleep | SELECT SLEEP(3600) |
+----+------+-----------------+------+---------+------+------------+--------------------+
4 rows in set (0.02 sec)

mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+--------------------+
| Id | User | Host            | db   | Command | Time | State      | Info               |
+----+------+-----------------+------+---------+------+------------+--------------------+
| 26 | root | localhost:63161 | test | Sleep   |  352 |            | NULL               |
| 27 | root | localhost:63162 | test | Sleep   |  352 |            | NULL               |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting   | show processlist   |
| 41 | root | localhost:63208 | test | Query   |   22 | User sleep | SELECT SLEEP(3600) |
+----+------+-----------------+------+---------+------+------------+--------------------+
4 rows in set (0.00 sec)

mysql> show processlist;
+----+------+-----------------+------+---------+------+------------+--------------------+
| Id | User | Host            | db   | Command | Time | State      | Info               |
+----+------+-----------------+------+---------+------+------------+--------------------+
| 26 | root | localhost:63161 | test | Sleep   |  358 |            | NULL               |
| 27 | root | localhost:63162 | test | Sleep   |  358 |            | NULL               |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting   | show processlist   |
| 41 | root | localhost:63208 | test | Query   |   28 | User sleep | SELECT SLEEP(3600) |
+----+------+-----------------+------+---------+------+------------+--------------------+
4 rows in set (0.00 sec)

mysql> show processlist;
+----+------+-----------------+------+---------+------+----------+------------------+
| Id | User | Host            | db   | Command | Time | State    | Info             |
+----+------+-----------------+------+---------+------+----------+------------------+
| 26 | root | localhost:63161 | test | Sleep   |  362 |          | NULL             |
| 27 | root | localhost:63162 | test | Sleep   |  362 |          | NULL             |
| 34 | root | localhost:63176 | NULL | Query   |    0 | starting | show processlist |
+----+------+-----------------+------+---------+------+----------+------------------+
3 rows in set (0.01 sec)

mysql>
[7 Aug 2017 9:02] Haixing Weng
Hi Chiranjeevi Battula:

I have confirmed that it's all normal in jdbc with a new version 5.1.43.I think I've made a mistake. 

Thank you