From 41dcb5ea3dfe94d499ce5cdd2d983af4733c90fb Mon Sep 17 00:00:00 2001 From: fhanik Date: Thu, 11 Dec 2008 22:07:43 +0000 Subject: [PATCH] Refactor slow query report so that it is extensible and one can override the methods git-svn-id: https://svn.apache.org/repos/asf/tomcat/trunk@725836 13f79535-47bb-0310-9956-ffa450edef68 --- .../AbstractCreateStatementInterceptor.java | 6 +- .../jdbc/pool/interceptor/SlowQueryReport.java | 148 ++++++++++++++------- .../jdbc/pool/interceptor/StatementFinalizer.java | 2 +- 3 files changed, 104 insertions(+), 52 deletions(-) diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractCreateStatementInterceptor.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractCreateStatementInterceptor.java index 6ed063c00..e489c2819 100644 --- a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractCreateStatementInterceptor.java +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/AbstractCreateStatementInterceptor.java @@ -47,8 +47,10 @@ public abstract class AbstractCreateStatementInterceptor extends JdbcIntercepto boolean process = false; process = process(statements, method, process); if (process) { + long start = System.currentTimeMillis(); Object statement = super.invoke(proxy,method,args); - return createStatement(proxy,method,args,statement); + long delta = System.currentTimeMillis() - start; + return createStatement(proxy,method,args,statement, delta); } else { return super.invoke(proxy,method,args); } @@ -64,7 +66,7 @@ public abstract class AbstractCreateStatementInterceptor extends JdbcIntercepto * @param statement * @return */ - public abstract Object createStatement(Object proxy, Method method, Object[] args, Object statement); + public abstract Object createStatement(Object proxy, Method method, Object[] args, Object statement, long time); public abstract void closeInvoked(); diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java index 62b7f2ff4..f2359733a 100644 --- a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReport.java @@ -128,7 +128,7 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { * Creates a statement interceptor to monitor query response times */ @Override - public Object createStatement(Object proxy, Method method, Object[] args, Object statement) { + public Object createStatement(Object proxy, Method method, Object[] args, Object statement, long time) { try { Object result = null; String name = method.getName(); @@ -141,10 +141,18 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { //prepareStatement sql = (String)args[0]; constructor = getConstructor(1,PreparedStatement.class); + if (sql!=null) { + QueryStats qs = getQueryStats(sql); + qs.prepare(time, System.currentTimeMillis()); + } }else if (compare(statements[2],name)) { //prepareCall sql = (String)args[0]; constructor = getConstructor(2,CallableStatement.class); + if (sql!=null) { + QueryStats qs = getQueryStats(sql); + qs.prepare(time, System.currentTimeMillis()); + } }else { //do nothing, might be a future unsupported method //so we better bail out and let the system continue @@ -187,6 +195,66 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { perPoolStats.remove(pool.getName()); super.poolClosed(pool); } + + protected void reportFailedQuery(String query, Object[] args, final String name, long start, Throwable t) { + //extract the query string + String sql = (query==null && args!=null && args.length>0)?(String)args[0]:query; + //if we do batch execution, then we name the query 'batch' + if (sql==null && compare(executes[3],name)) { + sql = "batch"; + } + //if we have a query, record the stats + if (sql!=null) { + QueryStats qs = getQueryStats(sql); + if (qs!=null) qs.failure(System.currentTimeMillis()-start,start); + } + } + + protected void reportSlowQuery(String query, Object[] args, final String name, long start, long delta) { + //extract the query string + String sql = (query==null && args!=null && args.length>0)?(String)args[0]:query; + //if we do batch execution, then we name the query 'batch' + if (sql==null && compare(executes[3],name)) { + sql = "batch"; + } + //if we have a query, record the stats + if (sql!=null) { + QueryStats qs = getQueryStats(sql); + if (qs!=null) qs.add(delta,start); + } + } + + protected QueryStats getQueryStats(String sql) { + ConcurrentHashMap queries = SlowQueryReport.this.queries; + if (queries==null) return null; + QueryStats qs = queries.get(sql); + if (qs == null) { + qs = new QueryStats(sql); + if (queries.putIfAbsent(sql,qs)!=null) { + qs = queries.get(sql); + } else { + //we added a new element, see if we need to remove the oldest + if (queries.size() > maxQueries) { + removeOldest(queries); + } + } + } + return qs; + } + + /** + * TODO - implement a better algorithm + * @param queries + */ + protected void removeOldest(ConcurrentHashMap queries) { + Iterator it = queries.keySet().iterator(); + while (queries.size()>maxQueries && it.hasNext()) { + String sql = it.next(); + it.remove(); + if (log.isDebugEnabled()) log.debug("Removing slow query, capacity reached:"+sql); + } + } + /** * @@ -201,6 +269,9 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { private long minInvocationTime = Long.MAX_VALUE; private long minInvocationDate; private long totalInvocationTime; + private long failures; + private int prepareCount; + private long prepareTime; private volatile long lastInvocation = 0; public String toString() { @@ -220,6 +291,12 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { buf.append(totalInvocationTime); buf.append(", averageInvocationTime:"); buf.append((float)totalInvocationTime / (float)nrOfInvocations); + buf.append(", failures:"); + buf.append(failures); + buf.append(", prepareCount:"); + buf.append(prepareCount); + buf.append(", prepareTime:"); + buf.append(prepareTime); buf.append("]"); return buf.toString(); } @@ -228,6 +305,12 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { this.query = query; } + public void prepare(long invocationTime, long now) { + prepareCount++; + prepareTime+=invocationTime; + + } + public void add(long invocationTime, long now) { //not thread safe, but don't sacrifice performance for this kind of stuff maxInvocationTime = Math.max(invocationTime, maxInvocationTime); @@ -243,6 +326,12 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { lastInvocation = now; } + public void failure(long invocationTime, long now) { + add(invocationTime,now); + failures++; + + } + public String getQuery() { return query; } @@ -318,15 +407,21 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { process = process(executes, method, process); //if we are executing, get the current time long start = (process)?System.currentTimeMillis():0; - //execute the query - Object result = method.invoke(delegate,args); + Object result = null; + try { + //execute the query + result = method.invoke(delegate,args); + }catch (Throwable t) { + reportFailedQuery(query,args,name,start,t); + throw t; + } //measure the time long delta = (process)?(System.currentTimeMillis()-start):Long.MIN_VALUE; //see if we meet the requirements to measure if (delta>threshold) { try { //report the slow query - reportSlowQuery(args, name, start, delta); + reportSlowQuery(query, args, name, start, delta); }catch (Exception t) { if (log.isWarnEnabled()) log.warn("Unable to process slow query",t); } @@ -338,50 +433,5 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { } return result; } - - protected void reportSlowQuery(Object[] args, final String name, long start, long delta) { - //extract the query string - String sql = (query==null && args!=null && args.length>0)?(String)args[0]:query; - //if we do batch execution, then we name the query 'batch' - if (sql==null && compare(executes[3],name)) { - sql = "batch"; - } - //if we have a query, record the stats - if (sql!=null) { - QueryStats qs = getQueryStats(sql); - if (qs!=null) qs.add(delta,start); - } - } - - private QueryStats getQueryStats(String sql) { - ConcurrentHashMap queries = SlowQueryReport.this.queries; - if (queries==null) return null; - QueryStats qs = queries.get(sql); - if (qs == null) { - qs = new QueryStats(sql); - if (queries.putIfAbsent(sql,qs)!=null) { - qs = queries.get(sql); - } else { - //we added a new element, see if we need to remove the oldest - if (queries.size() > maxQueries) { - removeOldest(queries); - } - } - } - return qs; - } - - /** - * TODO - implement a better algorithm - * @param queries - */ - protected void removeOldest(ConcurrentHashMap queries) { - Iterator it = queries.keySet().iterator(); - while (queries.size()>maxQueries && it.hasNext()) { - String sql = it.next(); - it.remove(); - if (log.isDebugEnabled()) log.debug("Removing slow query, capacity reached:"+sql); - } - } } } diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java index e223032c1..51ae467cf 100644 --- a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/StatementFinalizer.java @@ -36,7 +36,7 @@ public class StatementFinalizer extends AbstractCreateStatementInterceptor { protected ArrayList> statements = new ArrayList>(); @Override - public Object createStatement(Object proxy, Method method, Object[] args, Object statement) { + public Object createStatement(Object proxy, Method method, Object[] args, Object statement, long time) { // TODO Auto-generated method stub try { statements.add(new WeakReference((Statement)statement)); -- 2.11.0