Modified DataSource pool - cleanup of reset and statistics collection

This commit is contained in:
Rob Bygrave
2013-12-12 20:57:50 +13:00
parent 664f08fd6f
commit d16f33d26b
11 changed files with 852 additions and 452 deletions
@@ -42,14 +42,14 @@ public class DataSourceConfig {
private int leakTimeMinutes = 30;
private int maxInactiveTimeSecs = 900;
private int maxInactiveTimeSecs = 720;
private int pstmtCacheSize = 20;
private int cstmtCacheSize = 20;
private int waitTimeoutMillis = 1000;
private String poolListener;
private boolean offline;
@@ -5,6 +5,11 @@ import java.util.Arrays;
import java.util.Collections;
import java.util.List;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.avaje.ebeaninternal.server.lib.sql.PooledConnectionStatistics.LoadValues;
/**
* A buffer especially designed for Busy PooledConnections.
* <p>
@@ -21,6 +26,8 @@ import java.util.List;
*/
class BusyConnectionBuffer {
private static final Logger logger = LoggerFactory.getLogger(BusyConnectionBuffer.class);
private PooledConnection[] slots;
private int growBy;
@@ -66,8 +73,13 @@ class BusyConnectionBuffer {
return size;
}
protected boolean isEmpty(){
return size == 0;
protected boolean isEmpty() {
for (int i = 0; i < slots.length; i++) {
if (slots[i] != null) {
return false;
}
}
return true;
}
protected int add(PooledConnection pc){
@@ -75,23 +87,37 @@ class BusyConnectionBuffer {
// grow the capacity
setCapacity(slots.length + growBy);
}
++size;
int slot = nextEmptySlot();
pc.setSlotId(slot);
slots[slot] = pc;
return size;
return ++size;
}
protected boolean remove(PooledConnection pc) {
--size;
int slotId = pc.getSlotId();
if (slots[slotId] != pc){
PooledConnection heldBy = slots[slotId];
logger.warn("Failed to remove from slot[{}] PooledConnection[{}] - HeldBy[{}]", pc.getSlotId(), pc, heldBy);
return false;
}
slots[slotId] = null;
--size;
return true;
}
/**
* Collect the load statistics from all the busy connections.
* @param reset
*/
protected void collectStatistics(LoadValues values, boolean reset) {
for (int i = 0; i < slots.length; i++) {
if (slots[i] != null){
values.plus(slots[i].getStatistics().getValues(reset));
}
}
}
/**
* Get a shallow read only List of the busy connections.
@@ -15,11 +15,12 @@ import java.util.Set;
import javax.persistence.PersistenceException;
import javax.sql.DataSource;
import com.avaje.ebean.config.DataSourceConfig;
import com.avaje.ebeaninternal.api.ClassUtil;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.avaje.ebean.config.DataSourceConfig;
import com.avaje.ebeaninternal.api.ClassUtil;
/**
* A robust DataSource.
* <p>
@@ -73,7 +74,7 @@ public class DataSourcePool implements DataSource {
* The sql used to test a connection.
*/
private final String heartbeatsql;
private final int heartbeatFreqSecs;
/**
@@ -573,7 +574,15 @@ public class DataSourcePool implements DataSource {
}
queue.returnPooledConnection(pooledConnection);
}
/**
* Collect statistics of a connection that is fully closing
*/
protected void reportClosingConnection(PooledConnection pooledConnection) {
queue.reportClosingConnection(pooledConnection);
}
/**
* Returns information describing connections that are currently being used.
*/
@@ -834,6 +843,14 @@ public class DataSourcePool implements DataSource {
public Status getStatus(boolean reset) {
return queue.getStatus(reset);
}
/**
* Return the aggregated load statistics collected on all the connections in the pool.
*/
public DataSourcePoolStatistics getStatistics(boolean reset) {
return queue.getStatistics(reset);
}
/**
* Deregister the JDBC driver.
@@ -873,8 +890,8 @@ public class DataSourcePool implements DataSource {
}
public String toString() {
return "min:" + minSize + " max:" + maxSize + " free:" + free + " busy:" + busy + " waiting:" + waiting
+ " highWaterMark:" + highWaterMark + " waitCount:" + waitCount + " hitCount:" + hitCount;
return "min[" + minSize + "] max[" + maxSize + "] free[" + free + "] busy[" + busy + "] waiting[" + waiting
+ "] highWaterMark[" + highWaterMark + "] waitCount[" + waitCount + "] hitCount[" + hitCount+"]";
}
/**
@@ -0,0 +1,97 @@
package com.avaje.ebeaninternal.server.lib.sql;
/**
* Represents aggregated statistics collected from the DataSourcePool.
* <p>
* The goal is to present insight into the overload load of the DataSourcePool.
* These statistics can be collected and reported regularly to show load over
* time.
* </p>
* <p>
* Each pooled connection collects statistics. When a pooled connection is fully
* closed it can report it's statistics to the pool to be included as part of
* the collected statistics.
* </p>
*/
public class DataSourcePoolStatistics {
private final long collectionStart;
private final long count;
private final long errorCount;
private final long hwmMicros;
private final long totalMicros;
/**
* No statistics collected.
*/
public DataSourcePoolStatistics() {
this.collectionStart = 0;
this.count = 0;
this.errorCount = 0;
this.hwmMicros = 0;
this.totalMicros = 0;
}
/**
* Construct with statistics collected.
*/
public DataSourcePoolStatistics(long collectionStart, long count, long errorCount, long hwmMicros, long totalMicros) {
this.collectionStart = collectionStart;
this.count = count;
this.errorCount = errorCount;
this.hwmMicros = hwmMicros;
this.totalMicros = totalMicros;
}
public String toString() {
return "count[" + count + "] errors[" + errorCount + "] totalMicros[" + totalMicros + "] hwmMicros[" + hwmMicros
+ "] avgMicros[" + getAvgMicros() + "]";
}
/**
* Return the start time this set of statistics was collected from.
*/
public long getCollectionStart() {
return collectionStart;
}
/**
* Return the total number of 'get connection' requests.
*/
public long getCount() {
return count;
}
/**
* Return the number of SQLExceptions reported.
*/
public long getErrorCount() {
return errorCount;
}
/**
* Return the high water mark for the duration a connection was busy/used.
*/
public long getHwmMicros() {
return hwmMicros;
}
/**
* Return the aggregate time connections were busy/used.
*/
public long getTotalMicros() {
return totalMicros;
}
/**
* Return the average time connections were busy/used.
*/
public long getAvgMicros() {
return (totalMicros == 0) ? 0 : totalMicros / count;
}
}
@@ -31,18 +31,17 @@ public class ExtendedPreparedStatement extends ExtendedStatement implements Prep
/**
* The SQL used to create the underlying PreparedStatement.
*/
final String sql;
private final String sql;
/**
* The key used to cache this in the connection.
*/
final String cacheKey;
private final String cacheKey;
/**
* Create a wrapped PreparedStatement that can be cached.
*/
public ExtendedPreparedStatement(PooledConnection pooledConnection, PreparedStatement pstmt,
String sql, String cacheKey) {
public ExtendedPreparedStatement(PooledConnection pooledConnection, PreparedStatement pstmt, String sql, String cacheKey) {
super(pooledConnection, pstmt);
this.sql = sql;
this.cacheKey = cacheKey;
@@ -3,6 +3,8 @@ package com.avaje.ebeaninternal.server.lib.sql;
import java.util.ArrayList;
import java.util.List;
import com.avaje.ebeaninternal.server.lib.sql.PooledConnectionStatistics.LoadValues;
/**
* A buffer designed especially to hold free pooled connections.
* <p>
@@ -48,11 +50,31 @@ class FreeConnectionBuffer {
* Add at connection.
*/
protected void add(PooledConnection pc) {
if (conns[addIndex] != null) {
throw new RuntimeException("Buffer slot ["+addIndex+"] already full?");
}
conns[addIndex] = pc;
addIndex = inc(addIndex);
++size;
}
protected void closeAll(boolean logErrors) {
final PooledConnection[] items = this.conns;
this.conns = new PooledConnection[items.length];
this.size = 0;
this.removeIndex = 0;
this.addIndex = 0;
for (int i = 0; i < items.length; i++) {
PooledConnection c = items[i];
if (c != null) {
c.closeConnectionFully(logErrors);
}
}
}
/**
* Remove a connection at current remove position.
*/
@@ -79,6 +101,18 @@ class FreeConnectionBuffer {
return copy;
}
/**
* Collect the load statistics from all the free connections.
*/
protected void collectStatistics(LoadValues values, boolean reset) {
for (int i = 0; i < conns.length; i++) {
if (conns[i] != null){
values.plus(conns[i].getStatistics().getValues(reset));
}
}
}
/**
* Set the free list to be the connections in this copy. This is done after
* unused connections have been trimmed.
File diff suppressed because it is too large Load Diff
@@ -9,10 +9,12 @@ import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Condition;
import java.util.concurrent.locks.ReentrantLock;
import com.avaje.ebeaninternal.server.lib.sql.DataSourcePool.Status;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
import com.avaje.ebeaninternal.server.lib.sql.DataSourcePool.Status;
import com.avaje.ebeaninternal.server.lib.sql.PooledConnectionStatistics.LoadValues;
public class PooledConnectionQueue {
private static final Logger logger = LoggerFactory.getLogger(PooledConnectionQueue.class);
@@ -34,6 +36,16 @@ public class PooledConnectionQueue {
*/
private final BusyConnectionBuffer busyList;
/**
* Load statistics collected off connections that have closed fully (left the pool).
*/
private final PooledConnectionStatistics collectedStats = new PooledConnectionStatistics();
/**
* Currently accumulated load statistics.
*/
private LoadValues accumulatedValues = new LoadValues();
/**
* Main lock guarding all access
*/
@@ -95,10 +107,10 @@ public class PooledConnectionQueue {
this.waitTimeoutMillis = pool.getWaitTimeoutMillis();
this.leakTimeMinutes = pool.getLeakTimeMinutes();
this.busyList = new BusyConnectionBuffer(50,20);
this.busyList = new BusyConnectionBuffer(maxSize, 20);
this.freeList = new FreeConnectionBuffer(maxSize);
this.lock = new ReentrantLock(true);
this.lock = new ReentrantLock(false);
this.notEmpty = lock.newCondition();
}
@@ -116,6 +128,36 @@ public class PooledConnectionQueue {
}
}
/**
* Collect statistics of a connection that is fully closing
*/
protected void reportClosingConnection(PooledConnection pooledConnection) {
collectedStats.add(pooledConnection.getStatistics());
}
public DataSourcePoolStatistics getStatistics(boolean reset) {
final ReentrantLock lock = this.lock;
lock.lock();
try {
LoadValues aggregate = collectedStats.getValues(reset);
freeList.collectStatistics(aggregate, reset);
busyList.collectStatistics(aggregate, reset);
aggregate.plus(accumulatedValues);
this.accumulatedValues = (reset) ? new LoadValues() : aggregate;
return new DataSourcePoolStatistics(aggregate.getCollectionStart(), aggregate.getCount(), aggregate.getErrorCount(), aggregate.getHwmMicros(), aggregate.getTotalMicros());
} finally {
lock.unlock();
}
}
public Status getStatus(boolean reset) {
final ReentrantLock lock = this.lock;
lock.lock();
@@ -203,7 +245,7 @@ public class PooledConnectionQueue {
lock.lock();
try {
if (!busyList.remove(c)) {
logger.error("Connection [" + c + "] not found in BusyList? ");
logger.error("Connection [{}] not found in BusyList? ", c);
}
if (c.getCreationTime() <= lastResetTime) {
c.closeConnectionFully(false);
@@ -261,8 +303,7 @@ public class PooledConnectionQueue {
// are other threads already waiting? (they get priority)
if (waitingThreads == 0){
int freeSize = freeList.size();
if (freeSize > 0){
if (!freeList.isEmpty()){
// we have a free connection to return
return extractFromFreeList();
}
@@ -333,13 +374,13 @@ public class PooledConnectionQueue {
try {
doingShutdown = true;
Status status = createStatus();
logger.debug("DataSourcePool [" + name + "] shutdown: "+status);
DataSourcePoolStatistics statistics = pool.getStatistics(false);
logger.debug("DataSourcePool [" + name + "] shutdown {} - Statistics {}", status, statistics);
closeFreeConnections(true);
if (!busyList.isEmpty()) {
logger.warn("A potential connection leak was detected. Busy connections: "+ busyList.size());
logger.warn("Closing busy connections on shutdown size: "+ busyList.size());
dumpBusyConnectionInformation();
closeBusyConnections(0);
}
@@ -366,8 +407,7 @@ public class PooledConnectionQueue {
closeFreeConnections(false);
closeBusyConnections(leakTimeMinutes);
String busyMsg = "Busy Connections:\r\n" + getBusyConnectionInformation();
logger.info(busyMsg);
logger.info("Busy Connections:\n" + getBusyConnectionInformation());
} finally {
lock.unlock();
@@ -434,11 +474,7 @@ public class PooledConnectionQueue {
final ReentrantLock lock = this.lock;
lock.lock();
try {
while (!freeList.isEmpty()) {
PooledConnection c = freeList.remove();
logger.debug("PSTMT Statistics: "+c.getStatistics());
c.closeConnectionFully(logErrors);
}
freeList.closeAll(logErrors);
} finally {
lock.unlock();
}
@@ -465,6 +501,9 @@ public class PooledConnectionQueue {
long olderThanTime = System.currentTimeMillis() - (leakTimeMinutes*60000);
List<PooledConnection> copy = busyList.getShallowCopy();
logger.debug("Closing busy connections using leakTimeMinutes {}", leakTimeMinutes);
for (int i = 0; i < copy.size(); i++) {
PooledConnection pc = copy.get(i);
if (pc.isLongRunning() || pc.getLastUsedTime() > olderThanTime) {
@@ -472,7 +511,7 @@ public class PooledConnectionQueue {
// expected to be longRunning so not closing...
} else {
busyList.remove(pc);
closeBusyConnection(pc);
closeBusyConnection(pc, leakTimeMinutes);
}
}
@@ -481,26 +520,26 @@ public class PooledConnectionQueue {
}
}
private void closeBusyConnection(PooledConnection pc) {
private void closeBusyConnection(PooledConnection pc, long leakMinutes) {
try {
String methodLine = pc.getCreatedByMethod();
Date luDate = new Date();
luDate.setTime(pc.getLastUsedTime());
String msg = "DataSourcePool closing leaked connection? " + " name["
+ pc.getName() + "] lastUsed[" + luDate + "] createdBy[" + methodLine
String msg = "DataSourcePool closing leaked connection? name["
+ pc.getName() + "] leakMinutes["+leakMinutes+"] lastUsed[" + luDate + "] createdBy[" + methodLine
+ "] lastStmt[" + pc.getLastStatement() + "]";
logger.warn(msg);
logStackElement(pc, "Possible Leaked Connection: ");
System.out.println("CLOSING Possibly leaked connection: "+pc);
System.out.println("CLOSING BUSY CONNECTION ??? "+pc);
pc.close();
pc.closeConnectionFully(false);
} catch (SQLException ex) {
} catch (Exception ex) {
// this should never actually happen
logger.error(null, ex);
logger.error("Error when closing potentially leaked connection "+pc.getDescription(), ex);
}
}
@@ -557,13 +596,14 @@ public class PooledConnectionQueue {
lock.lock();
try {
if (toLogger) {
logger.info("Dumping busy connections: (Use datasource.xxx.capturestacktrace=true ... to get stackTraces)");
}
StringBuilder sb = new StringBuilder();
List<PooledConnection> copy = busyList.getShallowCopy();
if (toLogger) {
logger.info("Dumping [{}] busy connections: (Use datasource.xxx.capturestacktrace=true ... to get stackTraces)", copy.size());
}
for (int i = 0; i < copy.size(); i++) {
PooledConnection pc = copy.get(i);
if (toLogger) {
@@ -0,0 +1,162 @@
package com.avaje.ebeaninternal.server.lib.sql;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.atomic.AtomicLong;
/**
* Collects load statistics for a PooledConnection.
*/
public class PooledConnectionStatistics {
private final AtomicLong count = new AtomicLong();
private final AtomicLong errorCount = new AtomicLong();
private final AtomicLong hwmNanos = new AtomicLong();
private final AtomicLong totalNanos = new AtomicLong();
private final AtomicLong collectionStart;
public PooledConnectionStatistics() {
this.collectionStart = new AtomicLong(System.currentTimeMillis());
}
/**
* Add statistics from another collector.
*/
public void add(PooledConnectionStatistics other) {
errorCount.addAndGet(other.getErrorCount());
totalNanos.addAndGet(other.totalNanos.get());
count.addAndGet(other.getCount());
final long otherHwm = other.hwmNanos.get();
if (otherHwm > hwmNanos.get()) {
hwmNanos.set(otherHwm);
}
}
/**
* Add some time duration to the statistics.
*/
public void add(long durationNanos, boolean hasError) {
// This will be done in pretty much single threaded fashion
// as the Connections generally are not shared across threads
if (hasError) {
errorCount.incrementAndGet();
}
count.incrementAndGet();
totalNanos.addAndGet(durationNanos);
if (durationNanos > hwmNanos.get()) {
hwmNanos.set(durationNanos);
}
}
public String toString() {
return "count["+count+"] errors["+errorCount+"] totalMicros["+getTotalMicros()+"] hwmMicros["+getHwmMicros()+"]";
}
public long getCollectionStart() {
return collectionStart.get();
}
public long getCount() {
return count.get();
}
public long getErrorCount() {
return errorCount.get();
}
public long getTotalMicros() {
return TimeUnit.MICROSECONDS.convert(totalNanos.get(), TimeUnit.NANOSECONDS);
}
public long getHwmMicros() {
return TimeUnit.MICROSECONDS.convert(hwmNanos.get(), TimeUnit.NANOSECONDS);
}
/**
* Get the current values and reset the statistics if necessary.
*/
public LoadValues getValues(boolean reset) {
LoadValues value = new LoadValues(collectionStart.get(), count.get(), errorCount.get(), getHwmMicros(), getTotalMicros());
if (reset) {
count.set(0);
errorCount.set(0);
hwmNanos.set(0);
totalNanos.set(0);
collectionStart.set(System.currentTimeMillis());
}
return value;
}
/**
* Values representing the load or activity of a PooledConnection.
* <p>
* These are aggregated up to get a total for the DataSourcePool.
* </p>
*/
public static class LoadValues {
private long collectionStart;
private long count;
private long errorCount;
private long hwmMicros;
private long totalMicros;
public LoadValues() {
}
public LoadValues(long collectionStart, long count, long errorCount, long hwmMicros, long totalMicros) {
this.collectionStart = collectionStart;
this.count = count;
this.errorCount = errorCount;
this.hwmMicros = hwmMicros;
this.totalMicros = totalMicros;
}
public void plus(LoadValues additional) {
collectionStart = (collectionStart == 0) ? additional.collectionStart : Math.min(collectionStart, additional.collectionStart);
count += additional.count;
errorCount += additional.errorCount;
hwmMicros = Math.max(hwmMicros, additional.hwmMicros);
totalMicros += additional.totalMicros;
}
public String toString() {
return "count["+count+"] errors["+errorCount+"] totalMicros["+totalMicros+"] hwmMicros["+hwmMicros+"] avgMicros["+getAvgMicros()+"]";
}
public long getCollectionStart() {
return collectionStart;
}
public long getCount() {
return count;
}
public long getErrorCount() {
return errorCount;
}
public long getHwmMicros() {
return hwmMicros;
}
public long getTotalMicros() {
return totalMicros;
}
public long getAvgMicros() {
return (count == 0) ? 0 : totalMicros/count;
}
}
}
@@ -14,37 +14,37 @@ public class PstmtCache extends LinkedHashMap<String, ExtendedPreparedStatement>
private static final Logger logger = LoggerFactory.getLogger(PstmtCache.class);
static final long serialVersionUID = -3096406924865550697L;
static final long serialVersionUID = -3096406924865550697L;
/**
* The name of the cache, for tracing purposes.
*/
final String cacheName;
protected final String cacheName;
/**
* The maximum size of the cache. When this is exceeded the oldest entry is removed.
*/
final int maxSize;
private final int maxSize;
/**
* The total number of entries removed from this cache.
*/
int removeCounter;
private int removeCounter;
/**
* The number of get hits.
*/
int hitCounter;
private int hitCounter;
/**
* The number of get() misses.
*/
int missCounter;
private int missCounter;
/**
* The number of puts into this cache.
*/
int putCounter;
private int putCounter;
public PstmtCache(String cacheName, int maxCacheSize) {
@@ -58,7 +58,7 @@ public class PstmtCache extends LinkedHashMap<String, ExtendedPreparedStatement>
* Return a summary description of this cache.
*/
public String getDescription() {
return cacheName+" size:"+size()+" max:"+maxSize+" totalHits:"+hitCounter+" hitRatio:"+getHitRatio()+" removes:"+removeCounter;
return "size["+size()+"] max["+maxSize+"] hits["+hitCounter+"] miss["+missCounter+"] hitRatio["+getHitRatio()+"] removes["+removeCounter+"]";
}
/**
@@ -101,6 +101,24 @@ public class PstmtCache extends LinkedHashMap<String, ExtendedPreparedStatement>
return putCounter;
}
/**
* Try to add the returning statement to the cache. If there is already a
* matching ExtendedPreparedStatement in the cache return false else add
* the statement to the cache and return true.
*/
public boolean returnStatement(ExtendedPreparedStatement pstmt) {
ExtendedPreparedStatement alreadyInCache = super.get(pstmt.getCacheKey());
if (alreadyInCache != null) {
return false;
}
// add the returning prepared statement to the cache.
// Note that the LRUCache will automatically close fully old unused
// PStmts when the cache has hit its maximum size.
put(pstmt.getCacheKey(), pstmt);
return true;
}
/**
* additionally maintains hit and miss statistics.
*/