From: fhanik Date: Fri, 12 Dec 2008 01:26:39 +0000 (+0000) Subject: Implement JMX notification of query times and query failures X-Git-Url: https://git.internetallee.de/?a=commitdiff_plain;h=817d61f3ed0110154df1ccb7316794017fbe99ae;p=tomcat7.0 Implement JMX notification of query times and query failures git-svn-id: https://svn.apache.org/repos/asf/tomcat/trunk@725879 13f79535-47bb-0310-9956-ffa450edef68 --- diff --git a/modules/jdbc-pool/build.xml b/modules/jdbc-pool/build.xml index 6bd326686..e8f0178e8 100644 --- a/modules/jdbc-pool/build.xml +++ b/modules/jdbc-pool/build.xml @@ -102,6 +102,9 @@ + + + diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java index 51130344c..f4b14f7f1 100644 --- a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/ConnectionPool.java @@ -350,7 +350,9 @@ public class ConnectionPool { }catch (Exception x) { log.warn("Unable to inform interceptor of pool start.",x); close(true); - throw new SQLException(x); + SQLException ex = new SQLException(); + ex.initCause(x); + throw ex; } } //initialize the pool with its initial set of members @@ -477,7 +479,7 @@ public class ConnectionPool { } //while } - protected PooledConnection createConnection(long now, PooledConnection con) { + protected PooledConnection createConnection(long now, PooledConnection con) throws SQLException { //no connections where available we'll create one boolean error = false; try { @@ -502,7 +504,15 @@ public class ConnectionPool { } //end if } catch (Exception e) { error = true; - log.error("Unable to create a new JDBC connection.", e); + if (log.isDebugEnabled()) + log.debug("Unable to create a new JDBC connection.", e); + if (e instanceof SQLException) { + throw (SQLException)e; + } else { + SQLException ex = new SQLException(e.getMessage()); + ex.initCause(e); + throw ex; + } } finally { if (error ) { release(con); diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PoolProperties.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PoolProperties.java index d0dc7b33c..163e14b35 100644 --- a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PoolProperties.java +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PoolProperties.java @@ -54,7 +54,7 @@ public class PoolProperties { protected int removeAbandonedTimeout = 60; protected boolean logAbandoned = false; protected int loginTimeout = 10000; - protected String name = "Tomcat Connection Pool["+(poolCounter.addAndGet(1))+":"+System.identityHashCode(PoolProperties.class)+"]"; + protected String name = "Tomcat Connection Pool["+(poolCounter.addAndGet(1))+"-"+System.identityHashCode(PoolProperties.class)+"]"; protected String password; protected String username; protected long validationInterval = 30000; diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PooledConnection.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PooledConnection.java index d79e7de2c..ef05fb660 100644 --- a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PooledConnection.java +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/PooledConnection.java @@ -73,8 +73,12 @@ public class PooledConnection { driver = (java.sql.Driver) Class.forName(poolProperties.getDriverClassName(), true, PooledConnection.class.getClassLoader()).newInstance(); } catch (java.lang.Exception cn) { - log.error("Unable to instantiate JDBC driver.", cn); - throw new SQLException(cn.getMessage()); + if (log.isDebugEnabled()) { + log.debug("Unable to instantiate JDBC driver.", cn); + } + SQLException ex = new SQLException(cn.getMessage()); + ex.initCause(cn); + throw ex; } String driverURL = poolProperties.getUrl(); String usr = poolProperties.getUsername(); 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 0f3d15ff7..082ce53ea 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 @@ -27,6 +27,12 @@ import java.sql.Statement; import java.util.Iterator; import java.util.concurrent.ConcurrentHashMap; +import javax.management.openmbean.CompositeDataSupport; +import javax.management.openmbean.CompositeType; +import javax.management.openmbean.OpenDataException; +import javax.management.openmbean.OpenType; +import javax.management.openmbean.SimpleType; + import org.apache.juli.logging.Log; import org.apache.juli.logging.LogFactory; import org.apache.tomcat.jdbc.pool.ConnectionPool; @@ -197,7 +203,7 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { super.poolClosed(pool); } - protected void reportFailedQuery(String query, Object[] args, final String name, long start, Throwable t) { + protected String 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' @@ -209,9 +215,10 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { QueryStats qs = getQueryStats(sql); if (qs!=null) qs.failure(System.currentTimeMillis()-start,start); } + return sql; } - protected void reportSlowQuery(String query, Object[] args, final String name, long start, long delta) { + protected String 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' @@ -223,6 +230,7 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { QueryStats qs = getQueryStats(sql); if (qs!=null) qs.add(delta,start); } + return sql; } protected QueryStats getQueryStats(String sql) { @@ -274,6 +282,48 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { * */ public static class QueryStats { + static final String[] FIELD_NAMES = new String[] { + "query", + "nrOfInvocations", + "maxInvocationTime", + "maxInvocationDate", + "minInvocationTime", + "minInvocationDate", + "totalInvocationTime", + "failures", + "prepareCount", + "prepareTime", + "lastInvocation" + }; + + static final String[] FIELD_DESCRIPTIONS = new String[] { + "The SQL query", + "The number of query invocations, a call to executeXXX", + "The longest time for this query in milliseconds", + "The time and date for when the longest query took place", + "The shortest time for this query in milliseconds", + "The time and date for when the shortest query took place", + "The total amount of milliseconds spent executing this query", + "The number of failures for this query", + "The number of times this query was prepared (prepareStatement/prepareCall)", + "The total number of milliseconds spent preparing this query", + "The date and time of the last invocation" + }; + + static final OpenType[] FIELD_TYPES = new OpenType[] { + SimpleType.STRING, + SimpleType.INTEGER, + SimpleType.LONG, + SimpleType.LONG, + SimpleType.LONG, + SimpleType.LONG, + SimpleType.LONG, + SimpleType.LONG, + SimpleType.INTEGER, + SimpleType.LONG, + SimpleType.LONG + }; + private final String query; private int nrOfInvocations; private long maxInvocationTime = Long.MIN_VALUE; @@ -286,6 +336,18 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { private long prepareTime; private volatile long lastInvocation = 0; + public static String[] getFieldNames() { + return FIELD_NAMES; + } + + public static String[] getFieldDescriptions() { + return FIELD_DESCRIPTIONS; + } + + public static OpenType[] getFieldTypes() { + return FIELD_TYPES; + } + public String toString() { StringBuffer buf = new StringBuffer("QueryStats[query:"); buf.append(query); @@ -313,6 +375,23 @@ public class SlowQueryReport extends AbstractCreateStatementInterceptor { return buf.toString(); } + public CompositeDataSupport getCompositeData(final CompositeType type) throws OpenDataException{ + Object[] values = new Object[] { + query, + nrOfInvocations, + maxInvocationTime, + maxInvocationDate, + minInvocationTime, + minInvocationDate, + totalInvocationTime, + failures, + prepareCount, + prepareTime, + lastInvocation + }; + return new CompositeDataSupport(type,FIELD_NAMES,values); + } + public QueryStats(String query) { this.query = query; } diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java new file mode 100644 index 000000000..dc776eef3 --- /dev/null +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/SlowQueryReportJmx.java @@ -0,0 +1,249 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.tomcat.jdbc.pool.interceptor; + +import java.util.Iterator; +import java.util.Map; +import java.util.Set; +import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.atomic.AtomicLong; + +import javax.management.DynamicMBean; +import javax.management.InstanceAlreadyExistsException; +import javax.management.InstanceNotFoundException; +import javax.management.MBeanException; +import javax.management.MalformedObjectNameException; +import javax.management.NotCompliantMBeanException; +import javax.management.Notification; +import javax.management.ObjectName; +import javax.management.RuntimeOperationsException; +import javax.management.modelmbean.InvalidTargetObjectTypeException; +import javax.management.openmbean.CompositeData; +import javax.management.openmbean.CompositeDataSupport; +import javax.management.openmbean.CompositeType; +import javax.management.openmbean.OpenDataException; + +import org.apache.juli.logging.Log; +import org.apache.juli.logging.LogFactory; +import org.apache.tomcat.jdbc.pool.ConnectionPool; +import org.apache.tomcat.jdbc.pool.PooledConnection; +import org.apache.tomcat.util.modeler.BaseModelMBean; +import org.apache.tomcat.util.modeler.ManagedBean; +import org.apache.tomcat.util.modeler.Registry; +/** + * Publishes data to JMX and provides notifications + * when failures happen. + * @author fhanik + * + */ +public class SlowQueryReportJmx extends SlowQueryReport { + public static final String SLOW_QUERY_NOTIFICATION = "Slow query"; + public static final String FAILED_QUERY_NOTIFICATION = "Failed query"; + + protected static CompositeType SLOW_QUERY_TYPE; + + protected static Log log = LogFactory.getLog(SlowQueryReportJmx.class); + + + protected static ConcurrentHashMap mbeans = + new ConcurrentHashMap(); + + protected String poolName = null; + + protected static AtomicLong notifySequence = new AtomicLong(0); + + protected static CompositeType getCompositeType() { + if (SLOW_QUERY_TYPE==null) { + try { + SLOW_QUERY_TYPE = new CompositeType( + SlowQueryReportJmx.class.getName(), + "Composite data type for query statistics", + QueryStats.getFieldNames(), + QueryStats.getFieldDescriptions(), + QueryStats.getFieldTypes()); + }catch (OpenDataException x) { + log.warn("Unable to initialize composite data type for JMX stats and notifications.",x); + } + } + return SLOW_QUERY_TYPE; + } + + @Override + public void reset(ConnectionPool parent, PooledConnection con) { + // TODO Auto-generated method stub + super.reset(parent, con); + if (parent!=null) poolName = parent.getName(); + } + + + + @Override + public void poolClosed(ConnectionPool pool) { + this.poolName = pool.getName(); + deregisterJmx(); + super.poolClosed(pool); + } + + @Override + public void poolStarted(ConnectionPool pool) { + super.poolStarted(pool); + this.poolName = pool.getName(); + registerJmx(); + } + + @Override + protected String reportFailedQuery(String query, Object[] args, String name, long start, Throwable t) { + query = super.reportFailedQuery(query, args, name, start, t); + notifyJmx(query,FAILED_QUERY_NOTIFICATION); + return query; + } + + protected void notifyJmx(String query, String type) { + try { + DynamicMBean mbean = mbeans.get(poolName); + if (mbean!=null && mbean instanceof BaseModelMBean) { + BaseModelMBean bmbean = (BaseModelMBean)mbean; + long sequence = notifySequence.incrementAndGet(); + Notification notification = + new Notification(type, + mbean, + sequence, + System.currentTimeMillis(), + query); + bmbean.sendNotification(notification); + } + } catch (RuntimeOperationsException e) { + if (log.isDebugEnabled()) { + log.debug("Unable to send failed query notification.",e); + } + } catch (MBeanException e) { + if (log.isDebugEnabled()) { + log.debug("Unable to send failed query notification.",e); + } + } + } + + @Override + protected String reportSlowQuery(String query, Object[] args, String name, long start, long delta) { + query = super.reportSlowQuery(query, args, name, start, delta); + notifyJmx(query,SLOW_QUERY_NOTIFICATION); + return query; + } + + /** + * JMX operation - return the names of all the pools + * @return + */ + public String[] getPoolNames() { + Set keys = perPoolStats.keySet(); + return keys.toArray(new String[0]); + } + + /** + * JMX operation - return the name of the pool + * @return + */ + public String getPoolName() { + return poolName; + } + + /** + * JMX operation - remove all stats for this connection pool + */ + public void resetStats() { + ConcurrentHashMap queries = perPoolStats.get(poolName); + if (queries!=null) { + Iterator it = queries.keySet().iterator(); + while (it.hasNext()) it.remove(); + } + } + + /** + * JMX operation - returns all the queries we have collected. + * @return + */ + public CompositeData[] getSlowQueriesCD() throws OpenDataException { + CompositeDataSupport[] result = null; + ConcurrentHashMap queries = perPoolStats.get(poolName); + if (queries!=null) { + Set> stats = queries.entrySet(); + if (stats!=null) { + result = new CompositeDataSupport[stats.size()]; + Iterator> it = stats.iterator(); + int pos = 0; + while (it.hasNext()) { + Map.Entry entry = it.next(); + QueryStats qs = entry.getValue(); + result[pos++] = qs.getCompositeData(getCompositeType()); + } + } + } + return result; + } + + protected void deregisterJmx() { + try { + DynamicMBean mbean = null; + if ((mbean=mbeans.remove(poolName))!=null) { + Registry registry = Registry.getRegistry(null, null); + ManagedBean managed = registry.findManagedBean(this.getClass().getName()); + if (managed!=null) { + ObjectName oname = new ObjectName("org.apache.tomcat.jdbc.pool.jmx:type="+getClass().getName()+",name=" + poolName); + registry.unregisterComponent(oname); + registry.removeManagedBean(managed); + } + + } + } catch (MalformedObjectNameException e) { + log.warn("Jmx deregistration failed.",e); + } catch (RuntimeOperationsException e) { + log.warn("Jmx deregistration failed.",e); + } + + } + + protected void registerJmx() { + try { + if (getCompositeType()!=null) { + ObjectName oname = new ObjectName("org.apache.tomcat.jdbc.pool.jmx:type="+getClass().getName()+",name=" + poolName); + Registry registry = Registry.getRegistry(null, null); + registry.loadDescriptors(getClass().getPackage().getName(),getClass().getClassLoader()); + ManagedBean managed = registry.findManagedBean(this.getClass().getName()); + DynamicMBean mbean = managed!=null?managed.createMBean(this):null; + if (mbean!=null && mbeans.putIfAbsent(poolName, mbean)==null) { + registry.getMBeanServer().registerMBean( mbean, oname); + } else { + log.warn(SlowQueryReport.class.getName()+ "- No JMX support, composite type was not found."); + } + } else { + log.warn(SlowQueryReport.class.getName()+ "- No JMX support, composite type was not found."); + } + } catch (MalformedObjectNameException e) { + log.error("Jmx registration failed, no JMX data will be exposed for the query stats.",e); + } catch (InstanceNotFoundException e) { + log.error("Jmx registration failed, no JMX data will be exposed for the query stats.",e); + } catch (RuntimeOperationsException e) { + log.error("Jmx registration failed, no JMX data will be exposed for the query stats.",e); + } catch (MBeanException e) { + log.error("Jmx registration failed, no JMX data will be exposed for the query stats.",e); + } catch (InstanceAlreadyExistsException e) { + log.error("Jmx registration failed, no JMX data will be exposed for the query stats.",e); + } catch (NotCompliantMBeanException e) { + log.error("Jmx registration failed, no JMX data will be exposed for the query stats.",e); + } + } +} diff --git a/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/mbeans-descriptors.xml b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/mbeans-descriptors.xml new file mode 100644 index 000000000..1252cd109 --- /dev/null +++ b/modules/jdbc-pool/java/org/apache/tomcat/jdbc/pool/interceptor/mbeans-descriptors.xml @@ -0,0 +1,19 @@ + + + + + + + + + + + Slow query + + + + Failed query execution + + + \ No newline at end of file diff --git a/modules/jdbc-pool/test/org/apache/tomcat/jdbc/test/TestSlowQueryReport.java b/modules/jdbc-pool/test/org/apache/tomcat/jdbc/test/TestSlowQueryReport.java index 82ffe15c5..813a25a83 100644 --- a/modules/jdbc-pool/test/org/apache/tomcat/jdbc/test/TestSlowQueryReport.java +++ b/modules/jdbc-pool/test/org/apache/tomcat/jdbc/test/TestSlowQueryReport.java @@ -1,3 +1,19 @@ +/* + * Licensed to the Apache Software Foundation (ASF) under one or more + * contributor license agreements. See the NOTICE file distributed with + * this work for additional information regarding copyright ownership. + * The ASF licenses this file to You under the Apache License, Version 2.0 + * (the "License"); you may not use this file except in compliance with + * the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ package org.apache.tomcat.jdbc.test; import java.sql.CallableStatement; @@ -8,7 +24,7 @@ import java.sql.Statement; import java.util.Map; import org.apache.tomcat.jdbc.pool.ConnectionPool; -import org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReport; +import org.apache.tomcat.jdbc.pool.interceptor.SlowQueryReportJmx; public class TestSlowQueryReport extends DefaultTestCase { @@ -20,7 +36,7 @@ public class TestSlowQueryReport extends DefaultTestCase { int count = 3; this.init(); this.datasource.setMaxActive(1); - this.datasource.setJdbcInterceptors(SlowQueryReport.class.getName()); + this.datasource.setJdbcInterceptors(SlowQueryReportJmx.class.getName()); Connection con = this.datasource.getConnection(); String slowSql = "select count(1) from test where val1 like 'ewqeq' and val2 = 'ewrre' and val3 = 'sdada' and val4 = 'dadada'"; for (int i=0; i map = SlowQueryReport.getPoolStats(datasource.getPool().getName()); + Map map = SlowQueryReportJmx.getPoolStats(datasource.getPool().getName()); assertNotNull(map); assertEquals(1,map.size()); String key = map.keySet().iterator().next(); - SlowQueryReport.QueryStats stats = map.get(key); + SlowQueryReportJmx.QueryStats stats = map.get(key); System.out.println("Stats:"+stats); for (int i=0; i map = SlowQueryReport.getPoolStats(datasource.getPool().getName()); + Map map = SlowQueryReportJmx.getPoolStats(datasource.getPool().getName()); assertNotNull(map); assertEquals(0,map.size()); ConnectionPool pool = datasource.getPool(); con.close(); tearDown(); - assertNull(SlowQueryReport.getPoolStats(pool.getName())); + assertNull(SlowQueryReportJmx.getPoolStats(pool.getName())); } public void testFailedSql() throws Exception { int count = 3; this.init(); this.datasource.setMaxActive(1); - this.datasource.setJdbcInterceptors(SlowQueryReport.class.getName()); + this.datasource.setJdbcInterceptors(SlowQueryReportJmx.class.getName()); Connection con = this.datasource.getConnection(); String slowSql = "select 1 from non_existent"; int exceptionCount = 0; @@ -99,16 +115,16 @@ public class TestSlowQueryReport extends DefaultTestCase { st.close(); } - Map map = SlowQueryReport.getPoolStats(datasource.getPool().getName()); + Map map = SlowQueryReportJmx.getPoolStats(datasource.getPool().getName()); assertNotNull(map); assertEquals(1,map.size()); ConnectionPool pool = datasource.getPool(); String key = map.keySet().iterator().next(); - SlowQueryReport.QueryStats stats = map.get(key); + SlowQueryReportJmx.QueryStats stats = map.get(key); System.out.println("Stats:"+stats); con.close(); tearDown(); - assertNull(SlowQueryReport.getPoolStats(pool.getName())); + assertNull(SlowQueryReportJmx.getPoolStats(pool.getName())); }