Merge pull request #210 from wenshao/master

bug fixed & improve LogFilter
This commit is contained in:
温高铁
2012-11-28 04:27:37 -08:00
10 changed files with 326 additions and 71 deletions
@@ -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();
double nanos = statement.getLastExecuteTimeNano();
double millis = nanos / (1000 * 1000);
statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + "} executed. "
+ sql);
+ millis + " millis. " + sql);
}
}
@Override
protected void statementExecuteBatchBefore(StatementProxy statement) {
statement.setLastExecuteStartNano();
}
@Override
protected void statementExecuteBatchAfter(StatementProxy statement, int[] result) {
if (statementExecuteBatchAfterLogEnable && isStatementLogEnabled()) {
statement.setLastExecuteTimeNano();
double nanos = statement.getLastExecuteTimeNano();
double 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. " + millis + " millis. " + sql);
}
}
@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();
double nanos = statement.getLastExecuteTimeNano();
double millis = nanos / (1000 * 1000);
statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement) + ", rs-"
+ resultSet.getId() + "} query executed. " + sql);
+ resultSet.getId() + "} query executed. " + millis + " millis. " + sql);
}
}
@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();
double nanos = statement.getLastExecuteTimeNano();
double millis = nanos / (1000 * 1000);
statementLog("{conn-" + statement.getConnectionProxy().getId() + ", " + stmtId(statement)
+ "} update executed. effort " + updateCount + ". " + sql);
+ "} update executed. effort " + updateCount + ". " + millis + " millis. " + sql);
}
}
@@ -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();
@@ -710,6 +710,10 @@ public class DruidDataSource extends DruidAbstractDataSource implements DruidDat
try {
activeCount--;
discardCount++;
if (activeCount <= 0) {
empty.signal();
}
} finally {
lock.unlock();
}
@@ -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<Integer, JdbcParameter> getParameters();
@@ -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;
@@ -107,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;
}
@@ -117,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;
}
@@ -126,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;
}
@@ -135,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;
}
@@ -143,12 +156,15 @@ public class StatementProxyImpl extends WrapperProxyImpl implements StatementPro
public int[] executeBatch() throws SQLException {
firstResultSet = false;
lastExecuteType = StatementExecuteType.ExecuteBatch;
int[] updateCounts = createChain().statement_executeBatch(this);
lastExecuteStartNano = -1L;
lastExecuteTimeNano = -1L;
int[] updateCounts = createChain().statement_executeBatch(this);
if (updateCounts != null && updateCounts.length == 1) {
updateCount = updateCounts[0];
}
return updateCounts;
}
@@ -158,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);
}
@@ -166,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;
}
@@ -175,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;
}
@@ -184,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;
}
@@ -193,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;
}
@@ -264,13 +295,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 +422,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;
@@ -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;
}
}
}
@@ -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);
}
}
@@ -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);
}
}
@@ -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 <yinheli@gmail.com>
@@ -34,6 +37,7 @@ public class HibernateCRUDTest extends TestCase {
dataSource.setUsername("sa");
dataSource.setPassword("");
dataSource.setDefaultAutoCommit(false);
dataSource.setFilters("log4j");
/*init sessionFactory*/
LocalSessionFactoryBean factoryBean = new LocalSessionFactoryBean();
@@ -58,6 +62,7 @@ public class HibernateCRUDTest extends TestCase {
@Override
public void tearDown() throws Exception {
sessionFactory.close();
JdbcUtils.close(dataSource);
}
private void doCreate(Session session) {
@@ -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);
}
}
}