From 619c007db9ff6f8fa7fd45394554b55f45acce75 Mon Sep 17 00:00:00 2001 From: wenshao Date: Tue, 27 Nov 2012 12:51:32 +0800 Subject: [PATCH 1/4] improve LogFilter --- .../druid/filter/logging/LogFilter.java | 52 +++++++++++++------ .../alibaba/druid/filter/stat/StatFilter.java | 28 ++-------- .../druid/proxy/jdbc/StatementProxy.java | 5 ++ .../druid/proxy/jdbc/StatementProxyImpl.java | 31 +++++++++-- .../alibaba/druid/stat/JdbcStatementStat.java | 22 -------- 5 files changed, 73 insertions(+), 65 deletions(-) diff --git a/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java b/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java index 4a9717a620..684308423c 100644 --- a/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java +++ b/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java @@ -291,16 +291,16 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM connectionLog("{conn-" + connection.getId() + "} connected"); } } - + @Override public Savepoint connection_setSavepoint(FilterChain chain, ConnectionProxy connection) throws SQLException { Savepoint savepoint = chain.connection_setSavepoint(connection); - + if (isConnectionLogEnabled()) { connectionLog("{conn " + connection.getId() + "} setSavepoint-" + savepoint.getSavepointId()); } - + return savepoint; } @@ -308,11 +308,11 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM public Savepoint connection_setSavepoint(FilterChain chain, ConnectionProxy connection, String name) throws SQLException { Savepoint savepoint = chain.connection_setSavepoint(connection, name); - + if (isConnectionLogEnabled()) { connectionLog("{conn " + connection.getId() + "} setSavepoint-" + name); } - + return savepoint; } @@ -324,11 +324,12 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM connectionLog("{conn " + connection.getId() + "} rollback"); } } - + @Override - public void connection_rollback(FilterChain chain, ConnectionProxy connection, Savepoint savePoint) throws SQLException { + public void connection_rollback(FilterChain chain, ConnectionProxy connection, Savepoint savePoint) + throws SQLException { super.connection_rollback(chain, connection, savePoint); - + if (connectionRollbackAfterLogEnable && isConnectionLogEnabled()) { connectionLog("{conn " + connection.getId() + "} rollback -> " + savePoint.getSavepointId()); } @@ -371,7 +372,7 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM @Override protected void statementExecuteBefore(StatementProxy statement, String sql) { - + statement.setLastExecuteStartNano(); if (statement instanceof PreparedStatementProxy) { logParameter((PreparedStatementProxy) statement); } @@ -380,14 +381,27 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM @Override protected void statementExecuteAfter(StatementProxy statement, String sql, boolean firstResult) { if (statementExecuteAfterLogEnable && isStatementLogEnabled()) { + statement.setLastExecuteTimeNano(); + long nanos = statement.getLastExecuteTimeNano(); + long millis = nanos / (1000 * 1000); + statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + "} executed. " - + sql); + + sql + " (" + millis + " milliseconds)"); } } + @Override + protected void statementExecuteBatchBefore(StatementProxy statement) { + statement.setLastExecuteStartNano(); + } + @Override protected void statementExecuteBatchAfter(StatementProxy statement, int[] result) { if (statementExecuteBatchAfterLogEnable && isStatementLogEnabled()) { + statement.setLastExecuteTimeNano(); + long nanos = statement.getLastExecuteTimeNano(); + long millis = nanos / (1000 * 1000); + String sql; if (statement instanceof PreparedStatementProxy) { sql = ((PreparedStatementProxy) statement).getSql(); @@ -396,13 +410,13 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM } statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) - + "} batch executed. " + sql); + + "} batch executed. " + sql + " (" + millis + " milliseconds)"); } } @Override protected void statementExecuteQueryBefore(StatementProxy statement, String sql) { - + statement.setLastExecuteStartNano(); if (statement instanceof PreparedStatementProxy) { logParameter((PreparedStatementProxy) statement); } @@ -411,14 +425,18 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM @Override protected void statementExecuteQueryAfter(StatementProxy statement, String sql, ResultSetProxy resultSet) { if (statementExecuteQueryAfterLogEnable && isStatementLogEnabled()) { + statement.setLastExecuteTimeNano(); + long nanos = statement.getLastExecuteTimeNano(); + long millis = nanos / (1000 * 1000); + statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + ", rs-" - + resultSet.getId() + "} query executed. " + sql); + + resultSet.getId() + "} query executed. " + sql + " (" + millis + " milliseconds)"); } } @Override protected void statementExecuteUpdateBefore(StatementProxy statement, String sql) { - + statement.setLastExecuteStartNano(); if (statement instanceof PreparedStatementProxy) { logParameter((PreparedStatementProxy) statement); } @@ -427,8 +445,12 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM @Override protected void statementExecuteUpdateAfter(StatementProxy statement, String sql, int updateCount) { if (statementExecuteUpdateAfterLogEnable && isStatementLogEnabled()) { + statement.setLastExecuteTimeNano(); + long nanos = statement.getLastExecuteTimeNano(); + long millis = nanos / (1000 * 1000); + statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) - + "} update executed. effort " + updateCount + ". " + sql); + + "} update executed. effort " + updateCount + ". " + sql + " (" + millis + " milliseconds)"); } } diff --git a/src/main/java/com/alibaba/druid/filter/stat/StatFilter.java b/src/main/java/com/alibaba/druid/filter/stat/StatFilter.java index 4468011c8f..06e15e3f90 100644 --- a/src/main/java/com/alibaba/druid/filter/stat/StatFilter.java +++ b/src/main/java/com/alibaba/druid/filter/stat/StatFilter.java @@ -376,18 +376,13 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean { } private final void internalBeforeStatementExecute(StatementProxy statement, String sql) { - - final long startNano = System.nanoTime(); - JdbcDataSourceStat dataSourceStat = statement.getConnectionProxy().getDirectDataSource().getDataSourceStat(); dataSourceStat.getStatementStat().beforeExecute(); - final JdbcStatementStat.Entry statementStat = getStatementInfo(statement); final ConnectionProxy connection = statement.getConnectionProxy(); final JdbcConnectionStat.Entry connectionCounter = getConnectionInfo(connection); - statementStat.setLastExecuteStartNano(startNano); - statementStat.setLastExecuteSql(sql); + statement.setLastExecuteStartNano(); connectionCounter.setLastSql(sql); @@ -426,17 +421,14 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean { } StatFilterContext.getInstance().executeBefore(sql, inTransaction); - + Profiler.enter(sql, Profiler.PROFILE_TYPE_SQL); } private final void internalAfterStatementExecute(StatementProxy statement, boolean firstResult, int... updateCountArray) { - - final JdbcStatementStat.Entry entry = getStatementInfo(statement); - final long nowNano = System.nanoTime(); - final long nanos = nowNano - entry.getLastExecuteStartNano(); + final long nanos = nowNano - statement.getLastExecuteStartNano(); JdbcDataSourceStat dataSourceStat = statement.getConnectionProxy().getDirectDataSource().getDataSourceStat(); dataSourceStat.getStatementStat().afterExecute(nanos); @@ -485,11 +477,10 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean { @Override protected void statement_executeErrorAfter(StatementProxy statement, String sql, Throwable error) { - JdbcStatementStat.Entry counter = getStatementInfo(statement); ConnectionProxy connection = statement.getConnectionProxy(); JdbcConnectionStat.Entry connectionCounter = getConnectionInfo(connection); - long nanos = System.nanoTime() - counter.getLastExecuteStartNano(); + long nanos = System.nanoTime() - statement.getLastExecuteStartNano(); JdbcDataSourceStat dataSourceStat = statement.getConnectionProxy().getDirectDataSource().getDataSourceStat(); dataSourceStat.getStatementStat().error(error); @@ -618,17 +609,6 @@ public class StatFilter extends FilterEventAdapter implements StatFilterMBean { return counter; } - public JdbcStatementStat.Entry getStatementInfo(StatementProxy statement) { - JdbcStatementStat.Entry counter = (JdbcStatementStat.Entry) statement.getAttributes().get(ATTR_NAME_STATEMENT_STAT); - - if (counter == null) { - statement.getAttributes().put(ATTR_NAME_STATEMENT_STAT, new JdbcStatementStat.Entry()); - counter = (JdbcStatementStat.Entry) statement.getAttributes().get(ATTR_NAME_STATEMENT_STAT); - } - - return counter; - } - public JdbcSqlStat createSqlStat(StatementProxy statement, String sql) { DataSourceProxy dataSource = statement.getConnectionProxy().getDirectDataSource(); JdbcDataSourceStat dataSourceStat = dataSource.getDataSourceStat(); diff --git a/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxy.java b/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxy.java index 9a11baddf6..aa6a0d9b16 100644 --- a/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxy.java +++ b/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxy.java @@ -42,8 +42,13 @@ public interface StatementProxy extends Statement, WrapperProxy { String getLastExecuteSql(); + long getLastExecuteStartNano(); + void setLastExecuteStartNano(long lastExecuteStartNano); + void setLastExecuteStartNano(); + long getLastExecuteTimeNano(); void setLastExecuteTimeNano(long nano); + void setLastExecuteTimeNano(); Map getParameters(); diff --git a/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java b/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java index 4eeba26887..d18ec0c8e1 100644 --- a/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java +++ b/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java @@ -39,7 +39,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro private final Statement statement; protected String lastExecuteSql; + private long lastExecuteStartNano; private long lastExecuteTimeNano; + protected JdbcSqlStat sqlStat; protected boolean firstResultSet; @@ -144,11 +146,11 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro firstResultSet = false; lastExecuteType = StatementExecuteType.ExecuteBatch; int[] updateCounts = createChain().statement_executeBatch(this); - + if (updateCounts != null && updateCounts.length == 1) { updateCount = updateCounts[0]; } - + return updateCounts; } @@ -264,13 +266,13 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro return createChain().statement_getResultSetType(this); } - //bug fixed for oracle + // bug fixed for oracle @Override public int getUpdateCount() throws SQLException { if (updateCount == null) { updateCount = createChain().statement_getUpdateCount(this); } - return updateCount; + return updateCount; } @Override @@ -391,6 +393,27 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro public void setLastExecuteTimeNano(long lastExecuteTimeNano) { this.lastExecuteTimeNano = lastExecuteTimeNano; } + + public void setLastExecuteTimeNano() { + if (this.lastExecuteTimeNano <= 0 && this.lastExecuteStartNano > 0) { + this.lastExecuteTimeNano = System.nanoTime() - this.lastExecuteStartNano; + } + } + + public long getLastExecuteStartNano() { + return lastExecuteStartNano; + } + + public void setLastExecuteStartNano(long lastExecuteStartNano) { + this.lastExecuteStartNano = lastExecuteStartNano; + this.lastExecuteTimeNano = -1L; + } + + public void setLastExecuteStartNano() { + if (lastExecuteStartNano <= 0) { + setLastExecuteStartNano(System.nanoTime()); + } + } public StatementExecuteType getLastExecuteType() { return lastExecuteType; diff --git a/src/main/java/com/alibaba/druid/stat/JdbcStatementStat.java b/src/main/java/com/alibaba/druid/stat/JdbcStatementStat.java index 9b4c7fd84d..aec961b0d6 100644 --- a/src/main/java/com/alibaba/druid/stat/JdbcStatementStat.java +++ b/src/main/java/com/alibaba/druid/stat/JdbcStatementStat.java @@ -202,26 +202,4 @@ public class JdbcStatementStat implements JdbcStatementStatMBean { public void incrementStatementCloseCounter() { closeCount.incrementAndGet(); } - - public static class Entry { - - private long lastExecuteStartNano; - private String lastExecuteSql; - - public long getLastExecuteStartNano() { - return lastExecuteStartNano; - } - - public void setLastExecuteStartNano(long lastExecuteStartNano) { - this.lastExecuteStartNano = lastExecuteStartNano; - } - - public String getLastExecuteSql() { - return lastExecuteSql; - } - - public void setLastExecuteSql(String lastExecuteSql) { - this.lastExecuteSql = lastExecuteSql; - } - } } From 5a0740fcc87899ee5e4bae29c3bd32040a910bc4 Mon Sep 17 00:00:00 2001 From: wenshao Date: Tue, 27 Nov 2012 13:22:05 +0800 Subject: [PATCH 2/4] improve LogFilter --- .../druid/filter/logging/LogFilter.java | 16 ++++---- .../druid/proxy/jdbc/StatementProxyImpl.java | 31 +++++++++++++- .../druid/bvt/filter/log/LogFilterTest.java | 40 +++++++++++++++++++ 3 files changed, 78 insertions(+), 9 deletions(-) create mode 100644 src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest.java diff --git a/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java b/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java index 684308423c..14ad2bd491 100644 --- a/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java +++ b/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java @@ -382,8 +382,8 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM protected void statementExecuteAfter(StatementProxy statement, String sql, boolean firstResult) { if (statementExecuteAfterLogEnable && isStatementLogEnabled()) { statement.setLastExecuteTimeNano(); - long nanos = statement.getLastExecuteTimeNano(); - long millis = nanos / (1000 * 1000); + double nanos = statement.getLastExecuteTimeNano(); + double millis = nanos / (1000 * 1000); statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + "} executed. " + sql + " (" + millis + " milliseconds)"); @@ -399,8 +399,8 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM protected void statementExecuteBatchAfter(StatementProxy statement, int[] result) { if (statementExecuteBatchAfterLogEnable && isStatementLogEnabled()) { statement.setLastExecuteTimeNano(); - long nanos = statement.getLastExecuteTimeNano(); - long millis = nanos / (1000 * 1000); + double nanos = statement.getLastExecuteTimeNano(); + double millis = nanos / (1000 * 1000); String sql; if (statement instanceof PreparedStatementProxy) { @@ -426,8 +426,8 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM protected void statementExecuteQueryAfter(StatementProxy statement, String sql, ResultSetProxy resultSet) { if (statementExecuteQueryAfterLogEnable && isStatementLogEnabled()) { statement.setLastExecuteTimeNano(); - long nanos = statement.getLastExecuteTimeNano(); - long millis = nanos / (1000 * 1000); + double nanos = statement.getLastExecuteTimeNano(); + double millis = nanos / (1000 * 1000); statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + ", rs-" + resultSet.getId() + "} query executed. " + sql + " (" + millis + " milliseconds)"); @@ -446,8 +446,8 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM protected void statementExecuteUpdateAfter(StatementProxy statement, String sql, int updateCount) { if (statementExecuteUpdateAfterLogEnable && isStatementLogEnabled()) { statement.setLastExecuteTimeNano(); - long nanos = statement.getLastExecuteTimeNano(); - long millis = nanos / (1000 * 1000); + double nanos = statement.getLastExecuteTimeNano(); + double millis = nanos / (1000 * 1000); statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + "} update executed. effort " + updateCount + ". " + sql + " (" + millis + " milliseconds)"); diff --git a/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java b/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java index d18ec0c8e1..d97c2d8aa6 100644 --- a/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java +++ b/src/main/java/com/alibaba/druid/proxy/jdbc/StatementProxyImpl.java @@ -109,7 +109,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro updateCount = null; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.Execute; - + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + firstResultSet = createChain().statement_execute(this, sql); return firstResultSet; } @@ -119,6 +121,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro updateCount = null; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.Execute; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + firstResultSet = createChain().statement_execute(this, sql, autoGeneratedKeys); return firstResultSet; } @@ -128,6 +133,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro updateCount = null; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.Execute; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + firstResultSet = createChain().statement_execute(this, sql, columnIndexes); return firstResultSet; } @@ -137,6 +145,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro updateCount = null; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.Execute; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + firstResultSet = createChain().statement_execute(this, sql, columnNames); return firstResultSet; } @@ -145,6 +156,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro public int[] executeBatch() throws SQLException { firstResultSet = false; lastExecuteType = StatementExecuteType.ExecuteBatch; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + int[] updateCounts = createChain().statement_executeBatch(this); if (updateCounts != null && updateCounts.length == 1) { @@ -160,6 +174,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro updateCount = null; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.ExecuteQuery; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + return createChain().statement_executeQuery(this, sql); } @@ -168,6 +185,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro firstResultSet = false; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.ExecuteUpdate; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + updateCount = createChain().statement_executeUpdate(this, sql); return updateCount; } @@ -177,6 +197,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro firstResultSet = false; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.ExecuteUpdate; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + updateCount = createChain().statement_executeUpdate(this, sql, autoGeneratedKeys); return updateCount; } @@ -186,6 +209,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro firstResultSet = false; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.ExecuteUpdate; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + updateCount = createChain().statement_executeUpdate(this, sql, columnIndexes); return updateCount; } @@ -195,6 +221,9 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro firstResultSet = false; lastExecuteSql = sql; lastExecuteType = StatementExecuteType.ExecuteUpdate; + lastExecuteStartNano = -1L; + lastExecuteTimeNano = -1L; + updateCount = createChain().statement_executeUpdate(this, sql, columnNames); return updateCount; } diff --git a/src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest.java b/src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest.java new file mode 100644 index 0000000000..97b6daed0b --- /dev/null +++ b/src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest.java @@ -0,0 +1,40 @@ +package com.alibaba.druid.bvt.filter.log; + +import java.sql.Connection; +import java.sql.ResultSet; +import java.sql.Statement; + +import junit.framework.TestCase; + +import com.alibaba.druid.pool.DruidDataSource; +import com.alibaba.druid.util.JdbcUtils; + +public class LogFilterTest extends TestCase { + + private DruidDataSource dataSource; + + protected void setUp() throws Exception { + dataSource = new DruidDataSource(); + dataSource.setUrl("jdbc:derby:classpath:petstore-db"); + dataSource.setFilters("log4j"); + } + + public void test_select() throws Exception { + Connection conn = dataSource.getConnection(); + + Statement stmt = conn.createStatement(); + + for (int i = 0; i < 10; ++i) { + ResultSet rs = stmt.executeQuery("SELECT * FROM ITEM WHERE LISTPRICE > 10"); + rs.close(); + } + + stmt.close(); + + conn.close(); + } + + protected void tearDown() throws Exception { + JdbcUtils.close(dataSource); + } +} From ba1d978f9e60247958f587cbd3f42230b66507a8 Mon Sep 17 00:00:00 2001 From: wenshao Date: Tue, 27 Nov 2012 14:44:32 +0800 Subject: [PATCH 3/4] improve LogFilter --- .../druid/filter/logging/LogFilter.java | 8 ++-- .../druid/bvt/filter/log/LogFilterTest2.java | 40 +++++++++++++++++++ .../bvt/hibernate/HibernateCRUDTest.java | 1 + 3 files changed, 45 insertions(+), 4 deletions(-) create mode 100644 src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest2.java diff --git a/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java b/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java index 14ad2bd491..86a9823eb1 100644 --- a/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java +++ b/src/main/java/com/alibaba/druid/filter/logging/LogFilter.java @@ -386,7 +386,7 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM double millis = nanos / (1000 * 1000); statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + "} executed. " - + sql + " (" + millis + " milliseconds)"); + + millis + " millis. " + sql); } } @@ -410,7 +410,7 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM } statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) - + "} batch executed. " + sql + " (" + millis + " milliseconds)"); + + "} batch executed. " + millis + " millis. " + sql); } } @@ -430,7 +430,7 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM double millis = nanos / (1000 * 1000); statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + ", rs-" - + resultSet.getId() + "} query executed. " + sql + " (" + millis + " milliseconds)"); + + resultSet.getId() + "} query executed. " + millis + " millis. " + sql); } } @@ -450,7 +450,7 @@ public abstract class LogFilter extends FilterEventAdapter implements LogFilterM double millis = nanos / (1000 * 1000); statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) - + "} update executed. effort " + updateCount + ". " + sql + " (" + millis + " milliseconds)"); + + "} update executed. effort " + updateCount + ". " + millis + " millis. " + sql); } } diff --git a/src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest2.java b/src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest2.java new file mode 100644 index 0000000000..b7260e8366 --- /dev/null +++ b/src/test/java/com/alibaba/druid/bvt/filter/log/LogFilterTest2.java @@ -0,0 +1,40 @@ +package com.alibaba.druid.bvt.filter.log; + +import java.sql.Connection; +import java.sql.PreparedStatement; +import java.sql.ResultSet; + +import junit.framework.TestCase; + +import com.alibaba.druid.pool.DruidDataSource; +import com.alibaba.druid.util.JdbcUtils; + +public class LogFilterTest2 extends TestCase { + + private DruidDataSource dataSource; + + protected void setUp() throws Exception { + dataSource = new DruidDataSource(); + dataSource.setUrl("jdbc:derby:classpath:petstore-db"); + dataSource.setFilters("log4j"); + } + + public void test_select() throws Exception { + Connection conn = dataSource.getConnection(); + + PreparedStatement stmt = conn.prepareStatement("SELECT * FROM ITEM WHERE LISTPRICE > 10"); + + for (int i = 0; i < 10; ++i) { + ResultSet rs = stmt.executeQuery(); + rs.close(); + } + + stmt.close(); + + conn.close(); + } + + protected void tearDown() throws Exception { + JdbcUtils.close(dataSource); + } +} diff --git a/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java b/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java index 2bf0f7bb95..cab0b5c9f5 100644 --- a/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java +++ b/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java @@ -34,6 +34,7 @@ public class HibernateCRUDTest extends TestCase { dataSource.setUsername("sa"); dataSource.setPassword(""); dataSource.setDefaultAutoCommit(false); + dataSource.setFilters("log4j"); /*init sessionFactory*/ LocalSessionFactoryBean factoryBean = new LocalSessionFactoryBean(); From 8559ab6ce951a579855b560f7650b72f6c99ffa4 Mon Sep 17 00:00:00 2001 From: wenshao Date: Wed, 28 Nov 2012 20:25:57 +0800 Subject: [PATCH 4/4] bug fixed for discardConnection --- .../alibaba/druid/pool/DruidDataSource.java | 4 + .../bvt/hibernate/HibernateCRUDTest.java | 14 +- .../alibaba/druid/bvt/pool/DiscardTest.java | 129 ++++++++++++++++++ 3 files changed, 142 insertions(+), 5 deletions(-) create mode 100644 src/test/java/com/alibaba/druid/bvt/pool/DiscardTest.java diff --git a/src/main/java/com/alibaba/druid/pool/DruidDataSource.java b/src/main/java/com/alibaba/druid/pool/DruidDataSource.java index f7830e468f..9de9fa994a 100644 --- a/src/main/java/com/alibaba/druid/pool/DruidDataSource.java +++ b/src/main/java/com/alibaba/druid/pool/DruidDataSource.java @@ -710,6 +710,10 @@ public class DruidDataSource extends DruidAbstractDataSource implements DruidDat try { activeCount--; discardCount++; + + if (activeCount <= 0) { + empty.signal(); + } } finally { lock.unlock(); } diff --git a/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java b/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java index cab0b5c9f5..6872027a9d 100644 --- a/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java +++ b/src/test/java/com/alibaba/druid/bvt/hibernate/HibernateCRUDTest.java @@ -1,8 +1,11 @@ package com.alibaba.druid.bvt.hibernate; -import com.alibaba.druid.bvt.hibernate.entity.Sample; -import com.alibaba.druid.pool.DruidDataSource; +import java.io.IOException; +import java.util.Date; +import java.util.Properties; + import junit.framework.TestCase; + import org.hibernate.Session; import org.hibernate.SessionFactory; import org.hibernate.Transaction; @@ -10,9 +13,9 @@ import org.slf4j.Logger; import org.slf4j.LoggerFactory; import org.springframework.orm.hibernate4.LocalSessionFactoryBean; -import java.io.IOException; -import java.util.Date; -import java.util.Properties; +import com.alibaba.druid.bvt.hibernate.entity.Sample; +import com.alibaba.druid.pool.DruidDataSource; +import com.alibaba.druid.util.JdbcUtils; /** * @author yinheli @@ -59,6 +62,7 @@ public class HibernateCRUDTest extends TestCase { @Override public void tearDown() throws Exception { sessionFactory.close(); + JdbcUtils.close(dataSource); } private void doCreate(Session session) { diff --git a/src/test/java/com/alibaba/druid/bvt/pool/DiscardTest.java b/src/test/java/com/alibaba/druid/bvt/pool/DiscardTest.java new file mode 100644 index 0000000000..0f700c3f84 --- /dev/null +++ b/src/test/java/com/alibaba/druid/bvt/pool/DiscardTest.java @@ -0,0 +1,129 @@ +package com.alibaba.druid.bvt.pool; + +import java.sql.Connection; +import java.sql.ResultSet; +import java.sql.SQLException; +import java.sql.Statement; +import java.util.Properties; +import java.util.concurrent.CountDownLatch; + +import junit.framework.Assert; +import junit.framework.TestCase; + +import com.alibaba.druid.mock.MockDriver; +import com.alibaba.druid.mock.MockStatementBase; +import com.alibaba.druid.pool.DruidDataSource; +import com.alibaba.druid.pool.vendor.MySqlExceptionSorter; +import com.alibaba.druid.util.JdbcUtils; + +public class DiscardTest extends TestCase { + + private DruidDataSource dataSource; + + private MockDriver driver; + + private volatile boolean failed = false; + + protected void setUp() throws Exception { + driver = new MockDriver() { + + public ResultSet executeQuery(MockStatementBase stmt, String sql) throws SQLException { + if (failed) { + throw new SQLException("", "", 1040); + } + return super.executeQuery(stmt, sql); + } + + public Connection connect(String url, Properties info) throws SQLException { + while (failed) { + try { + Thread.sleep(1); + } catch (InterruptedException e) { + throw new SQLException(e.getMessage(), e); + } + } + + return super.connect(url, info); + } + }; + + dataSource = new DruidDataSource(); + dataSource.setUrl("jdbc:mock:xxx"); + dataSource.setTestOnBorrow(false); + dataSource.setDriver(driver); + dataSource.setDbType("mysql"); + dataSource.setMinIdle(1); + dataSource.setMaxActive(1); + dataSource.setFilters("log4j"); + dataSource.setExceptionSorter(new MySqlExceptionSorter()); + } + + protected void tearDown() throws Exception { + dataSource.close(); + } + + public void test_db_fail() throws Exception { + exec(); + + final int THREAD_COUNT = 10; + final CountDownLatch endLatch = new CountDownLatch(THREAD_COUNT); + + Thread[] threads = new Thread[THREAD_COUNT]; + + { + Exception error = null; + + Connection conn = dataSource.getConnection(); + Statement stmt = conn.createStatement(); + + for (int i = 0; i < THREAD_COUNT; ++i) { + threads[i] = new Thread() { + + public void run() { + try { + exec(); + } finally { + endLatch.countDown(); + } + } + }; + threads[i].start(); + } + + this.failed = true; + try { + ResultSet rs = stmt.executeQuery("select 1"); + rs.close(); + } catch (SQLException e) { + error = e; + } + + stmt.close(); + conn.close(); + + Assert.assertNotNull(error); + } + + this.failed = false; + + endLatch.await(); + } + + private void exec() { + Connection conn = null; + Statement stmt = null; + ResultSet rs = null; + + try { + conn = dataSource.getConnection(); + stmt = conn.createStatement(); + rs = stmt.executeQuery("select 1"); + } catch (Exception ex) { + ex.printStackTrace(); + } finally { + JdbcUtils.close(rs); + JdbcUtils.close(stmt); + JdbcUtils.close(conn); + } + } +}