From 619c007db9ff6f8fa7fd45394554b55f45acce75 Mon Sep 17 00:00:00 2001 From: wenshao Date: Tue, 27 Nov 2012 12:51:32 +0800 Subject: [PATCH] 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; - } - } }