Open neutrinoes opened 6 years ago
mycat version：1.6.5 mysql version: 5.7.16 问题描述： 在批处理作业中，从mycat获取连接后，长时间使用同一个连接执行多次多条不同的SQL进行插入。单条SQL执行时间不超过30ms。 t获取连接超过sqlExecuteTimeout(默认300秒)时间后，mycat会主动关闭该连接。
期望结果：若单条SQL执行时间不超过sqlExecuteTimeout，mycat不主动关闭连接，即使客户端已占用这个连接较长时间。
建议：检测后端连接超时时间，可以在每次执行提交SQL前，更新io.mycat.backend.jdbc.JDBCConnection.lastTime = TimeUtil.currentTimeMillis();
mycat server 日志： 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=10,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-16, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@362a422, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1636, '1436', '2018-01-04 09:35:54.123')}, packetId=1], attachement=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1636, '1436', '2018-01-04 09:35:54.123')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029736200, lastTime=1515029743240, isSpark=false, processor=io.mycat.net.NIOProcessor@5d3cd617] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=6,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-15, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@3c904a8, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t3 (id, name, create_time) VALUES (1641, '1441', '2018-01-04 09:35:54.16')}, packetId=1], attachement=mydn{INSERT INTO t3 (id, name, create_time) VALUES (1641, '1441', '2018-01-04 09:35:54.16')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743230, isSpark=false, processor=io.mycat.net.NIOProcessor@59388336] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=3,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-16, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@2b4c4b93, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t1 (id, name, create_time) VALUES (1639, '1439', '2018-01-04 09:35:54.144')}, packetId=1], attachement=mydn{INSERT INTO t1 (id, name, create_time) VALUES (1639, '1439', '2018-01-04 09:35:54.144')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743270, isSpark=false, processor=io.mycat.net.NIOProcessor@1e869cd8] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=7,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-16, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@16bb9576, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t0 (id, name, create_time) VALUES (1638, '1438', '2018-01-04 09:35:54.137')}, packetId=1], attachement=mydn{INSERT INTO t0 (id, name, create_time) VALUES (1638, '1438', '2018-01-04 09:35:54.137')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743260, isSpark=false, processor=io.mycat.net.NIOProcessor@1e869cd8] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,169 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=8,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-15, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@4760a12a, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t2 (id, name, create_time) VALUES (1640, '1440', '2018-01-04 09:35:54.153')}, packetId=1], attachement=mydn{INSERT INTO t2 (id, name, create_time) VALUES (1640, '1440', '2018-01-04 09:35:54.153')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743217, isSpark=false, processor=io.mycat.net.NIOProcessor@1f51427f] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,179 [WARN ][BusinessExecutor7] set txisolation error: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at com.mysql.jdbc.Util.handleNewInstance(Util.java:389) at com.mysql.jdbc.Util.getInstance(Util.java:372) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:958) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:937) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:872) at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1236) at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1231) at com.mysql.jdbc.ConnectionImpl.setTransactionIsolation(ConnectionImpl.java:5088) at io.mycat.backend.jdbc.JDBCConnection.syncIsolation(JDBCConnection.java:279) at io.mycat.backend.jdbc.JDBCConnection.executeSQL(JDBCConnection.java:297) at io.mycat.backend.jdbc.JDBCConnection.access$000(JDBCConnection.java:33) at io.mycat.backend.jdbc.JDBCConnection$1.run(JDBCConnection.java:783) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) (io.mycat.backend.jdbc.JDBCConnection:JDBCConnection.java:282) 2018-01-04 09:35:54,180 [WARN ][BusinessExecutor7] execute sql err : errno:0 No operations allowed after connection closed. con:JDBCConnection [id=10,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-15, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@362a422, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1642, '1442', '2018-01-04 09:35:54.167')}, packetId=1], attachement=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1642, '1442', '2018-01-04 09:35:54.167')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029736200, lastTime=1515029743240, isSpark=false, processor=io.mycat.net.NIOProcessor@5d3cd617] frontend host:127.0.0.1/52920/root (io.mycat.backend.mysql.nio.handler.SingleNodeHandler:SingleNodeHandler.java:250)
主动关闭连接处： io.mycat.net.NIOProcessor.backendCheck() line:201 // SQL执行超时的连接关闭 if (c.isBorrowed() && c.getLastTime() < TimeUtil.currentTimeMillis() - sqlTimeout) { LOGGER.warn("found backend connection SQL timeout ,close it " + c); c.close("sql timeout"); } 建议修改： io.mycat.backend.jdbc.JDBCConnection.executeSQL() line:287
private void executeSQL(RouteResultsetNode rrn, ServerConnection sc, boolean autocommit) throws IOException { //防止长时间使用一个connection时，mycat自动关闭该连接 this.lastTime = TimeUtil.currentTimeMillis(); String orgin = rrn.getStatement();
same issue.
amao12580
commented
5 years ago amao12580
commented
5 years ago
mycat version：1.6.5 mysql version: 5.7.16 问题描述： 在批处理作业中，从mycat获取连接后，长时间使用同一个连接执行多次多条不同的SQL进行插入。单条SQL执行时间不超过30ms。 t获取连接超过sqlExecuteTimeout(默认300秒)时间后，mycat会主动关闭该连接。
期望结果：若单条SQL执行时间不超过sqlExecuteTimeout，mycat不主动关闭连接，即使客户端已占用这个连接较长时间。
建议：检测后端连接超时时间，可以在每次执行提交SQL前，更新io.mycat.backend.jdbc.JDBCConnection.lastTime = TimeUtil.currentTimeMillis();
mycat server 日志： 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=10,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-16, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@362a422, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1636, '1436', '2018-01-04 09:35:54.123')}, packetId=1], attachement=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1636, '1436', '2018-01-04 09:35:54.123')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029736200, lastTime=1515029743240, isSpark=false, processor=io.mycat.net.NIOProcessor@5d3cd617] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=6,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-15, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@3c904a8, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t3 (id, name, create_time) VALUES (1641, '1441', '2018-01-04 09:35:54.16')}, packetId=1], attachement=mydn{INSERT INTO t3 (id, name, create_time) VALUES (1641, '1441', '2018-01-04 09:35:54.16')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743230, isSpark=false, processor=io.mycat.net.NIOProcessor@59388336] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=3,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-16, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@2b4c4b93, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t1 (id, name, create_time) VALUES (1639, '1439', '2018-01-04 09:35:54.144')}, packetId=1], attachement=mydn{INSERT INTO t1 (id, name, create_time) VALUES (1639, '1439', '2018-01-04 09:35:54.144')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743270, isSpark=false, processor=io.mycat.net.NIOProcessor@1e869cd8] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,168 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=7,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-16, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@16bb9576, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t0 (id, name, create_time) VALUES (1638, '1438', '2018-01-04 09:35:54.137')}, packetId=1], attachement=mydn{INSERT INTO t0 (id, name, create_time) VALUES (1638, '1438', '2018-01-04 09:35:54.137')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743260, isSpark=false, processor=io.mycat.net.NIOProcessor@1e869cd8] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,169 [WARN ][Timer0] found backend connection SQL timeout ,close it JDBCConnection [id=8,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-15, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@4760a12a, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t2 (id, name, create_time) VALUES (1640, '1440', '2018-01-04 09:35:54.153')}, packetId=1], attachement=mydn{INSERT INTO t2 (id, name, create_time) VALUES (1640, '1440', '2018-01-04 09:35:54.153')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029735967, lastTime=1515029743217, isSpark=false, processor=io.mycat.net.NIOProcessor@1f51427f] (io.mycat.net.NIOProcessor:NIOProcessor.java:211) 2018-01-04 09:35:54,179 [WARN ][BusinessExecutor7] set txisolation error: com.mysql.jdbc.exceptions.jdbc4.MySQLNonTransientConnectionException: No operations allowed after connection closed. at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method) at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62) at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45) at java.lang.reflect.Constructor.newInstance(Constructor.java:423) at com.mysql.jdbc.Util.handleNewInstance(Util.java:389) at com.mysql.jdbc.Util.getInstance(Util.java:372) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:958) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:937) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:926) at com.mysql.jdbc.SQLError.createSQLException(SQLError.java:872) at com.mysql.jdbc.ConnectionImpl.throwConnectionClosedException(ConnectionImpl.java:1236) at com.mysql.jdbc.ConnectionImpl.checkClosed(ConnectionImpl.java:1231) at com.mysql.jdbc.ConnectionImpl.setTransactionIsolation(ConnectionImpl.java:5088) at io.mycat.backend.jdbc.JDBCConnection.syncIsolation(JDBCConnection.java:279) at io.mycat.backend.jdbc.JDBCConnection.executeSQL(JDBCConnection.java:297) at io.mycat.backend.jdbc.JDBCConnection.access$000(JDBCConnection.java:33) at io.mycat.backend.jdbc.JDBCConnection$1.run(JDBCConnection.java:783) at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) at java.lang.Thread.run(Thread.java:748) (io.mycat.backend.jdbc.JDBCConnection:JDBCConnection.java:282) 2018-01-04 09:35:54,180 [WARN ][BusinessExecutor7] execute sql err : errno:0 No operations allowed after connection closed. con:JDBCConnection [id=10,autocommit=true,pool=io.mycat.backend.jdbc.JDBCDatasource@58406d0f, schema=tmp, dbType=MYSQL, oldSchema=tmp, packetId=-15, txIsolation=0, running=false, borrowed=true, host=127.0.0.1, port=3310, con=com.mysql.jdbc.JDBC4Connection@362a422, respHandler=SingleNodeHandler [node=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1642, '1442', '2018-01-04 09:35:54.167')}, packetId=1], attachement=mydn{INSERT INTO t4 (id, name, create_time) VALUES (1642, '1442', '2018-01-04 09:35:54.167')}, headerOutputed=false, modifiedSQLExecuted=true, startTime=1515029736200, lastTime=1515029743240, isSpark=false, processor=io.mycat.net.NIOProcessor@5d3cd617] frontend host:127.0.0.1/52920/root (io.mycat.backend.mysql.nio.handler.SingleNodeHandler:SingleNodeHandler.java:250)
主动关闭连接处： io.mycat.net.NIOProcessor.backendCheck() line:201 // SQL执行超时的连接关闭 if (c.isBorrowed() && c.getLastTime() < TimeUtil.currentTimeMillis() - sqlTimeout) { LOGGER.warn("found backend connection SQL timeout ,close it " + c); c.close("sql timeout"); } 建议修改： io.mycat.backend.jdbc.JDBCConnection.executeSQL() line:287
private void executeSQL(RouteResultsetNode rrn, ServerConnection sc, boolean autocommit) throws IOException { //防止长时间使用一个connection时，mycat自动关闭该连接 this.lastTime = TimeUtil.currentTimeMillis(); String orgin = rrn.getStatement();