Fix for DataSourcePool trim idle connections not firing frequently

enough
This commit is contained in:
Rob Bygrave
2013-12-14 21:24:26 +13:00
parent d16f33d26b
commit 4900a460d1
8 changed files with 225 additions and 123 deletions
@@ -43,6 +43,8 @@ public class DataSourceConfig {
private int leakTimeMinutes = 30;
private int maxInactiveTimeSecs = 720;
private int trimPoolFreqSecs = 59;
private int pstmtCacheSize = 20;
@@ -321,6 +323,25 @@ public class DataSourceConfig {
this.maxInactiveTimeSecs = maxInactiveTimeSecs;
}
/**
* Return the minimum time gap between pool trim checks.
* <p>
* This defaults to 59 seconds meaning that the pool trim check will run every
* minute assuming the heart beat check runs every 30 seconds.
* </p>
*/
public int getTrimPoolFreqSecs() {
return trimPoolFreqSecs;
}
/**
* Set the minimum trim gap between pool trim checks.
*/
public void setTrimPoolFreqSecs(int trimPoolFreqSecs) {
this.trimPoolFreqSecs = trimPoolFreqSecs;
}
/**
* Return the pool listener.
*/
@@ -388,18 +409,17 @@ public class DataSourceConfig {
this.username = properties.get(prefix + "username", null);
this.password = properties.get(prefix + "password", null);
String v;
String dbDriver = properties.get(prefix + "databaseDriver", null);
this.driver = properties.get(prefix + "driver", dbDriver);
v = properties.get(prefix + "databaseDriver", null);
this.driver = properties.get(prefix + "driver", v);
v = properties.get(prefix + "databaseUrl", null);
this.url = properties.get(prefix + "url", v);
String dbUrl = properties.get(prefix + "databaseUrl", null);
this.url = properties.get(prefix + "url", dbUrl);
this.captureStackTrace = properties.getBoolean(prefix + "captureStackTrace", false);
this.maxStackTraceSize = properties.getInt(prefix + "maxStackTraceSize", 5);
this.leakTimeMinutes = properties.getInt(prefix + "leakTimeMinutes", 30);
this.maxInactiveTimeSecs = properties.getInt(prefix + "maxInactiveTimeSecs", 900);
this.maxInactiveTimeSecs = properties.getInt(prefix + "maxInactiveTimeSecs", 720);
this.trimPoolFreqSecs = properties.getInt(prefix + "trimPoolFreqSecs", 59);
this.minConnections = properties.getInt(prefix + "minConnections", 0);
this.maxConnections = properties.getInt(prefix + "maxConnections", 20);
@@ -77,6 +77,8 @@ public class DataSourcePool implements DataSource {
private final int heartbeatFreqSecs;
private final int trimPoolFreqSecs;
/**
* The transaction isolation level as per java.sql.Connection.
*/
@@ -181,6 +183,7 @@ public class DataSourcePool implements DataSource {
this.waitTimeoutMillis = params.getWaitTimeoutMillis();
this.heartbeatsql = params.getHeartbeatSql();
this.heartbeatFreqSecs = params.getHeartbeatFreqSecs();
this.trimPoolFreqSecs = params.getTrimPoolFreqSecs();
queue = new PooledConnectionQueue(this);
@@ -383,7 +386,7 @@ public class DataSourcePool implements DataSource {
notifyDataSourceIsUp();
if (System.currentTimeMillis() > (lastTrimTime + (maxInactiveTimeSecs * 1000))) {
if (System.currentTimeMillis() > (lastTrimTime + (trimPoolFreqSecs * 1000))) {
queue.trim(maxInactiveTimeSecs);
lastTrimTime = System.currentTimeMillis();
}
@@ -19,10 +19,19 @@ import com.avaje.ebeaninternal.server.lib.sql.PooledConnectionStatistics.LoadVal
*/
class FreeConnectionBuffer {
/**
* The buffer itself.
*/
private PooledConnection[] conns;
/**
* The position in the buffer where the next connection is removed from.
*/
private int removeIndex;
/**
* Position in the buffer where the next connection is added to.
*/
private int addIndex;
/**
@@ -51,13 +60,16 @@ class FreeConnectionBuffer {
*/
protected void add(PooledConnection pc) {
if (conns[addIndex] != null) {
throw new RuntimeException("Buffer slot ["+addIndex+"] already full?");
throw new IllegalStateException("Buffer slot ["+addIndex+"] already full?");
}
conns[addIndex] = pc;
addIndex = inc(addIndex);
++size;
}
/**
* Close all connections in this buffer.
*/
protected void closeAll(boolean logErrors) {
final PooledConnection[] items = this.conns;
@@ -88,19 +100,25 @@ class FreeConnectionBuffer {
}
/**
* Return a shallow copy of the free connections.
* Trim any inactive connections that have not been used since usedSince.
*/
protected List<PooledConnection> getShallowCopy() {
List<PooledConnection> copy = new ArrayList<PooledConnection>(conns.length);
for (int i = 0; i < conns.length; i++) {
if (conns[i] != null){
copy.add(conns[i]);
}
protected int trim(long usedSince) {
int trimCount = 0;
for (int i = 0; i < conns.length; i++) {
if (conns[i] != null){
if (conns[i].getLastUsedTime() < usedSince) {
trimCount++;
conns[i].closeConnectionFully(true);
conns[i] = null;
--size;
}
}
return copy;
}
return trimCount;
}
/**
* Collect the load statistics from all the free connections.
*/
@@ -114,36 +132,25 @@ class FreeConnectionBuffer {
}
/**
* Set the free list to be the connections in this copy. This is done after
* unused connections have been trimmed.
* <p>
* Not a particularly performant approach but this should not be called very
* often
* </p>
* Return a shallow copy of the free connections.
*/
protected void setShallowCopy(List<PooledConnection> copy) {
// reset to empty state
this.removeIndex = 0;
this.addIndex = 0;
this.size = 0;
// null all the current connections
for (int i = 0; i < conns.length; i++) {
conns[i] = null;
}
// add connections from the copy
for (int i = 0; i < copy.size(); i++) {
add(copy.get(i));
}
}
private List<PooledConnection> getShallowCopy() {
List<PooledConnection> copy = new ArrayList<PooledConnection>(conns.length);
for (int i = 0; i < conns.length; i++) {
if (conns[i] != null){
copy.add(conns[i]);
}
}
return copy;
}
/**
* Increase the capacity of the buffer. This is a relatively expensive
* operation but should occur very infrequently.
*/
protected void setCapacity(int newCapacity) {
if (newCapacity > conns.length){
List<PooledConnection> copy = getShallowCopy();
@@ -9,10 +9,12 @@ import java.sql.SQLWarning;
import java.sql.Savepoint;
import java.sql.Statement;
import java.util.ArrayList;
import java.util.Arrays;
import java.util.Iterator;
import java.util.Map;
import com.avaje.ebeaninternal.jdbc.ConnectionDelegator;
import org.slf4j.Logger;
import org.slf4j.LoggerFactory;
@@ -218,10 +220,18 @@ public class PooledConnection extends ConnectionDelegator {
return getDescription();
}
public String getDescription() {
return "name["+name+"] slot["+slotId+"] startTime["+getStartUseTime()+"] stmt["+getLastStatement()+"] createdBy["+getCreatedByMethod()+"]";
public long getBusySeconds() {
return (System.currentTimeMillis() - startUseTime)/1000;
}
public String getDescription() {
return "name["+name+"] slot["+slotId+"] startTime["+getStartUseTime()+"] busySeconds["+getBusySeconds()+"] createdBy["+getCreatedByMethod()+"] stmt["+getLastStatement()+"]";
}
public String getFullDescription() {
return "name["+name+"] slot["+slotId+"] startTime["+getStartUseTime()+"] busySeconds["+getBusySeconds()+"] stackTrace["+getStackTraceAsString()+"] stmt["+getLastStatement()+"]";
}
public String getPstmtStatistics() {
return "name["+name+"] startTime["+getStartUseTime()+"] "+pstmtCache.getDescription();
}
@@ -907,6 +917,17 @@ public class PooledConnection extends ConnectionDelegator {
this.stackTrace = stackTrace;
}
/**
* Return the stackTrace as a String for logging purposes.
*/
public String getStackTraceAsString() {
StackTraceElement[] stackTrace = getStackTrace();
if (stackTrace == null){
return "";
}
return Arrays.toString(stackTrace);
}
/**
* Return the full stack trace that got the connection from the pool. You
* could use this if getCreatedByMethod() doesn't work for you.
@@ -1,9 +1,6 @@
package com.avaje.ebeaninternal.server.lib.sql;
import java.sql.SQLException;
import java.util.Arrays;
import java.util.Date;
import java.util.Iterator;
import java.util.List;
import java.util.concurrent.TimeUnit;
import java.util.concurrent.locks.Condition;
@@ -418,9 +415,9 @@ public class PooledConnectionQueue {
final ReentrantLock lock = this.lock;
lock.lock();
try {
trimInactiveConnections(maxInactiveTimeSecs);
ensureMinimumConnections();
if (trimInactiveConnections(maxInactiveTimeSecs) > 0) {
ensureMinimumConnections();
}
} finally {
lock.unlock();
}
@@ -430,39 +427,12 @@ public class PooledConnectionQueue {
* Trim connections that have been not used for some time.
*/
private int trimInactiveConnections(int maxInactiveTimeSecs) {
int maxTrim = freeList.size() - minSize;
if (maxTrim <= 0) {
return 0;
}
int trimedCount = 0;
long usedSince = System.currentTimeMillis() - (maxInactiveTimeSecs * 1000);
// get a shallow copy to manipulate
List<PooledConnection> freeListCopy = freeList.getShallowCopy();
Iterator<PooledConnection> it = freeListCopy.iterator();
while (it.hasNext()) {
PooledConnection pc = it.next();
if (pc.getLastUsedTime() < usedSince) {
// trim this connection as it hasn't been used in a while
trimedCount++;
it.remove();
pc.closeConnectionFully(true);
if (trimedCount >= maxTrim) {
break;
}
}
}
int trimedCount = freeList.trim(usedSince);
if (trimedCount > 0) {
// rebuild the free list from the trimmed copy
freeList.setShallowCopy(freeListCopy);
String msg = "DataSourcePool [" + name + "] trimmed [" + trimedCount + "] inactive connections. New size[" + totalConnections() + "]";
logger.debug(msg);
logger.debug("DataSourcePool [{}] trimmed [{}] inactive connections. New size[{}]", name, trimedCount, totalConnections());
}
return trimedCount;
}
@@ -522,18 +492,9 @@ public class PooledConnectionQueue {
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() + "] 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);
logger.warn("DataSourcePool closing busy connection? "+pc.getFullDescription());
System.out.println("CLOSING busy connection: "+pc.getFullDescription());
pc.closeConnectionFully(false);
@@ -543,19 +504,6 @@ public class PooledConnectionQueue {
}
}
private void logStackElement(PooledConnection pc, String prefix) {
StackTraceElement[] stackTrace = pc.getStackTrace();
if (stackTrace != null){
String s = Arrays.toString(stackTrace);
String msg = prefix+" name["+pc.getName()+"] stackTrace: "+s;
logger.warn(msg);
// also send to syserr ... as the loggers get turned
// off early in JVM shutdown
System.err.println(msg);
}
}
/**
* As the pool grows it gets closer to the maxConnections limit. We can send
* an Alert (or warning) as we get close to this limit and hence an
@@ -607,11 +555,9 @@ public class PooledConnectionQueue {
for (int i = 0; i < copy.size(); i++) {
PooledConnection pc = copy.get(i);
if (toLogger) {
logger.info(pc.getDescription());
logStackElement(pc, "Busy Connection: ");
logger.info("Busy Connection - {}", pc.getFullDescription());
} else {
sb.append(pc.getDescription()).append("\r\n");
sb.append(pc.getFullDescription()).append("\r\n");
}
}