1. 程式人生 > >druid連接池使用過程遇到的一個奇怪異常

druid連接池使用過程遇到的一個奇怪異常

druid 異常 canceling statement due to user request

某天日誌中連續都是如下的異常:

2017-09-06 21:39:52.936 ERROR [DruidDataSource.java:1974] create connection holder error

org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block

at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2476) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2189) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:301) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:287) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:264) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgConnection.execSQLQuery(PgConnection.java:416) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgConnection.execSQLQuery(PgConnection.java:410) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgConnection.getTransactionIsolation(PgConnection.java:793) ~[postgresql-42.1.1.jar:42.1.1]

at com.alibaba.druid.filter.FilterChainImpl.connection_getTransactionIsolation(FilterChainImpl.java:362) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.filter.FilterAdapter.connection_getTransactionIsolation(FilterAdapter.java:871) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.filter.FilterChainImpl.connection_getTransactionIsolation(FilterChainImpl.java:359) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.proxy.jdbc.ConnectionProxyImpl.getTransactionIsolation(ConnectionProxyImpl.java:260) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidConnectionHolder.<init>(DruidConnectionHolder.java:145) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidConnectionHolder.<init>(DruidConnectionHolder.java:84) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidDataSource.put(DruidDataSource.java:1964) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2221) [druid-1.1.0.jar:1.1.0]

Caused by: org.postgresql.util.PSQLException: ERROR: canceling statement due to user request

at org.postgresql.core.v3.QueryExecutorImpl.receiveErrorResponse(QueryExecutorImpl.java:2476) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.core.v3.QueryExecutorImpl.processResults(QueryExecutorImpl.java:2189) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.core.v3.QueryExecutorImpl.execute(QueryExecutorImpl.java:300) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeInternal(PgStatement.java:428) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.execute(PgStatement.java:354) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:301) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeCachedSql(PgStatement.java:287) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeWithFlags(PgStatement.java:264) ~[postgresql-42.1.1.jar:42.1.1]

at org.postgresql.jdbc.PgStatement.executeQuery(PgStatement.java:231) ~[postgresql-42.1.1.jar:42.1.1]

at com.alibaba.druid.pool.vendor.PGValidConnectionChecker.isValidConnection(PGValidConnectionChecker.java:65) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidAbstractDataSource.validateConnection(DruidAbstractDataSource.java:1293) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidAbstractDataSource.createPhysicalConnection(DruidAbstractDataSource.java:1539) ~[druid-1.1.0.jar:1.1.0]

at com.alibaba.druid.pool.DruidDataSource$CreateConnectionThread.run(DruidDataSource.java:2178) [druid-1.1.0.jar:1.1.0]

最後查找資料,查看druid源代碼,終於找到了原因,在數據庫建立連接時,會檢查連接狀況:

(!= ) {
    result = ;
    Exception error = ;
    {
        result = .isValidConnection(conn, , );
    } (Exception ex) {
        error = ex;
    }
    
    (!result) {
        SQLException sqlError = error != ? SQLException(, error) : SQLException();
        sqlError;
    }
    ;
}

由於我們使用的是postgres數據庫,在PGValidConnectionChecker代碼中

int queryTimeout = validationQueryTimeout < 0 ? defaultQueryTimeout : validationQueryTimeout;

Statement stmt = ;
ResultSet rs = ;
{
    stmt = conn.createStatement();
    stmt.setQueryTimeout(queryTimeout);
    rs = stmt.executeQuery(validateQuery);
    ;

此處validationQueryTime默認值-1,defaultQueryTimeout則為1,這就造成執行sql語句需要在1秒內返回,偏偏那時候我們數據庫正處於非常復雜的計算中,沒有及時響應,就拋出了

如下異常Caused by: org.postgresql.util.PSQLException: ERROR: canceling statement due to user request,然後更有趣的事情發生了

這段代碼是數據源建立連接的時候,測試連接是否通順運行的,拋出異常後,

由於此處result默認為true,拋出異常也沒有更改result為false,然後該連接會被正常使用,由於本身該連接使用過程中已經出現過異常,再次使用就會拋出

ERROR [DruidDataSource.java:1974] create connection holder error

org.postgresql.util.PSQLException: ERROR: current transaction is aborted, commands ignored until end of transaction block

由於druid的連接池未滿,所以不停的創建連接,接連不斷拋出如上異常


druid連接池使用過程遇到的一個奇怪異常