From 9d12b1cd04cf86ecf137a25ea6a941e4a09a495c Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Tue, 22 Sep 2026 17:30:27 -0700 Subject: [PATCH 1/9] Expose more stats from the connection pool --- api/src/org/labkey/api/data/DbScope.java | 23 +++++- .../labkey/api/data/dialect/SqlDialect.java | 57 +++++++++++++ .../query/controllers/QueryController.java | 79 +++++++++++++++++-- 3 files changed, 149 insertions(+), 10 deletions(-) diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 9ba19871b81..91843001cb4 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -1407,11 +1407,26 @@ public void logCurrentConnectionState(LoggerWriter log) { synchronized (_transaction) { + DataSourcePropertyReader props = getDbScopeLoader().getDsProps(); + log.info("Data source " + this + - ". Max connections: " + getDbScopeLoader().getDsProps().getMaxTotal() + - ", active: " + getDbScopeLoader().getDsProps().getNumActive() + - ", idle: " + getDbScopeLoader().getDsProps().getNumIdle() + - ", maxWaitMillis: " + getDbScopeLoader().getDsProps().getMaxWaitMillis()); + ". Max connections: " + props.getMaxTotal() + + ", active: " + props.getNumActive() + + ", idle: " + props.getNumIdle() + + ", maxWaitMillis: " + props.getMaxWaitMillis()); + + DataSourcePropertyReader.PoolStatistics pool = props.getPoolStatistics(); + + if (null != pool) + log.info("Connection pool for data source " + this + + ". Opened: " + pool.createdCount() + + ", closed: " + pool.destroyedCount() + + " (idle: " + pool.destroyedByEvictorCount() + + ", failed validation: " + pool.destroyedByBorrowValidationCount() + + "), borrowed: " + pool.borrowedCount() + + ", waiting threads: " + pool.numWaiters() + + ", meanBorrowWaitMillis: " + pool.meanBorrowWaitMillis() + + ", maxBorrowWaitMillis: " + pool.maxBorrowWaitMillis()); if (_transaction.isEmpty()) { diff --git a/api/src/org/labkey/api/data/dialect/SqlDialect.java b/api/src/org/labkey/api/data/dialect/SqlDialect.java index 9a2688d87dd..7176ff6de46 100644 --- a/api/src/org/labkey/api/data/dialect/SqlDialect.java +++ b/api/src/org/labkey/api/data/dialect/SqlDialect.java @@ -1751,6 +1751,63 @@ public Long getMaxWaitMillis() } } + /** + * Statistics tracked by the commons-pool2 GenericObjectPool that BasicDataSource wraps. They're reachable only + * through the pool itself; BasicDataSource doesn't republish them the way it does numActive/numIdle. Every count + * is cumulative since the pool was created, except numWaiters, which is a current reading. + */ + public record PoolStatistics( + /** Connections opened */ + long createdCount, + /** Connections closed, for any reason */ + long destroyedCount, + /** Connections closed because they sat idle longer than the pool allows */ + long destroyedByEvictorCount, + /** Connections closed because they failed validation when a caller tried to borrow them */ + long destroyedByBorrowValidationCount, + /** Connections handed out */ + long borrowedCount, + /** Threads currently blocked waiting for a connection */ + long numWaiters, + /** Mean time callers have waited to borrow a connection */ + long meanBorrowWaitMillis, + /** Longest a caller has ever waited to borrow a connection */ + long maxBorrowWaitMillis + ) {} + + public @Nullable PoolStatistics getPoolStatistics() + { + try + { + Object pool = _ds.getClass().getMethod("getConnectionPool").invoke(_ds); + + // BasicDataSource creates the pool lazily, on the first connection request + if (null == pool) + return null; + + return new PoolStatistics( + getPoolStatistic(pool, "getCreatedCount"), + getPoolStatistic(pool, "getDestroyedCount"), + getPoolStatistic(pool, "getDestroyedByEvictorCount"), + getPoolStatistic(pool, "getDestroyedByBorrowValidationCount"), + getPoolStatistic(pool, "getBorrowedCount"), + getPoolStatistic(pool, "getNumWaiters"), + getPoolStatistic(pool, "getMeanBorrowWaitTimeMillis"), + getPoolStatistic(pool, "getMaxBorrowWaitTimeMillis") + ); + } + catch (Exception e) + { + LOG.error("Could not extract connection pool statistics from data source \"{}\"", _dsName); + return null; + } + } + + private static long getPoolStatistic(Object pool, String methodName) throws ReflectiveOperationException + { + return ((Number)pool.getClass().getMethod(methodName).invoke(pool)).longValue(); + } + public @Nullable Properties getConnectionProperties() { try diff --git a/query/src/org/labkey/query/controllers/QueryController.java b/query/src/org/labkey/query/controllers/QueryController.java index d222143fd72..2bf192f0313 100644 --- a/query/src/org/labkey/query/controllers/QueryController.java +++ b/query/src/org/labkey/query/controllers/QueryController.java @@ -134,6 +134,7 @@ import org.labkey.api.data.TableSelector; import org.labkey.api.data.dialect.JdbcMetaDataLocator; import org.labkey.api.data.dialect.SqlDialect; +import org.labkey.api.data.dialect.SqlDialect.DataSourcePropertyReader.PoolStatistics; import org.labkey.api.dataiterator.DataIteratorBuilder; import org.labkey.api.dataiterator.DataIteratorContext; import org.labkey.api.dataiterator.DetailedAuditLogDataIterator; @@ -230,6 +231,7 @@ import org.labkey.api.util.DOM; import org.labkey.api.util.ExceptionUtil; import org.labkey.api.util.FileUtil; +import org.labkey.api.util.Formats; import org.labkey.api.util.HtmlString; import org.labkey.api.util.HtmlStringBuilder; import org.labkey.api.util.JavaScriptFragment; @@ -344,6 +346,7 @@ import java.util.Objects; import java.util.Set; import java.util.TreeSet; +import java.util.function.BiFunction; import java.util.stream.Collectors; import java.util.stream.Stream; @@ -355,9 +358,14 @@ import static org.labkey.api.data.DbScope.NO_OP_TRANSACTION; import static org.labkey.api.query.AbstractQueryUpdateService.saveFile; import static org.labkey.api.util.DOM.BR; +import static org.labkey.api.util.DOM.DETAILS; import static org.labkey.api.util.DOM.DIV; import static org.labkey.api.util.DOM.FONT; +import static org.labkey.api.util.DOM.I; import static org.labkey.api.util.DOM.Renderable; +import static org.labkey.api.util.DOM.SPAN; +import static org.labkey.api.util.DOM.STYLE; +import static org.labkey.api.util.DOM.SUMMARY; import static org.labkey.api.util.DOM.TABLE; import static org.labkey.api.util.DOM.TD; import static org.labkey.api.util.DOM.TR; @@ -747,9 +755,10 @@ public ModelAndView getView(Object o, BindException errors) MutableInt row = new MutableInt(); Renderable r = DOM.DIV( + STYLE(TABLE_CSS, POOL_STATS_CSS), DIV("This page lists all the data sources defined in your " + AppProps.getInstance().getWebappConfigurationFilename() + " file that were available when first referenced and the external schemas defined in each."), BR(), - TABLE(cl("labkey-data-region"), + TABLE(cl("labkey-data-region", "lk-datasource-admin"), TR(cl("labkey-show-borders"), showTestButton ? TD(cl("labkey-column-header"), "Test") : null, TD(cl("labkey-column-header"), "Data Source"), @@ -782,16 +791,21 @@ public ModelAndView getView(Object o, BindException errors) TR( cl(rowStyle), showTestButton ? TD(connected ? new ButtonBuilder("Test").href(new ActionURL(TestDataSourceConfirmAction.class, getContainer()).addParameter("dataSource", scope.getDataSourceName())) : "") : null, - TD(HtmlString.NBSP, scope.getDisplayName()), + TD(scope.getDisplayName()), TD(status), TD(scope.getDatabaseUrl()), TD(scope.getDatabaseName()), TD(scope.getDatabaseProductName()), TD(scope.getDatabaseProductVersion()), - TD(scope.getDataSourceProperties().getMaxTotal()), - TD(scope.getDataSourceProperties().getNumActive()), - TD(scope.getDataSourceProperties().getNumIdle()), - TD(scope.getDataSourceProperties().getMaxWaitMillis()) + TD(formatCount(scope.getDataSourceProperties().getMaxTotal())), + TD(formatCount(scope.getDataSourceProperties().getNumActive())), + TD(formatCount(scope.getDataSourceProperties().getNumIdle())), + TD(formatCount(scope.getDataSourceProperties().getMaxWaitMillis())) + ), + TR( + cl(rowStyle), + TD(HtmlString.NBSP), + TD(at(DOM.Attribute.colspan, 10), renderPoolStatistics(scope)) ), TR( cl(rowStyle), @@ -806,6 +820,59 @@ public ModelAndView getView(Object o, BindException errors) return new HtmlView(r); } + private static String formatCount(@Nullable Number value) + { + return null != value ? Formats.commaf0.format(value) : ""; + } + + // .labkey-data-region pads header cells but not data cells, so the two rows sit 4px out of line + private static final String TABLE_CSS = """ + table.lk-datasource-admin td { padding: 1px 4px; } + """; + + // The normalize.css rule "summary { display: block }" suppresses the native disclosure triangle, so supply our own + private static final String POOL_STATS_CSS = """ + details.lk-pool-stats summary { display: block; width: fit-content; } + details.lk-pool-stats summary:hover { text-decoration: underline; } + details.lk-pool-stats .lk-pool-caret { display: inline-block; width: 10px; margin-right: 5px; color: #116596; } + details.lk-pool-stats[open] .lk-pool-caret { transform: rotate(90deg); } + details.lk-pool-stats table { margin: 3px 0 6px 17px; } + details.lk-pool-stats td.lk-pool-stat-value { text-align: right; padding-left: 30px; } + """; + + // Live pool numbers, collapsed by default to keep the data source rows scannable + private Renderable renderPoolStatistics(DbScope scope) + { + PoolStatistics pool = scope.getDataSourceProperties().getPoolStatistics(); + + if (null == pool) + return HtmlString.EMPTY_STRING; + + MutableInt row = new MutableInt(); + BiFunction stat = (label, value) -> + TR(cl(row.getAndIncrement() % 2 == 0 ? "labkey-alternate-row" : "labkey-row"), + TD(label), + TD(cl("lk-pool-stat-value"), formatCount(value)) + ); + + return DETAILS(cl("lk-pool-stats"), + SUMMARY( + I(cl("fa", "fa-caret-right", "lk-pool-caret")), + SPAN(cl("labkey-link"), "Connection pool statistics") + ), + TABLE( + stat.apply("Threads waiting for a connection", pool.numWaiters()), + stat.apply("Connections opened", pool.createdCount()), + stat.apply("Connections closed", pool.destroyedCount()), + stat.apply("Closed after sitting idle", pool.destroyedByEvictorCount()), + stat.apply("Closed after failed validation", pool.destroyedByBorrowValidationCount()), + stat.apply("Connections borrowed", pool.borrowedCount()), + stat.apply("Mean wait to borrow (ms)", pool.meanBorrowWaitMillis()), + stat.apply("Longest wait to borrow (ms)", pool.maxBorrowWaitMillis()) + ) + ); + } + private Renderable getDataSourceTable(Collection dsDefs) { if (dsDefs.isEmpty()) From 6ce8f65a83a450d19372f33c4ec86258667caadd Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Wed, 23 Sep 2026 11:42:04 -0700 Subject: [PATCH 2/9] Clarify connection pool stat labels and logging Mean borrow wait is a rolling window of the last 100 borrows and the evictor count includes idle validation failures; also log the extraction exception and drop the shared DecimalFormat. --- api/src/org/labkey/api/data/DbScope.java | 4 ++-- api/src/org/labkey/api/data/dialect/SqlDialect.java | 11 ++++++----- .../org/labkey/query/controllers/QueryController.java | 11 +++++------ 3 files changed, 13 insertions(+), 13 deletions(-) diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 91843001cb4..cf5633969c9 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -1421,11 +1421,11 @@ public void logCurrentConnectionState(LoggerWriter log) log.info("Connection pool for data source " + this + ". Opened: " + pool.createdCount() + ", closed: " + pool.destroyedCount() + - " (idle: " + pool.destroyedByEvictorCount() + + " (evictor: " + pool.destroyedByEvictorCount() + ", failed validation: " + pool.destroyedByBorrowValidationCount() + "), borrowed: " + pool.borrowedCount() + ", waiting threads: " + pool.numWaiters() + - ", meanBorrowWaitMillis: " + pool.meanBorrowWaitMillis() + + ", meanBorrowWaitMillis (last 100): " + pool.meanBorrowWaitMillis() + ", maxBorrowWaitMillis: " + pool.maxBorrowWaitMillis()); if (_transaction.isEmpty()) diff --git a/api/src/org/labkey/api/data/dialect/SqlDialect.java b/api/src/org/labkey/api/data/dialect/SqlDialect.java index 7176ff6de46..c745ccce20a 100644 --- a/api/src/org/labkey/api/data/dialect/SqlDialect.java +++ b/api/src/org/labkey/api/data/dialect/SqlDialect.java @@ -1753,15 +1753,16 @@ public Long getMaxWaitMillis() /** * Statistics tracked by the commons-pool2 GenericObjectPool that BasicDataSource wraps. They're reachable only - * through the pool itself; BasicDataSource doesn't republish them the way it does numActive/numIdle. Every count - * is cumulative since the pool was created, except numWaiters, which is a current reading. + * through the pool itself; BasicDataSource doesn't republish them the way it does numActive/numIdle. Values are + * cumulative since the pool was created, except numWaiters (a current reading) and meanBorrowWaitMillis (the + * mean of the most recent 100 borrows). */ public record PoolStatistics( /** Connections opened */ long createdCount, /** Connections closed, for any reason */ long destroyedCount, - /** Connections closed because they sat idle longer than the pool allows */ + /** Connections closed by the idle evictor, either for exceeding the idle timeout or failing idle validation */ long destroyedByEvictorCount, /** Connections closed because they failed validation when a caller tried to borrow them */ long destroyedByBorrowValidationCount, @@ -1769,7 +1770,7 @@ public record PoolStatistics( long borrowedCount, /** Threads currently blocked waiting for a connection */ long numWaiters, - /** Mean time callers have waited to borrow a connection */ + /** Mean time callers waited to borrow a connection, over the most recent 100 borrows */ long meanBorrowWaitMillis, /** Longest a caller has ever waited to borrow a connection */ long maxBorrowWaitMillis @@ -1798,7 +1799,7 @@ public record PoolStatistics( } catch (Exception e) { - LOG.error("Could not extract connection pool statistics from data source \"{}\"", _dsName); + LOG.warn("Could not extract connection pool statistics from data source \"{}\"", _dsName, e); return null; } } diff --git a/query/src/org/labkey/query/controllers/QueryController.java b/query/src/org/labkey/query/controllers/QueryController.java index 2bf192f0313..f3788375e26 100644 --- a/query/src/org/labkey/query/controllers/QueryController.java +++ b/query/src/org/labkey/query/controllers/QueryController.java @@ -231,7 +231,6 @@ import org.labkey.api.util.DOM; import org.labkey.api.util.ExceptionUtil; import org.labkey.api.util.FileUtil; -import org.labkey.api.util.Formats; import org.labkey.api.util.HtmlString; import org.labkey.api.util.HtmlStringBuilder; import org.labkey.api.util.JavaScriptFragment; @@ -822,7 +821,7 @@ public ModelAndView getView(Object o, BindException errors) private static String formatCount(@Nullable Number value) { - return null != value ? Formats.commaf0.format(value) : ""; + return null != value ? String.format("%,d", value.longValue()) : ""; } // .labkey-data-region pads header cells but not data cells, so the two rows sit 4px out of line @@ -834,7 +833,7 @@ private static String formatCount(@Nullable Number value) private static final String POOL_STATS_CSS = """ details.lk-pool-stats summary { display: block; width: fit-content; } details.lk-pool-stats summary:hover { text-decoration: underline; } - details.lk-pool-stats .lk-pool-caret { display: inline-block; width: 10px; margin-right: 5px; color: #116596; } + details.lk-pool-stats .lk-pool-caret { display: inline-block; width: 10px; margin-right: 5px; } details.lk-pool-stats[open] .lk-pool-caret { transform: rotate(90deg); } details.lk-pool-stats table { margin: 3px 0 6px 17px; } details.lk-pool-stats td.lk-pool-stat-value { text-align: right; padding-left: 30px; } @@ -857,17 +856,17 @@ private Renderable renderPoolStatistics(DbScope scope) return DETAILS(cl("lk-pool-stats"), SUMMARY( - I(cl("fa", "fa-caret-right", "lk-pool-caret")), + I(cl("fa", "fa-caret-right", "lk-pool-caret", "labkey-link")), SPAN(cl("labkey-link"), "Connection pool statistics") ), TABLE( stat.apply("Threads waiting for a connection", pool.numWaiters()), stat.apply("Connections opened", pool.createdCount()), stat.apply("Connections closed", pool.destroyedCount()), - stat.apply("Closed after sitting idle", pool.destroyedByEvictorCount()), + stat.apply("Closed by idle evictor", pool.destroyedByEvictorCount()), stat.apply("Closed after failed validation", pool.destroyedByBorrowValidationCount()), stat.apply("Connections borrowed", pool.borrowedCount()), - stat.apply("Mean wait to borrow (ms)", pool.meanBorrowWaitMillis()), + stat.apply("Mean wait to borrow, last 100 (ms)", pool.meanBorrowWaitMillis()), stat.apply("Longest wait to borrow (ms)", pool.maxBorrowWaitMillis()) ) ); From aa26f937476b41e9423610e01d1c4b15476e2aca Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sat, 26 Sep 2026 11:17:02 -0700 Subject: [PATCH 3/9] Integration test --- api/src/org/labkey/api/ApiModule.java | 1 + api/src/org/labkey/api/data/DbScope.java | 26 +++++++++++++++++++ .../labkey/api/data/dialect/SqlDialect.java | 20 +++++++------- 3 files changed, 36 insertions(+), 11 deletions(-) diff --git a/api/src/org/labkey/api/ApiModule.java b/api/src/org/labkey/api/ApiModule.java index 7692f0239bd..5f3062b4691 100644 --- a/api/src/org/labkey/api/ApiModule.java +++ b/api/src/org/labkey/api/ApiModule.java @@ -541,6 +541,7 @@ public void registerServlets(ServletContext servletCtx) DbSchema.TransactionTestCase.class, DbScope.GroupConcatTestCase.class, DbScope.SchemaNameTestCase.class, + DbScope.PoolStatisticsTestCase.class, DbScope.TransactionTestCase.class, DbSequenceManager.TestCase.class, DisplayColumn.TestCase.class, diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index cf5633969c9..10539fbb4a5 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -3788,5 +3788,31 @@ public void testRetryException() } } } + + public static class PoolStatisticsTestCase extends Assert + { + @Test + public void testPoolStatistics() throws SQLException + { + DataSourcePropertyReader props = getLabKeyScope().getDataSourceProperties(); + DataSourcePropertyReader.PoolStatistics before = props.getPoolStatistics(); + assertNotNull("Could not read connection pool statistics; see log for the reflection failure", before); + + assertTrue(before.createdCount() >= 1); + assertTrue(before.destroyedCount() <= before.createdCount()); + assertTrue(before.destroyedByEvictorCount() <= before.destroyedCount()); + assertTrue(before.destroyedByBorrowValidationCount() <= before.destroyedCount()); + assertTrue(before.numWaiters() >= 0); + assertTrue(before.meanBorrowWaitMillis() >= 0); + assertTrue(before.maxBorrowWaitMillis() >= before.meanBorrowWaitMillis()); + + try (Connection ignored = getLabKeyScope().getPooledConnection()) + { + DataSourcePropertyReader.PoolStatistics after = props.getPoolStatistics(); + assertNotNull(after); + assertTrue(after.borrowedCount() > before.borrowedCount()); + } + } + } } diff --git a/api/src/org/labkey/api/data/dialect/SqlDialect.java b/api/src/org/labkey/api/data/dialect/SqlDialect.java index c745ccce20a..c66384c8e0d 100644 --- a/api/src/org/labkey/api/data/dialect/SqlDialect.java +++ b/api/src/org/labkey/api/data/dialect/SqlDialect.java @@ -1753,26 +1753,24 @@ public Long getMaxWaitMillis() /** * Statistics tracked by the commons-pool2 GenericObjectPool that BasicDataSource wraps. They're reachable only - * through the pool itself; BasicDataSource doesn't republish them the way it does numActive/numIdle. Values are - * cumulative since the pool was created, except numWaiters (a current reading) and meanBorrowWaitMillis (the - * mean of the most recent 100 borrows). + * through the pool itself; BasicDataSource doesn't republish them the way it does numActive/numIdle. */ public record PoolStatistics( - /** Connections opened */ + // Total connections opened long createdCount, - /** Connections closed, for any reason */ + // Tocal connections closed, for any reason long destroyedCount, - /** Connections closed by the idle evictor, either for exceeding the idle timeout or failing idle validation */ + // Total connections closed by the idle evictor, either for exceeding the idle timeout or failing idle validation long destroyedByEvictorCount, - /** Connections closed because they failed validation when a caller tried to borrow them */ + // Total connections closed because they failed validation when a caller tried to borrow them long destroyedByBorrowValidationCount, - /** Connections handed out */ + // Total connections handed out long borrowedCount, - /** Threads currently blocked waiting for a connection */ + // Threads currently blocked waiting for a connection long numWaiters, - /** Mean time callers waited to borrow a connection, over the most recent 100 borrows */ + // Mean wait time to borrow a connection, over the most recent 100 borrows long meanBorrowWaitMillis, - /** Longest a caller has ever waited to borrow a connection */ + // Longest a caller has ever waited to borrow a connection long maxBorrowWaitMillis ) {} From 78d52ecb42b5d744fca031590fc4422861a6af3f Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sat, 26 Sep 2026 12:18:58 -0700 Subject: [PATCH 4/9] Mesure the count and time spent borrowing connections per request --- api/src/org/labkey/api/ApiModule.java | 2 + .../api/action/SpringActionController.java | 101 ++++++- .../org/labkey/api/data/ConnectionUsage.java | 280 ++++++++++++++++++ .../labkey/api/data/ConnectionWrapper.java | 13 + api/src/org/labkey/api/data/DbScope.java | 5 +- .../labkey/api/module/SimpleController.java | 3 +- core/src/org/labkey/core/CoreModule.java | 32 +- .../org/labkey/core/admin/ActionsView.java | 33 ++- .../labkey/core/admin/AdminController.java | 14 + .../core/admin/ConnectionUsageTsvWriter.java | 85 ++++++ 10 files changed, 537 insertions(+), 31 deletions(-) create mode 100644 api/src/org/labkey/api/data/ConnectionUsage.java create mode 100644 core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java diff --git a/api/src/org/labkey/api/ApiModule.java b/api/src/org/labkey/api/ApiModule.java index 7692f0239bd..016bf0b7b54 100644 --- a/api/src/org/labkey/api/ApiModule.java +++ b/api/src/org/labkey/api/ApiModule.java @@ -53,6 +53,7 @@ import org.labkey.api.data.BooleanFormat; import org.labkey.api.data.BuilderObjectFactory; import org.labkey.api.data.CompareType; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.ContainerDisplayColumn; import org.labkey.api.data.ContainerFilter; import org.labkey.api.data.ContainerManager; @@ -531,6 +532,7 @@ public void registerServlets(ServletContext servletCtx) BindingTestCase.class, BlockingCache.BlockingCacheTest.class, CompareType.TestCase.class, + ConnectionUsage.TestCase.class, ContainerDisplayColumn.TestCase.class, ContainerFilter.TestCase.class, ContainerManager.TestCase.class, diff --git a/api/src/org/labkey/api/action/SpringActionController.java b/api/src/org/labkey/api/action/SpringActionController.java index a66b95382df..3954cd7b7b1 100644 --- a/api/src/org/labkey/api/action/SpringActionController.java +++ b/api/src/org/labkey/api/action/SpringActionController.java @@ -28,6 +28,7 @@ import org.labkey.api.action.ApiResponseWriter.Format; import org.labkey.api.admin.AdminUrls; import org.labkey.api.collections.CaseInsensitiveHashMap; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.Container; import org.labkey.api.data.TransactionFilter; import org.labkey.api.data.dialect.SqlDialect; @@ -98,6 +99,7 @@ import java.util.Map; import java.util.Set; import java.util.concurrent.CopyOnWriteArraySet; +import java.util.concurrent.TimeUnit; import java.util.function.Supplier; import static java.lang.Boolean.FALSE; @@ -191,7 +193,7 @@ protected static String h(@Nullable Object o) public interface ActionResolver { Controller resolveActionName(Controller actionController, String actionName); - void addTime(Controller action, long elapsedTime); + void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage); Collection getActionDescriptors(); } @@ -203,7 +205,7 @@ public interface ActionDescriptor Class getActionClass(); Controller createController(Controller actionController); - void addTime(long time); + void addTime(long time, ConnectionUsage.Snapshot connectionUsage); void addException(Exception x); ActionStats getStats(); } @@ -214,8 +216,27 @@ public interface ActionStats long getCount(); long getElapsedTime(); long getMaxTime(); + long getBorrows(); + /** Summed over connections, so exceeds wall time when a request holds several at once */ + long getConnectionHoldTime(); + /** Time holding at least one connection */ + long getConnectionWallTime(); + int getMaxConcurrent(); + long getAcquireTime(); + long getUnreturned(); boolean hasExceptions(); List getExceptions(); + + default double getBorrowsPerInvocation() + { + return 0 == getCount() ? 0 : getBorrows() / (double) getCount(); + } + + /** Clamped because elapsed time has millisecond resolution and connection time has nanosecond resolution */ + default double getConnectionHoldFraction() + { + return 0 == getElapsedTime() ? 0 : Math.min(1.0, getConnectionWallTime() / (double) getElapsedTime()); + } } ApplicationContext _applicationContext = null; @@ -421,6 +442,7 @@ public ModelAndView handleRequest(HttpServletRequest request, @NotNull HttpServl ActionURL url = context.getActionURL(); long startTime = System.currentTimeMillis(); + ConnectionUsage.Mark connectionMark = ConnectionUsage.mark(); Controller controller = null; PageConfig pageConfig = null; @@ -560,7 +582,7 @@ public ModelAndView handleRequest(HttpServletRequest request, @NotNull HttpServl clearActionForThread(controller); if (null != controller) - _actionResolver.addTime(controller, System.currentTimeMillis() - startTime); + _actionResolver.addTime(controller, System.currentTimeMillis() - startTime, ConnectionUsage.measure(connectionMark)); } return null; @@ -783,16 +805,29 @@ public static abstract class BaseActionDescriptor implements ActionDescriptor private long _count = 0; private long _elapsedTime = 0; private long _maxTime = 0; + private long _borrows = 0; + private long _heldNanos = 0; + private long _wallNanos = 0; + private int _maxConcurrent = 0; + private long _acquireNanos = 0; + private long _unreturned = 0; private List _exceptions = null; @Override - synchronized public void addTime(long time) + synchronized public void addTime(long time, ConnectionUsage.Snapshot connectionUsage) { _count++; _elapsedTime += time; if (time > _maxTime) _maxTime = time; + + _borrows += connectionUsage.borrows(); + _heldNanos += connectionUsage.heldNanos(); + _wallNanos += connectionUsage.wallNanos(); + _maxConcurrent = Math.max(_maxConcurrent, connectionUsage.maxConcurrent()); + _acquireNanos += connectionUsage.acquireNanos(); + _unreturned += connectionUsage.unreturned(); } @Override @@ -807,7 +842,7 @@ public void addException(Exception ex) @Override synchronized public ActionStats getStats() { - return new BaseActionStats(_count, _elapsedTime, _maxTime, _exceptions); + return new BaseActionStats(_count, _elapsedTime, _maxTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _unreturned, _exceptions); } // Immutable stats holder to eliminate external synchronization needs @@ -816,13 +851,25 @@ private class BaseActionStats implements ActionStats private final long _count; private final long _elapsedTime; private final long _maxTime; + private final long _borrows; + private final long _heldNanos; + private final long _wallNanos; + private final int _maxConcurrent; + private final long _acquireNanos; + private final long _unreturned; private final List _exceptions; - private BaseActionStats(long count, long elapsedTime, long maxTime, List ex) + private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long unreturned, List ex) { _count = count; _elapsedTime = elapsedTime; _maxTime = maxTime; + _borrows = borrows; + _heldNanos = heldNanos; + _wallNanos = wallNanos; + _maxConcurrent = maxConcurrent; + _acquireNanos = acquireNanos; + _unreturned = unreturned; _exceptions = ex; } @@ -844,6 +891,42 @@ public long getMaxTime() return _maxTime; } + @Override + public long getBorrows() + { + return _borrows; + } + + @Override + public long getConnectionHoldTime() + { + return TimeUnit.NANOSECONDS.toMillis(_heldNanos); + } + + @Override + public long getConnectionWallTime() + { + return TimeUnit.NANOSECONDS.toMillis(_wallNanos); + } + + @Override + public int getMaxConcurrent() + { + return _maxConcurrent; + } + + @Override + public long getAcquireTime() + { + return TimeUnit.NANOSECONDS.toMillis(_acquireNanos); + } + + @Override + public long getUnreturned() + { + return _unreturned; + } + @Override @Nullable public Class getActionType() @@ -881,7 +964,7 @@ public HTMLFileActionResolver(String controllerName) } @Override - public void addTime(Controller action, long elapsedTime) + public void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage) { /* Never called */ } @@ -1059,11 +1142,11 @@ public Controller resolveActionName(Controller actionController, String name) @Override - public void addTime(Controller action, long elapsedTime) + public void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage) { ActionDescriptor ad = getActionDescriptor(action.getClass()); if (null != ad) - ad.addTime(elapsedTime); + ad.addTime(elapsedTime, connectionUsage); } diff --git a/api/src/org/labkey/api/data/ConnectionUsage.java b/api/src/org/labkey/api/data/ConnectionUsage.java new file mode 100644 index 00000000000..a0adb763569 --- /dev/null +++ b/api/src/org/labkey/api/data/ConnectionUsage.java @@ -0,0 +1,280 @@ +/* + * Copyright (c) 2026 LabKey Corporation + * + * Licensed 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.labkey.api.data; + +import org.jetbrains.annotations.NotNull; +import org.jetbrains.annotations.Nullable; +import org.junit.Assert; +import org.junit.Test; + +import java.sql.Connection; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.Map; +import java.util.WeakHashMap; +import java.util.concurrent.atomic.AtomicReference; + +/** + * Counts connection pool borrows and hold time within a window opened by {@link #mark()}. Usage is keyed on + * {@link DbScope#getEffectiveThread()}, so async threads sharing a request's connections are charged to that request. + */ +public class ConnectionUsage +{ + private static final Map USAGE = Collections.synchronizedMap(new WeakHashMap<>()); + + public record Snapshot(long borrows, long acquireNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned) + { + public static final Snapshot EMPTY = new Snapshot(0, 0, 0, 0, 0, 0); + } + + /** Opaque token returned by {@link #mark()} */ + public static final class Mark + { + private final Usage _usage; + private final long _borrows; + private final long _acquireNanos; + private final long _heldNanos; + private final long _wallNanos; + private final int _active; + private int _maxActive; + + private Mark(Usage usage, long now) + { + _usage = usage; + _borrows = usage._borrows; + _acquireNanos = usage._acquireNanos; + _heldNanos = usage.held(now); + _wallNanos = usage.wall(now); + _active = usage._active; + _maxActive = usage._active; + } + } + + // Sums of nanoTime() values may overflow; that's harmless because only differences are reported + static final class Usage + { + private long _borrows; + private long _acquireNanos; + private long _heldClosedNanos; + private long _openStartSum; + private long _wallClosedNanos; + private long _wallStart; + private int _active; + private final List _marks = new ArrayList<>(2); + + private long held(long now) + { + return _heldClosedNanos + _active * now - _openStartSum; + } + + private long wall(long now) + { + return _wallClosedNanos + (_active > 0 ? now - _wallStart : 0); + } + + private synchronized void borrow(long acquireNanos, long now) + { + _borrows++; + _acquireNanos += acquireNanos; + if (_active++ == 0) + _wallStart = now; + _openStartSum += now; + for (Mark mark : _marks) + mark._maxActive = Math.max(mark._maxActive, _active); + } + + private synchronized void release(long borrowedAt, long now) + { + _active--; + _heldClosedNanos += now - borrowedAt; + _openStartSum -= borrowedAt; + if (_active == 0) + _wallClosedNanos += now - _wallStart; + } + + private synchronized Mark mark() + { + Mark mark = new Mark(this, System.nanoTime()); + _marks.add(mark); + return mark; + } + + private synchronized Snapshot measure(Mark mark) + { + long now = System.nanoTime(); + _marks.remove(mark); + return new Snapshot( + _borrows - mark._borrows, + _acquireNanos - mark._acquireNanos, + held(now) - mark._heldNanos, + wall(now) - mark._wallNanos, + mark._maxActive, + Math.max(0, _active - mark._active) + ); + } + } + + /** Opens a measurement window for the current effective thread. Windows may nest. */ + public static @NotNull Mark mark() + { + return USAGE.computeIfAbsent(DbScope.getEffectiveThread(), _ -> new Usage()).mark(); + } + + /** Closes the window; unreturned counts connections borrowed since the mark and still held. */ + public static @NotNull Snapshot measure(@NotNull Mark mark) + { + return mark._usage.measure(mark); + } + + /** @return the Usage to credit when this connection is returned, or null if the thread has never been marked */ + static @Nullable Usage recordBorrow(long acquireNanos, long borrowedAt) + { + Usage usage = USAGE.get(DbScope.getEffectiveThread()); + if (null != usage) + usage.borrow(acquireNanos, borrowedAt); + return usage; + } + + static void recordReturn(@Nullable Usage usage, long borrowedAt) + { + if (null != usage) + usage.release(borrowedAt, System.nanoTime()); + } + + public static class TestCase extends Assert + { + private static Snapshot measureOnNewThread(ThrowingRunnable block) throws Exception + { + AtomicReference result = new AtomicReference<>(); + AtomicReference failure = new AtomicReference<>(); + Thread thread = new Thread(() -> { + Mark mark = mark(); + try + { + block.run(); + } + catch (Throwable t) + { + failure.set(t); + } + result.set(measure(mark)); + }, "ConnectionUsage test"); + thread.start(); + thread.join(); + if (null != failure.get()) + throw new AssertionError("Failure on test thread", failure.get()); + return result.get(); + } + + private interface ThrowingRunnable + { + void run() throws Exception; + } + + @Test + public void testConcurrentPooledBorrows() throws Exception + { + DbScope scope = DbScope.getLabKeyScope(); + Snapshot snapshot = measureOnNewThread(() -> { + try (Connection ignored1 = scope.getPooledConnection(); + Connection ignored2 = scope.getPooledConnection(); + Connection ignored3 = scope.getPooledConnection()) + { + Thread.sleep(5); + } + }); + assertEquals(3, snapshot.borrows()); + assertEquals(3, snapshot.maxConcurrent()); + assertEquals(0, snapshot.unreturned()); + assertTrue("Summed hold time should exceed the union", snapshot.heldNanos() > snapshot.wallNanos()); + assertTrue(snapshot.wallNanos() >= 5_000_000); + } + + @Test + public void testThreadConnectionRefCountIsOneBorrow() throws Exception + { + DbScope scope = DbScope.getLabKeyScope(); + Snapshot snapshot = measureOnNewThread(() -> { + try (Connection outer = scope.getConnection(); + Connection inner = scope.getConnection()) + { + assertSame(outer, inner); + } + }); + assertEquals(1, snapshot.borrows()); + assertEquals(1, snapshot.maxConcurrent()); + assertEquals(0, snapshot.unreturned()); + } + + @Test + public void testUnreturned() throws Exception + { + DbScope scope = DbScope.getLabKeyScope(); + AtomicReference held = new AtomicReference<>(); + Snapshot snapshot = measureOnNewThread(() -> held.set(scope.getPooledConnection())); + held.get().close(); + assertEquals(1, snapshot.borrows()); + assertEquals(1, snapshot.unreturned()); + } + + @Test + public void testSharedThreadChargesOwner() throws Exception + { + DbScope scope = DbScope.getLabKeyScope(); + Snapshot snapshot = measureOnNewThread(() -> { + Thread piggyback = new Thread(() -> { + try (Connection ignored = scope.getPooledConnection()) + { + } + catch (Exception e) + { + throw new RuntimeException(e); + } + }); + try (var ignored = DbScope.shareConnections(Thread.currentThread(), piggyback)) + { + piggyback.start(); + piggyback.join(); + } + }); + assertEquals(1, snapshot.borrows()); + assertEquals(0, snapshot.unreturned()); + } + + @Test + public void testNestedMarks() throws Exception + { + DbScope scope = DbScope.getLabKeyScope(); + AtomicReference inner = new AtomicReference<>(); + Snapshot outer = measureOnNewThread(() -> { + try (Connection ignored = scope.getPooledConnection()) + { + Mark mark = mark(); + try (Connection ignored2 = scope.getPooledConnection()) + { + } + inner.set(measure(mark)); + } + }); + assertEquals(2, outer.borrows()); + assertEquals(2, outer.maxConcurrent()); + assertEquals(1, inner.get().borrows()); + assertEquals(2, inner.get().maxConcurrent()); + assertTrue(outer.wallNanos() >= inner.get().wallNanos()); + } + } +} diff --git a/api/src/org/labkey/api/data/ConnectionWrapper.java b/api/src/org/labkey/api/data/ConnectionWrapper.java index 6e67fdb90ca..c1212ec5889 100644 --- a/api/src/org/labkey/api/data/ConnectionWrapper.java +++ b/api/src/org/labkey/api/data/ConnectionWrapper.java @@ -159,6 +159,10 @@ private void realClose() private volatile boolean _allowClose = true; + // Captured at borrow because the return can happen on another thread, e.g. the Cleaner + private volatile @Nullable ConnectionUsage.Usage _usage; + private long _borrowedAt; + static { // Issue 51483: DB query can be left running after shutting down server @@ -224,6 +228,14 @@ public ConnectionWrapper(Connection conn, DbScope scope, Integer spid, Connectio _cleanable = CLEANER.register(this, _state); } + /** Called only for real pool borrows, so wrappers created without one never record a return */ + void trackUsage(long acquireStart) + { + long now = System.nanoTime(); + _borrowedAt = now; + _usage = ConnectionUsage.recordBorrow(now - acquireStart, now); + } + /** this is a best guess logger, pass one in to be predictable */ static Logger getConnectionLogger() { @@ -555,6 +567,7 @@ private void realClose() private void realCloseInternal() throws SQLException { _openConnections.remove(this); + ConnectionUsage.recordReturn(_usage, _borrowedAt); _loggedLeaks.remove(this); // The Tomcat connection pool violates the API for close() - it throws an exception diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 9ba19871b81..1f8eba3eb5a 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -1457,6 +1457,7 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg } Connection conn; + long acquireStart = System.nanoTime(); try { @@ -1491,7 +1492,9 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg _initializedConnections.put(delegate, spid == null ? spidUnknown : spid); } - return new ConnectionWrapper(conn, this, spid, type, log); + ConnectionWrapper wrapper = new ConnectionWrapper(conn, this, spid, type, log); + wrapper.trackUsage(acquireStart); + return wrapper; } catch (Throwable t) { diff --git a/api/src/org/labkey/api/module/SimpleController.java b/api/src/org/labkey/api/module/SimpleController.java index 03c06d3cbdd..06bde7890ad 100644 --- a/api/src/org/labkey/api/module/SimpleController.java +++ b/api/src/org/labkey/api/module/SimpleController.java @@ -16,6 +16,7 @@ package org.labkey.api.module; import org.labkey.api.action.SpringActionController; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.Container; import org.labkey.api.util.Path; import org.labkey.api.view.ActionURL; @@ -57,7 +58,7 @@ public Controller resolveActionName(Controller actionController, String actionNa } @Override - public void addTime(Controller action, long elapsedTime) + public void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage) { } diff --git a/core/src/org/labkey/core/CoreModule.java b/core/src/org/labkey/core/CoreModule.java index a96ce5ad774..83fcf51d097 100644 --- a/core/src/org/labkey/core/CoreModule.java +++ b/core/src/org/labkey/core/CoreModule.java @@ -215,6 +215,7 @@ import org.labkey.core.admin.AdminConsoleServiceImpl; import org.labkey.core.admin.AdminController; import org.labkey.core.admin.AllowListType; +import org.labkey.core.admin.ConnectionUsageTsvWriter; import org.labkey.core.admin.CopyFileRootPipelineJob; import org.labkey.core.admin.CustomizeMenuForm; import org.labkey.core.admin.DisplayFormatAnalyzer; @@ -1049,24 +1050,25 @@ public void shutdownPre() { } - Logger logger = LogManager.getLogger(ActionsTsvWriter.class); - - if (null != logger) - { - StringBuilder buf = new StringBuilder(); + logTsv(new ActionsTsvWriter()); + logTsv(new ConnectionUsageTsvWriter()); + LOG.info("Completed logging statistics for actions prior to web application shut down"); + } - try (TSVWriter writer = new ActionsTsvWriter()) - { - writer.write(buf); - } - catch (IOException e) - { - LOG.error("Exception exporting action stats", e); - } + private void logTsv(TSVWriter writer) + { + StringBuilder buf = new StringBuilder(); - logger.info(buf.toString()); - LOG.info("Completed logging statistics for actions prior to web application shut down"); + try (writer) + { + writer.write(buf); } + catch (IOException e) + { + LOG.error("Exception exporting {}", writer.getClass().getSimpleName(), e); + } + + LogManager.getLogger(writer.getClass()).info(buf.toString()); } @Override diff --git a/core/src/org/labkey/core/admin/ActionsView.java b/core/src/org/labkey/core/admin/ActionsView.java index f7073b26582..6ba01174184 100644 --- a/core/src/org/labkey/core/admin/ActionsView.java +++ b/core/src/org/labkey/core/admin/ActionsView.java @@ -26,6 +26,7 @@ import org.labkey.api.view.HttpView; import java.io.PrintWriter; +import java.text.NumberFormat; import java.util.Map; class ActionsView extends HttpView @@ -41,7 +42,10 @@ class ActionsView extends HttpView protected void renderInternal(Object model, PrintWriter out) throws Exception { if (!_summary) + { out.println(PageFlowUtil.button("Export").href(new ActionURL(AdminController.ExportActionsAction.class, ContainerManager.getRoot()))); + out.println(PageFlowUtil.button("Export Connection Usage").href(new ActionURL(AdminController.ExportConnectionUsageAction.class, ContainerManager.getRoot()))); + } Map>> modules = ActionsHelper.getActionStatistics(); @@ -62,7 +66,14 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception out.print("Invocations"); out.print("Cumulative Time"); out.print("Average Time"); - out.print("Max Time"); + out.print("Max Time"); + out.print("Borrows"); + out.print("Borrows/Invocation"); + out.print("Hold Time"); + out.print("Hold %"); + out.print("Max Concurrent"); + out.print("Acquire Time"); + out.print("Unreturned"); } int totalActions = 0; @@ -116,6 +127,13 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception renderTd(out, stats.getElapsedTime()); renderTd(out, 0 == stats.getCount() ? 0 : stats.getElapsedTime() / stats.getCount()); renderTd(out, stats.getMaxTime()); + renderTd(out, stats.getBorrows()); + renderTd(out, stats.getBorrowsPerInvocation(), Formats.f2); + renderTd(out, stats.getConnectionWallTime()); + renderTd(out, stats.getConnectionHoldFraction(), Formats.percent1); + renderTd(out, stats.getMaxConcurrent()); + renderTd(out, stats.getAcquireTime()); + renderTd(out, stats.getUnreturned()); out.print(""); rowCount++; @@ -129,7 +147,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception if (!_summary) { out.print(""); - out.print(" Action Coverage"); + out.print(" Action Coverage"); } else { @@ -148,7 +166,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception if (!_summary) { out.print(""); - out.print(" "); + out.print(" "); rowCount++; } } @@ -168,7 +186,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception else { out.print(""); - out.print("Total Action Coverage"); + out.print("Total Action Coverage"); } out.print(""); @@ -179,9 +197,14 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception private void renderTd(PrintWriter out, Number d) + { + renderTd(out, d, Formats.commaf0); + } + + private void renderTd(PrintWriter out, Number d, NumberFormat format) { out.print(""); - out.print(Formats.commaf0.format(d)); + out.print(format.format(d)); out.print(""); } } diff --git a/core/src/org/labkey/core/admin/AdminController.java b/core/src/org/labkey/core/admin/AdminController.java index c2f115a44b8..9309c8987e1 100644 --- a/core/src/org/labkey/core/admin/AdminController.java +++ b/core/src/org/labkey/core/admin/AdminController.java @@ -3037,6 +3037,19 @@ public void export(Object form, HttpServletResponse response, BindException erro } } + @AdminConsoleAction + public static class ExportConnectionUsageAction extends ExportAction + { + @Override + public void export(Object form, HttpServletResponse response, BindException errors) throws Exception + { + try (ConnectionUsageTsvWriter writer = new ConnectionUsageTsvWriter()) + { + writer.write(response); + } + } + } + private static ActionURL getQueriesURL(@Nullable String statName) { ActionURL url = new ActionURL(QueriesAction.class, ContainerManager.getRoot()); @@ -12710,6 +12723,7 @@ controller.new ShowPrimaryLogAction(), controller.new ShowCspReportLogAction(), controller.new ShowThreadsAction(), new ExportActionsAction(), + new ExportConnectionUsageAction(), new ExportQueriesAction(), new MemoryChartAction(), new ShowAdminAction() diff --git a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java new file mode 100644 index 00000000000..bd8e4a4a859 --- /dev/null +++ b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java @@ -0,0 +1,85 @@ +/* + * Copyright (c) 2026 LabKey Corporation + * + * Licensed 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.labkey.core.admin; + +import org.labkey.api.action.SpringActionController.ActionStats; +import org.labkey.api.admin.ActionsHelper; +import org.labkey.api.data.TSVWriter; +import org.labkey.api.util.UnexpectedException; + +import java.util.Arrays; +import java.util.Comparator; +import java.util.List; +import java.util.Locale; + +/** Invoked actions only, heaviest connection borrowers first */ +public class ConnectionUsageTsvWriter extends TSVWriter +{ + private record Row(String module, String controller, String action, ActionStats stats) {} + + @Override + protected void writeColumnHeaders() + { + writeLine(Arrays.asList("module", "controller", "action", "invocations", "cumulative", "borrows", "borrowsPerInvocation", + "holdMs", "holdPercent", "connectionMs", "maxConcurrent", "acquireMs", "unreturned")); + } + + @Override + protected int writeBody() + { + List rows; + + try + { + rows = ActionsHelper.getActionStatistics().entrySet().stream() + .flatMap(module -> module.getValue().entrySet().stream() + .flatMap(controller -> controller.getValue().entrySet().stream() + .map(action -> new Row(module.getKey(), controller.getKey(), action.getKey(), action.getValue())))) + .filter(row -> row.stats().getCount() > 0) + .sorted(Comparator.comparingLong((Row row) -> row.stats().getBorrows()) + .thenComparingLong(row -> row.stats().getCount()) + .reversed()) + .toList(); + } + catch (Exception e) + { + throw UnexpectedException.wrap(e); + } + + for (Row row : rows) + { + ActionStats stats = row.stats(); + writeLine(Arrays.asList( + row.module(), + row.controller(), + row.action(), + String.valueOf(stats.getCount()), + String.valueOf(stats.getElapsedTime()), + String.valueOf(stats.getBorrows()), + String.format(Locale.ROOT, "%.2f", stats.getBorrowsPerInvocation()), + String.valueOf(stats.getConnectionWallTime()), + String.format(Locale.ROOT, "%.1f", stats.getConnectionHoldFraction() * 100), + String.valueOf(stats.getConnectionHoldTime()), + String.valueOf(stats.getMaxConcurrent()), + String.valueOf(stats.getAcquireTime()), + String.valueOf(stats.getUnreturned()) + )); + } + + return rows.size(); + } +} From 8c125ce0abfcc4f0806d994ae02071b65fa8c809 Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sat, 26 Sep 2026 14:34:36 -0700 Subject: [PATCH 5/9] Track connection pool stats --- .../labkey/api/data/dialect/SqlDialect.java | 13 ++++++ .../labkey/core/admin/AdminController.java | 40 +++++++++++++++++++ 2 files changed, 53 insertions(+) diff --git a/api/src/org/labkey/api/data/dialect/SqlDialect.java b/api/src/org/labkey/api/data/dialect/SqlDialect.java index c66384c8e0d..533dd1f6cf3 100644 --- a/api/src/org/labkey/api/data/dialect/SqlDialect.java +++ b/api/src/org/labkey/api/data/dialect/SqlDialect.java @@ -1713,6 +1713,19 @@ public Integer getMaxTotal() } } + public Integer getMaxIdle() + { + try + { + return callGetter("getMaxIdle"); + } + catch (ServletException e) + { + LOG.error("Could not extract connection pool max idle from data source \"{}\"", _dsName); + return null; + } + } + public Integer getNumActive() { try diff --git a/core/src/org/labkey/core/admin/AdminController.java b/core/src/org/labkey/core/admin/AdminController.java index 9309c8987e1..59c0ddde94b 100644 --- a/core/src/org/labkey/core/admin/AdminController.java +++ b/core/src/org/labkey/core/admin/AdminController.java @@ -138,6 +138,7 @@ import org.labkey.api.data.TransactionFilter; import org.labkey.api.data.WorkbookContainerType; import org.labkey.api.data.dialect.BasePostgreSqlDialect; +import org.labkey.api.data.dialect.SqlDialect.DataSourcePropertyReader; import org.labkey.api.data.dialect.SqlDialect.ExecutionPlanType; import org.labkey.api.data.queryprofiler.QueryProfiler; import org.labkey.api.data.queryprofiler.QueryProfiler.QueryStatTsvWriter; @@ -3050,6 +3051,44 @@ public void export(Object form, HttpServletResponse response, BindException erro } } + @AdminConsoleAction + public static class GetConnectionPoolStatsAction extends ReadOnlyApiAction + { + @Override + public Object execute(Object o, BindException errors) + { + // Initialized scopes only, so an unreachable external data source isn't probed + return Map.of("dataSources", DbScope.getInitializedDbScopes().stream() + .map(GetConnectionPoolStatsAction::getPoolStats) + .toList()); + } + + private static Map getPoolStats(DbScope scope) + { + DataSourcePropertyReader props = scope.getDataSourceProperties(); + DataSourcePropertyReader.PoolStatistics pool = props.getPoolStatistics(); + Map result = new LinkedHashMap<>(); + result.put("name", scope.getDataSourceName()); + result.put("isLabKeyScope", scope.isLabKeyScope()); + result.put("maxTotal", props.getMaxTotal()); + result.put("maxIdle", props.getMaxIdle()); + result.put("numActive", props.getNumActive()); + result.put("numIdle", props.getNumIdle()); + if (null != pool) + { + result.put("createdCount", pool.createdCount()); + result.put("destroyedCount", pool.destroyedCount()); + result.put("destroyedByEvictorCount", pool.destroyedByEvictorCount()); + result.put("destroyedByBorrowValidationCount", pool.destroyedByBorrowValidationCount()); + result.put("borrowedCount", pool.borrowedCount()); + result.put("numWaiters", pool.numWaiters()); + result.put("meanBorrowWaitMillis", pool.meanBorrowWaitMillis()); + result.put("maxBorrowWaitMillis", pool.maxBorrowWaitMillis()); + } + return result; + } + } + private static ActionURL getQueriesURL(@Nullable String statName) { ActionURL url = new ActionURL(QueriesAction.class, ContainerManager.getRoot()); @@ -12724,6 +12763,7 @@ controller.new ShowCspReportLogAction(), controller.new ShowThreadsAction(), new ExportActionsAction(), new ExportConnectionUsageAction(), + new GetConnectionPoolStatsAction(), new ExportQueriesAction(), new MemoryChartAction(), new ShowAdminAction() From ac1d4c1d2405b99abccb66c633efd4ed094fcad4 Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sat, 26 Sep 2026 18:19:49 -0700 Subject: [PATCH 6/9] More granular timers and potential concurrency improvements --- .../api/action/SpringActionController.java | 40 +++++++++++++++++- .../org/labkey/api/data/ConnectionUsage.java | 37 ++++++++++++++--- .../labkey/api/data/ConnectionWrapper.java | 25 +++++------ api/src/org/labkey/api/data/DbScope.java | 6 ++- api/src/org/labkey/api/util/MemTracker.java | 41 ++++++++++++++----- .../core/admin/ConnectionUsageTsvWriter.java | 9 +++- 6 files changed, 125 insertions(+), 33 deletions(-) diff --git a/api/src/org/labkey/api/action/SpringActionController.java b/api/src/org/labkey/api/action/SpringActionController.java index 3954cd7b7b1..04215b373bc 100644 --- a/api/src/org/labkey/api/action/SpringActionController.java +++ b/api/src/org/labkey/api/action/SpringActionController.java @@ -223,6 +223,12 @@ public interface ActionStats long getConnectionWallTime(); int getMaxConcurrent(); long getAcquireTime(); + /** Portion of acquire time inside the pool's getConnection() */ + long getAcquirePoolTime(); + /** Portion of acquire time in per-connection setup */ + long getAcquireSetupTime(); + /** Thread CPU time consumed while acquiring */ + long getAcquireCpuTime(); long getUnreturned(); boolean hasExceptions(); List getExceptions(); @@ -810,6 +816,9 @@ public static abstract class BaseActionDescriptor implements ActionDescriptor private long _wallNanos = 0; private int _maxConcurrent = 0; private long _acquireNanos = 0; + private long _acquirePoolNanos = 0; + private long _acquireSetupNanos = 0; + private long _acquireCpuNanos = 0; private long _unreturned = 0; private List _exceptions = null; @@ -827,6 +836,9 @@ synchronized public void addTime(long time, ConnectionUsage.Snapshot connectionU _wallNanos += connectionUsage.wallNanos(); _maxConcurrent = Math.max(_maxConcurrent, connectionUsage.maxConcurrent()); _acquireNanos += connectionUsage.acquireNanos(); + _acquirePoolNanos += connectionUsage.poolNanos(); + _acquireSetupNanos += connectionUsage.setupNanos(); + _acquireCpuNanos += connectionUsage.acquireCpuNanos(); _unreturned += connectionUsage.unreturned(); } @@ -842,7 +854,7 @@ public void addException(Exception ex) @Override synchronized public ActionStats getStats() { - return new BaseActionStats(_count, _elapsedTime, _maxTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _unreturned, _exceptions); + return new BaseActionStats(_count, _elapsedTime, _maxTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _acquirePoolNanos, _acquireSetupNanos, _acquireCpuNanos, _unreturned, _exceptions); } // Immutable stats holder to eliminate external synchronization needs @@ -856,10 +868,13 @@ private class BaseActionStats implements ActionStats private final long _wallNanos; private final int _maxConcurrent; private final long _acquireNanos; + private final long _acquirePoolNanos; + private final long _acquireSetupNanos; + private final long _acquireCpuNanos; private final long _unreturned; private final List _exceptions; - private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long unreturned, List ex) + private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long acquirePoolNanos, long acquireSetupNanos, long acquireCpuNanos, long unreturned, List ex) { _count = count; _elapsedTime = elapsedTime; @@ -869,6 +884,9 @@ private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows _wallNanos = wallNanos; _maxConcurrent = maxConcurrent; _acquireNanos = acquireNanos; + _acquirePoolNanos = acquirePoolNanos; + _acquireSetupNanos = acquireSetupNanos; + _acquireCpuNanos = acquireCpuNanos; _unreturned = unreturned; _exceptions = ex; } @@ -921,6 +939,24 @@ public long getAcquireTime() return TimeUnit.NANOSECONDS.toMillis(_acquireNanos); } + @Override + public long getAcquirePoolTime() + { + return TimeUnit.NANOSECONDS.toMillis(_acquirePoolNanos); + } + + @Override + public long getAcquireSetupTime() + { + return TimeUnit.NANOSECONDS.toMillis(_acquireSetupNanos); + } + + @Override + public long getAcquireCpuTime() + { + return TimeUnit.NANOSECONDS.toMillis(_acquireCpuNanos); + } + @Override public long getUnreturned() { diff --git a/api/src/org/labkey/api/data/ConnectionUsage.java b/api/src/org/labkey/api/data/ConnectionUsage.java index a0adb763569..01f60d9855f 100644 --- a/api/src/org/labkey/api/data/ConnectionUsage.java +++ b/api/src/org/labkey/api/data/ConnectionUsage.java @@ -20,6 +20,8 @@ import org.junit.Assert; import org.junit.Test; +import java.lang.management.ManagementFactory; +import java.lang.management.ThreadMXBean; import java.sql.Connection; import java.util.ArrayList; import java.util.Collections; @@ -35,10 +37,19 @@ public class ConnectionUsage { private static final Map USAGE = Collections.synchronizedMap(new WeakHashMap<>()); + private static final ThreadMXBean THREADS = ManagementFactory.getThreadMXBean(); + private static final boolean CPU_TIME = THREADS.isCurrentThreadCpuTimeSupported() && THREADS.isThreadCpuTimeEnabled(); - public record Snapshot(long borrows, long acquireNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned) + /** acquireNanos is the whole borrow: poolNanos in getConnection(), setupNanos for per-connection setup, and the remainder building the wrapper */ + public record Snapshot(long borrows, long acquireNanos, long poolNanos, long setupNanos, long acquireCpuNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned) { - public static final Snapshot EMPTY = new Snapshot(0, 0, 0, 0, 0, 0); + public static final Snapshot EMPTY = new Snapshot(0, 0, 0, 0, 0, 0, 0, 0, 0); + } + + /** Current thread's CPU time, or 0 when the JVM can't measure it */ + static long currentThreadCpuNanos() + { + return CPU_TIME ? THREADS.getCurrentThreadCpuTime() : 0; } /** Opaque token returned by {@link #mark()} */ @@ -47,6 +58,9 @@ public static final class Mark private final Usage _usage; private final long _borrows; private final long _acquireNanos; + private final long _poolNanos; + private final long _setupNanos; + private final long _acquireCpuNanos; private final long _heldNanos; private final long _wallNanos; private final int _active; @@ -57,6 +71,9 @@ private Mark(Usage usage, long now) _usage = usage; _borrows = usage._borrows; _acquireNanos = usage._acquireNanos; + _poolNanos = usage._poolNanos; + _setupNanos = usage._setupNanos; + _acquireCpuNanos = usage._acquireCpuNanos; _heldNanos = usage.held(now); _wallNanos = usage.wall(now); _active = usage._active; @@ -69,6 +86,9 @@ static final class Usage { private long _borrows; private long _acquireNanos; + private long _poolNanos; + private long _setupNanos; + private long _acquireCpuNanos; private long _heldClosedNanos; private long _openStartSum; private long _wallClosedNanos; @@ -86,10 +106,13 @@ private long wall(long now) return _wallClosedNanos + (_active > 0 ? now - _wallStart : 0); } - private synchronized void borrow(long acquireNanos, long now) + private synchronized void borrow(long acquireNanos, long poolNanos, long setupNanos, long acquireCpuNanos, long now) { _borrows++; _acquireNanos += acquireNanos; + _poolNanos += poolNanos; + _setupNanos += setupNanos; + _acquireCpuNanos += acquireCpuNanos; if (_active++ == 0) _wallStart = now; _openStartSum += now; @@ -120,6 +143,9 @@ private synchronized Snapshot measure(Mark mark) return new Snapshot( _borrows - mark._borrows, _acquireNanos - mark._acquireNanos, + _poolNanos - mark._poolNanos, + _setupNanos - mark._setupNanos, + _acquireCpuNanos - mark._acquireCpuNanos, held(now) - mark._heldNanos, wall(now) - mark._wallNanos, mark._maxActive, @@ -141,11 +167,11 @@ private synchronized Snapshot measure(Mark mark) } /** @return the Usage to credit when this connection is returned, or null if the thread has never been marked */ - static @Nullable Usage recordBorrow(long acquireNanos, long borrowedAt) + static @Nullable Usage recordBorrow(long acquireNanos, long poolNanos, long setupNanos, long acquireCpuNanos, long borrowedAt) { Usage usage = USAGE.get(DbScope.getEffectiveThread()); if (null != usage) - usage.borrow(acquireNanos, borrowedAt); + usage.borrow(acquireNanos, poolNanos, setupNanos, acquireCpuNanos, borrowedAt); return usage; } @@ -199,6 +225,7 @@ public void testConcurrentPooledBorrows() throws Exception }); assertEquals(3, snapshot.borrows()); assertEquals(3, snapshot.maxConcurrent()); + assertTrue("Acquire phases can't exceed the whole", snapshot.poolNanos() + snapshot.setupNanos() <= snapshot.acquireNanos()); assertEquals(0, snapshot.unreturned()); assertTrue("Summed hold time should exceed the union", snapshot.heldNanos() > snapshot.wallNanos()); assertTrue(snapshot.wallNanos() >= 5_000_000); diff --git a/api/src/org/labkey/api/data/ConnectionWrapper.java b/api/src/org/labkey/api/data/ConnectionWrapper.java index c1212ec5889..4f62ed78da0 100644 --- a/api/src/org/labkey/api/data/ConnectionWrapper.java +++ b/api/src/org/labkey/api/data/ConnectionWrapper.java @@ -23,6 +23,7 @@ import org.apache.logging.log4j.core.LoggerContext; import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.labkey.api.action.SpringActionController; import org.labkey.api.data.DbScope.ConnectionType; import org.labkey.api.data.dialect.SqlDialect; import org.labkey.api.data.dialect.StatementWrapper; @@ -81,6 +82,7 @@ public class ConnectionWrapper implements java.sql.Connection private static final Logger LOG = LogHelper.getLogger(ConnectionWrapper.class, "All JDBC metadata and SQL execution calls being made"); private static final Cleaner CLEANER = Cleaner.create(); + private static final StackWalker STACK_WALKER = StackWalker.getInstance(Set.of(StackWalker.Option.RETAIN_CLASS_REFERENCE, StackWalker.Option.DROP_METHOD_INFO)); private static class ConnectionState implements Runnable { @@ -229,11 +231,12 @@ public ConnectionWrapper(Connection conn, DbScope scope, Integer spid, Connectio } /** Called only for real pool borrows, so wrappers created without one never record a return */ - void trackUsage(long acquireStart) + void trackUsage(long acquireStart, long poolDone, long setupDone, long acquireCpuStart) { + long cpuNow = ConnectionUsage.currentThreadCpuNanos(); long now = System.nanoTime(); _borrowedAt = now; - _usage = ConnectionUsage.recordBorrow(now - acquireStart, now); + _usage = ConnectionUsage.recordBorrow(now - acquireStart, poolDone - acquireStart, setupDone - poolDone, cpuNow - acquireCpuStart, now); } /** this is a best guess logger, pass one in to be predictable */ @@ -241,16 +244,14 @@ static Logger getConnectionLogger() { if (_explicitLogger) return LOG; - StackTraceElement[] stes = Thread.currentThread().getStackTrace(); - for (StackTraceElement ste : stes) - { - String className = ste.getClassName(); - if (className.equals("org.labkey.api.view.ViewServlet") || className.equals("org.labkey.api.action.SpringActionController")) - break; - if (className.endsWith("Controller") && !className.startsWith("org.labkey.api.view")) - return LogManager.getLogger(className); - } - return LOG; + // Runs on every borrow, so walk lazily and stop early rather than materializing the whole stack + return STACK_WALKER.walk(frames -> frames + .map(StackWalker.StackFrame::getDeclaringClass) + .takeWhile(clazz -> clazz != ViewServlet.class && clazz != SpringActionController.class) + .filter(clazz -> clazz.getName().endsWith("Controller") && !clazz.getPackageName().startsWith(ViewServlet.class.getPackageName())) + .findFirst() + .map(clazz -> LogManager.getLogger(clazz.getName())) + .orElse(LOG)); } public @NotNull Logger getLogger() diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 99ffd5ee86d..7a6c7746ffe 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -1472,6 +1472,7 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg } Connection conn; + long acquireCpuStart = ConnectionUsage.currentThreadCpuNanos(); long acquireStart = System.nanoTime(); try @@ -1483,6 +1484,8 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg throw new ConfigurationException("Can't create a database connection for data source " + getDbScopeLoader().getDsName(), e); } + long poolDone = System.nanoTime(); + try { if (!conn.getAutoCommit()) @@ -1507,8 +1510,9 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg _initializedConnections.put(delegate, spid == null ? spidUnknown : spid); } + long setupDone = System.nanoTime(); ConnectionWrapper wrapper = new ConnectionWrapper(conn, this, spid, type, log); - wrapper.trackUsage(acquireStart); + wrapper.trackUsage(acquireStart, poolDone, setupDone, acquireCpuStart); return wrapper; } catch (Throwable t) diff --git a/api/src/org/labkey/api/util/MemTracker.java b/api/src/org/labkey/api/util/MemTracker.java index cc64adc31a4..1b146ed068b 100644 --- a/api/src/org/labkey/api/util/MemTracker.java +++ b/api/src/org/labkey/api/util/MemTracker.java @@ -420,33 +420,52 @@ public boolean shouldDisplay(Thread thread) // reference tracking impl // + // Separate from this object's monitor so tracking allocations doesn't contend with request profiling + private final Object _referencesLock = new Object(); private final Map _references = new ReferenceIdentityMap<>(ReferenceStrength.WEAK, ReferenceStrength.HARD, true); private final List _listeners = new CopyOnWriteArrayList<>(); - private synchronized boolean _put(Object object) + private boolean _put(Object object) { if (object != null) - _references.put(object, new AllocationInfo()); + { + // Built outside the lock because it may capture a stack trace + AllocationInfo allocationInfo = new AllocationInfo(); + synchronized (_referencesLock) + { + _references.put(object, allocationInfo); + } + } + // Touches only the calling thread's RequestInfo MiniProfiler.addObject(object); return true; } - private synchronized boolean _remove(Object object) + private boolean _remove(Object object) { if (object != null) - _references.remove(object); + { + synchronized (_referencesLock) + { + _references.remove(object); + } + } return true; } - public synchronized List getReferences() + public List getReferences() { - List refs = new ArrayList<>(_references.size()); - for (Map.Entry entry : _references.entrySet()) + List refs; + synchronized (_referencesLock) { - // get a hard reference so we know that we're placing an actual object into our list: - Object obj = entry.getKey(); - if (obj != null) - refs.add(new HeldReference(entry.getKey(), entry.getValue())); + refs = new ArrayList<>(_references.size()); + for (Map.Entry entry : _references.entrySet()) + { + // get a hard reference so we know that we're placing an actual object into our list: + Object obj = entry.getKey(); + if (obj != null) + refs.add(new HeldReference(obj, entry.getValue())); + } } refs.sort(Comparator.comparing(HeldReference::getClassName, String.CASE_INSENSITIVE_ORDER)); return refs; diff --git a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java index bd8e4a4a859..233bb77cdbc 100644 --- a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java +++ b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java @@ -35,7 +35,8 @@ private record Row(String module, String controller, String action, ActionStats protected void writeColumnHeaders() { writeLine(Arrays.asList("module", "controller", "action", "invocations", "cumulative", "borrows", "borrowsPerInvocation", - "holdMs", "holdPercent", "connectionMs", "maxConcurrent", "acquireMs", "unreturned")); + "holdMs", "holdPercent", "connectionMs", "maxConcurrent", "acquireMs", "unreturned", + "acquirePoolMs", "acquireSetupMs", "acquireWrapperMs", "acquireCpuMs")); } @Override @@ -76,7 +77,11 @@ protected int writeBody() String.valueOf(stats.getConnectionHoldTime()), String.valueOf(stats.getMaxConcurrent()), String.valueOf(stats.getAcquireTime()), - String.valueOf(stats.getUnreturned()) + String.valueOf(stats.getUnreturned()), + String.valueOf(stats.getAcquirePoolTime()), + String.valueOf(stats.getAcquireSetupTime()), + String.valueOf(Math.max(0, stats.getAcquireTime() - stats.getAcquirePoolTime() - stats.getAcquireSetupTime())), + String.valueOf(stats.getAcquireCpuTime()) )); } From 87dceba7b2993e4490805a1d15e4d59a3c04edbc Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sun, 27 Sep 2026 10:53:30 -0700 Subject: [PATCH 7/9] Skip redundant isolation-level round trips when streaming from Postgres PostgreSQL runs READ UNCOMMITTED as READ COMMITTED, so cursor-based fetching only needs autoCommit off; this drops three statements per uncached borrow. Adds a pg_cursors test that verifies uncached reads still stream. --- .../labkey/api/data/SqlSelectorTestCase.java | 58 +++++++++++++++++-- .../data/dialect/BasePostgreSqlDialect.java | 5 +- 2 files changed, 54 insertions(+), 9 deletions(-) diff --git a/api/src/org/labkey/api/data/SqlSelectorTestCase.java b/api/src/org/labkey/api/data/SqlSelectorTestCase.java index 52fcdfc99c9..c5e39b418f7 100644 --- a/api/src/org/labkey/api/data/SqlSelectorTestCase.java +++ b/api/src/org/labkey/api/data/SqlSelectorTestCase.java @@ -20,7 +20,9 @@ import org.labkey.api.data.dialect.SqlDialect; import java.sql.Connection; +import java.sql.ResultSet; import java.sql.SQLException; +import java.sql.Statement; import java.util.Collection; import java.util.Collections; import java.util.IdentityHashMap; @@ -29,7 +31,6 @@ import java.util.stream.Stream; import static java.sql.Connection.TRANSACTION_READ_COMMITTED; -import static java.sql.Connection.TRANSACTION_READ_UNCOMMITTED; public class SqlSelectorTestCase extends AbstractSelectorTestCase { @@ -194,7 +195,6 @@ public void testJdbcUncached() throws SQLException try (Connection conn2 = new SqlSelector(scope, "SELECT RowId, Body FROM comm.Announcements").getConnection()) { assertNotEquals(conn, conn2); - assertEquals(TRANSACTION_READ_UNCOMMITTED, conn2.getTransactionIsolation()); assertFalse(conn2.getAutoCommit()); } @@ -214,7 +214,6 @@ public void testJdbcUncached() throws SQLException try (Connection conn2 = new SqlSelector(scope, "SELECT RowId, Body FROM comm.Announcements").setJdbcCaching(false).getConnection()) { assertNotEquals(conn, conn2); - assertEquals(TRANSACTION_READ_UNCOMMITTED, conn2.getTransactionIsolation()); assertFalse(conn2.getAutoCommit()); } } @@ -238,7 +237,6 @@ public void testJdbcUncached() throws SQLException assertEquals(borrowed, nested); } - assertEquals(TRANSACTION_READ_UNCOMMITTED, borrowed.getTransactionIsolation()); assertFalse(borrowed.getAutoCommit()); } finally @@ -293,7 +291,6 @@ public void testNestedQueryDuringForEach() throws SQLException callbackConnections.add(nested); assertFalse("Nested access during forEach() should run on the uncached borrowed connection", nested.getAutoCommit()); - assertEquals(TRANSACTION_READ_UNCOMMITTED, nested.getTransactionIsolation()); } // A nested self-contained query must return correct results even though the outer server-side cursor is open @@ -313,6 +310,57 @@ public void testNestedQueryDuringForEach() throws SQLException } } + // More rows than the dialect's default fetch size (1000), so an uncached read leaves its cursor open after the first batch + private static final String STREAMING_SQL = "SELECT g FROM generate_series(1, 5000) g"; + private static final String OPEN_CURSOR_SQL = "SELECT COUNT(*) FROM pg_cursors WHERE statement LIKE 'SELECT g FROM generate_series%'"; + + // pg_cursors is per-session, so each check runs on the connection that's streaming + @Test + public void testJdbcUncachedStreamsFromCursor() throws SQLException + { + DbScope scope = CoreSchema.getInstance().getScope(); + assertFalse("Test assumes no active transaction on this thread", scope.isTransactionActive()); + + // Control: with autoCommit on, pgjdbc buffers the whole result and leaves no cursor behind + try (Connection conn = scope.getConnection(); Statement stmt = conn.createStatement(); ResultSet rs = stmt.executeQuery(STREAMING_SQL)) + { + assertTrue(conn.getAutoCommit()); + assertTrue(rs.next()); + assertEquals("Cached read should not hold a cursor open", 0, countOpenCursors(conn)); + } + + // Dedicated uncached connection + try (Connection conn = new SqlSelector(scope, STREAMING_SQL).getConnection(); Statement stmt = conn.createStatement(); ResultSet rs = stmt.executeQuery(STREAMING_SQL)) + { + assertTrue(rs.next()); + assertEquals("Uncached read should stream from an open cursor", 1, countOpenCursors(conn)); + + int rows = 1; + while (rs.next()) + rows++; + assertEquals(5000, rows); + } + + // Shared thread connection borrowed by forEach(); the nested query reuses it, so it sees the outer cursor + MutableInt visited = new MutableInt(0); + MutableInt cursorsDuringIteration = new MutableInt(-1); + new SqlSelector(scope, STREAMING_SQL).forEach(Integer.class, g -> { + if (visited.getAndIncrement() == 0) + cursorsDuringIteration.setValue(new SqlSelector(scope, OPEN_CURSOR_SQL).getObject(Integer.class)); + }); + assertEquals(5000, visited.intValue()); + assertEquals("forEach() should stream from an open cursor", 1, cursorsDuringIteration.intValue()); + } + + private static int countOpenCursors(Connection conn) throws SQLException + { + try (Statement stmt = conn.createStatement(); ResultSet rs = stmt.executeQuery(OPEN_CURSOR_SQL)) + { + assertTrue(rs.next()); + return rs.getInt(1); + } + } + // Passing in a Connection and calling setJdbcCaching() should throw @Test(expected = IllegalStateException.class) public void testJdbcUncachedTrue() throws SQLException diff --git a/api/src/org/labkey/api/data/dialect/BasePostgreSqlDialect.java b/api/src/org/labkey/api/data/dialect/BasePostgreSqlDialect.java index 61ad4f9ffba..e20df648ec5 100644 --- a/api/src/org/labkey/api/data/dialect/BasePostgreSqlDialect.java +++ b/api/src/org/labkey/api/data/dialect/BasePostgreSqlDialect.java @@ -1008,9 +1008,7 @@ private Closer configureToDisableJdbcCaching(ConnectionWrapper connection, DbSco try { - // See http://stackoverflow.com/questions/1468036/java-jdbc-ignores-setfetchsize - int previousTransactionIsolation = connection.getTransactionIsolation(); - connection.setTransactionIsolation(Connection.TRANSACTION_READ_UNCOMMITTED); + // pgjdbc streams through a server-side cursor only when autoCommit is off. See http://stackoverflow.com/questions/1468036/java-jdbc-ignores-setfetchsize connection.setAutoCommit(false); Closer previous = connection.getRunOnClose(); // We know this is a no-op closer, but do this just in case these get shared or wrapped in the future @@ -1018,7 +1016,6 @@ private Closer configureToDisableJdbcCaching(ConnectionWrapper connection, DbSco return () -> { previous.close(); connection.setAutoCommit(true); - connection.setTransactionIsolation(previousTransactionIsolation); }; } catch (SQLException e) From d495eb8172fb8d934dc0586c599a49a6de58bbbf Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sat, 3 Oct 2026 14:57:20 -0700 Subject: [PATCH 8/9] Gate per-action connection usage tracking and drop thread CPU timing Tracking is on when assertions are enabled and can be toggled from the profiler settings until restart; also closes the measurement window for requests that never resolve an action, which leaked marks on pooled threads. --- .../api/action/SpringActionController.java | 32 +++--- .../org/labkey/api/data/ConnectionUsage.java | 106 +++++++++++++----- .../labkey/api/data/ConnectionWrapper.java | 5 +- api/src/org/labkey/api/data/DbScope.java | 11 +- .../labkey/api/miniprofiler/MiniProfiler.java | 18 ++- core/src/org/labkey/core/CoreModule.java | 4 +- .../org/labkey/core/admin/ActionsView.java | 48 +++++--- .../core/admin/ConnectionUsageTsvWriter.java | 5 +- .../labkey/core/admin/miniprofiler/manage.jsp | 9 ++ 9 files changed, 159 insertions(+), 79 deletions(-) diff --git a/api/src/org/labkey/api/action/SpringActionController.java b/api/src/org/labkey/api/action/SpringActionController.java index 04215b373bc..4b569b57670 100644 --- a/api/src/org/labkey/api/action/SpringActionController.java +++ b/api/src/org/labkey/api/action/SpringActionController.java @@ -227,8 +227,6 @@ public interface ActionStats long getAcquirePoolTime(); /** Portion of acquire time in per-connection setup */ long getAcquireSetupTime(); - /** Thread CPU time consumed while acquiring */ - long getAcquireCpuTime(); long getUnreturned(); boolean hasExceptions(); List getExceptions(); @@ -584,11 +582,19 @@ public ModelAndView handleRequest(HttpServletRequest request, @NotNull HttpServl } finally { - afterAction(throwable); - clearActionForThread(controller); + try + { + afterAction(throwable); + clearActionForThread(controller); + } + finally + { + // Measure even when no action resolved, else the unclosed mark stays on this pooled thread forever + ConnectionUsage.Snapshot connectionUsage = ConnectionUsage.measure(connectionMark); - if (null != controller) - _actionResolver.addTime(controller, System.currentTimeMillis() - startTime, ConnectionUsage.measure(connectionMark)); + if (null != controller) + _actionResolver.addTime(controller, System.currentTimeMillis() - startTime, connectionUsage); + } } return null; @@ -818,7 +824,6 @@ public static abstract class BaseActionDescriptor implements ActionDescriptor private long _acquireNanos = 0; private long _acquirePoolNanos = 0; private long _acquireSetupNanos = 0; - private long _acquireCpuNanos = 0; private long _unreturned = 0; private List _exceptions = null; @@ -838,7 +843,6 @@ synchronized public void addTime(long time, ConnectionUsage.Snapshot connectionU _acquireNanos += connectionUsage.acquireNanos(); _acquirePoolNanos += connectionUsage.poolNanos(); _acquireSetupNanos += connectionUsage.setupNanos(); - _acquireCpuNanos += connectionUsage.acquireCpuNanos(); _unreturned += connectionUsage.unreturned(); } @@ -854,7 +858,7 @@ public void addException(Exception ex) @Override synchronized public ActionStats getStats() { - return new BaseActionStats(_count, _elapsedTime, _maxTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _acquirePoolNanos, _acquireSetupNanos, _acquireCpuNanos, _unreturned, _exceptions); + return new BaseActionStats(_count, _elapsedTime, _maxTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _acquirePoolNanos, _acquireSetupNanos, _unreturned, _exceptions); } // Immutable stats holder to eliminate external synchronization needs @@ -870,11 +874,10 @@ private class BaseActionStats implements ActionStats private final long _acquireNanos; private final long _acquirePoolNanos; private final long _acquireSetupNanos; - private final long _acquireCpuNanos; private final long _unreturned; private final List _exceptions; - private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long acquirePoolNanos, long acquireSetupNanos, long acquireCpuNanos, long unreturned, List ex) + private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long acquirePoolNanos, long acquireSetupNanos, long unreturned, List ex) { _count = count; _elapsedTime = elapsedTime; @@ -886,7 +889,6 @@ private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows _acquireNanos = acquireNanos; _acquirePoolNanos = acquirePoolNanos; _acquireSetupNanos = acquireSetupNanos; - _acquireCpuNanos = acquireCpuNanos; _unreturned = unreturned; _exceptions = ex; } @@ -951,12 +953,6 @@ public long getAcquireSetupTime() return TimeUnit.NANOSECONDS.toMillis(_acquireSetupNanos); } - @Override - public long getAcquireCpuTime() - { - return TimeUnit.NANOSECONDS.toMillis(_acquireCpuNanos); - } - @Override public long getUnreturned() { diff --git a/api/src/org/labkey/api/data/ConnectionUsage.java b/api/src/org/labkey/api/data/ConnectionUsage.java index 01f60d9855f..a25adfe5d47 100644 --- a/api/src/org/labkey/api/data/ConnectionUsage.java +++ b/api/src/org/labkey/api/data/ConnectionUsage.java @@ -17,11 +17,11 @@ import org.jetbrains.annotations.NotNull; import org.jetbrains.annotations.Nullable; +import org.junit.After; import org.junit.Assert; +import org.junit.Before; import org.junit.Test; -import java.lang.management.ManagementFactory; -import java.lang.management.ThreadMXBean; import java.sql.Connection; import java.util.ArrayList; import java.util.Collections; @@ -33,51 +33,68 @@ /** * Counts connection pool borrows and hold time within a window opened by {@link #mark()}. Usage is keyed on * {@link DbScope#getEffectiveThread()}, so async threads sharing a request's connections are charged to that request. + * Off by default unless assertions are enabled; admins can toggle it from the profiler settings until restart. */ public class ConnectionUsage { private static final Map USAGE = Collections.synchronizedMap(new WeakHashMap<>()); - private static final ThreadMXBean THREADS = ManagementFactory.getThreadMXBean(); - private static final boolean CPU_TIME = THREADS.isCurrentThreadCpuTimeSupported() && THREADS.isThreadCpuTimeEnabled(); + private static final Mark DISABLED = new Mark(); + + private static volatile boolean _enabled = assertionsEnabled(); /** acquireNanos is the whole borrow: poolNanos in getConnection(), setupNanos for per-connection setup, and the remainder building the wrapper */ - public record Snapshot(long borrows, long acquireNanos, long poolNanos, long setupNanos, long acquireCpuNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned) + public record Snapshot(long borrows, long acquireNanos, long poolNanos, long setupNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned) + { + public static final Snapshot EMPTY = new Snapshot(0, 0, 0, 0, 0, 0, 0, 0); + } + + @SuppressWarnings({"AssertWithSideEffects", "ConstantValue"}) + private static boolean assertionsEnabled() + { + boolean enabled = false; + assert enabled = true; + return enabled; + } + + public static boolean isEnabled() { - public static final Snapshot EMPTY = new Snapshot(0, 0, 0, 0, 0, 0, 0, 0, 0); + return _enabled; } - /** Current thread's CPU time, or 0 when the JVM can't measure it */ - static long currentThreadCpuNanos() + public static void setEnabled(boolean enabled) { - return CPU_TIME ? THREADS.getCurrentThreadCpuTime() : 0; + _enabled = enabled; } /** Opaque token returned by {@link #mark()} */ public static final class Mark { - private final Usage _usage; + private final @Nullable Usage _usage; private final long _borrows; private final long _acquireNanos; private final long _poolNanos; private final long _setupNanos; - private final long _acquireCpuNanos; private final long _heldNanos; private final long _wallNanos; private final int _active; private int _maxActive; - private Mark(Usage usage, long now) + private Mark() + { + this(null, 0); + } + + private Mark(@Nullable Usage usage, long now) { _usage = usage; - _borrows = usage._borrows; - _acquireNanos = usage._acquireNanos; - _poolNanos = usage._poolNanos; - _setupNanos = usage._setupNanos; - _acquireCpuNanos = usage._acquireCpuNanos; - _heldNanos = usage.held(now); - _wallNanos = usage.wall(now); - _active = usage._active; - _maxActive = usage._active; + _borrows = null == usage ? 0 : usage._borrows; + _acquireNanos = null == usage ? 0 : usage._acquireNanos; + _poolNanos = null == usage ? 0 : usage._poolNanos; + _setupNanos = null == usage ? 0 : usage._setupNanos; + _heldNanos = null == usage ? 0 : usage.held(now); + _wallNanos = null == usage ? 0 : usage.wall(now); + _active = null == usage ? 0 : usage._active; + _maxActive = _active; } } @@ -88,7 +105,6 @@ static final class Usage private long _acquireNanos; private long _poolNanos; private long _setupNanos; - private long _acquireCpuNanos; private long _heldClosedNanos; private long _openStartSum; private long _wallClosedNanos; @@ -106,13 +122,12 @@ private long wall(long now) return _wallClosedNanos + (_active > 0 ? now - _wallStart : 0); } - private synchronized void borrow(long acquireNanos, long poolNanos, long setupNanos, long acquireCpuNanos, long now) + private synchronized void borrow(long acquireNanos, long poolNanos, long setupNanos, long now) { _borrows++; _acquireNanos += acquireNanos; _poolNanos += poolNanos; _setupNanos += setupNanos; - _acquireCpuNanos += acquireCpuNanos; if (_active++ == 0) _wallStart = now; _openStartSum += now; @@ -145,7 +160,6 @@ private synchronized Snapshot measure(Mark mark) _acquireNanos - mark._acquireNanos, _poolNanos - mark._poolNanos, _setupNanos - mark._setupNanos, - _acquireCpuNanos - mark._acquireCpuNanos, held(now) - mark._heldNanos, wall(now) - mark._wallNanos, mark._maxActive, @@ -154,24 +168,30 @@ private synchronized Snapshot measure(Mark mark) } } - /** Opens a measurement window for the current effective thread. Windows may nest. */ + /** + * Opens a measurement window for the current effective thread. Windows may nest. Every mark must be passed to + * {@link #measure(Mark)}, typically in a finally block, or it stays on the thread for the thread's lifetime. + */ public static @NotNull Mark mark() { + if (!_enabled) + return DISABLED; + return USAGE.computeIfAbsent(DbScope.getEffectiveThread(), _ -> new Usage()).mark(); } /** Closes the window; unreturned counts connections borrowed since the mark and still held. */ public static @NotNull Snapshot measure(@NotNull Mark mark) { - return mark._usage.measure(mark); + return null == mark._usage ? Snapshot.EMPTY : mark._usage.measure(mark); } /** @return the Usage to credit when this connection is returned, or null if the thread has never been marked */ - static @Nullable Usage recordBorrow(long acquireNanos, long poolNanos, long setupNanos, long acquireCpuNanos, long borrowedAt) + static @Nullable Usage recordBorrow(long acquireNanos, long poolNanos, long setupNanos, long borrowedAt) { Usage usage = USAGE.get(DbScope.getEffectiveThread()); if (null != usage) - usage.borrow(acquireNanos, poolNanos, setupNanos, acquireCpuNanos, borrowedAt); + usage.borrow(acquireNanos, poolNanos, setupNanos, borrowedAt); return usage; } @@ -183,6 +203,21 @@ static void recordReturn(@Nullable Usage usage, long borrowedAt) public static class TestCase extends Assert { + private boolean _wasEnabled; + + @Before + public void enable() + { + _wasEnabled = isEnabled(); + setEnabled(true); + } + + @After + public void restore() + { + setEnabled(_wasEnabled); + } + private static Snapshot measureOnNewThread(ThrowingRunnable block) throws Exception { AtomicReference result = new AtomicReference<>(); @@ -303,5 +338,18 @@ public void testNestedMarks() throws Exception assertEquals(2, inner.get().maxConcurrent()); assertTrue(outer.wallNanos() >= inner.get().wallNanos()); } + + @Test + public void testDisabled() throws Exception + { + setEnabled(false); + DbScope scope = DbScope.getLabKeyScope(); + Snapshot snapshot = measureOnNewThread(() -> { + try (Connection ignored = scope.getPooledConnection()) + { + } + }); + assertEquals(Snapshot.EMPTY, snapshot); + } } } diff --git a/api/src/org/labkey/api/data/ConnectionWrapper.java b/api/src/org/labkey/api/data/ConnectionWrapper.java index 4f62ed78da0..9fd4b520c84 100644 --- a/api/src/org/labkey/api/data/ConnectionWrapper.java +++ b/api/src/org/labkey/api/data/ConnectionWrapper.java @@ -231,12 +231,11 @@ public ConnectionWrapper(Connection conn, DbScope scope, Integer spid, Connectio } /** Called only for real pool borrows, so wrappers created without one never record a return */ - void trackUsage(long acquireStart, long poolDone, long setupDone, long acquireCpuStart) + void trackUsage(long acquireStart, long poolDone, long setupDone) { - long cpuNow = ConnectionUsage.currentThreadCpuNanos(); long now = System.nanoTime(); _borrowedAt = now; - _usage = ConnectionUsage.recordBorrow(now - acquireStart, poolDone - acquireStart, setupDone - poolDone, cpuNow - acquireCpuStart, now); + _usage = ConnectionUsage.recordBorrow(now - acquireStart, poolDone - acquireStart, setupDone - poolDone, now); } /** this is a best guess logger, pass one in to be predictable */ diff --git a/api/src/org/labkey/api/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 7a6c7746ffe..24a5d7bc18c 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -1472,8 +1472,8 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg } Connection conn; - long acquireCpuStart = ConnectionUsage.currentThreadCpuNanos(); - long acquireStart = System.nanoTime(); + boolean trackUsage = ConnectionUsage.isEnabled(); + long acquireStart = trackUsage ? System.nanoTime() : 0; try { @@ -1484,7 +1484,7 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg throw new ConfigurationException("Can't create a database connection for data source " + getDbScopeLoader().getDsName(), e); } - long poolDone = System.nanoTime(); + long poolDone = trackUsage ? System.nanoTime() : 0; try { @@ -1510,9 +1510,10 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg _initializedConnections.put(delegate, spid == null ? spidUnknown : spid); } - long setupDone = System.nanoTime(); + long setupDone = trackUsage ? System.nanoTime() : 0; ConnectionWrapper wrapper = new ConnectionWrapper(conn, this, spid, type, log); - wrapper.trackUsage(acquireStart, poolDone, setupDone, acquireCpuStart); + if (trackUsage) + wrapper.trackUsage(acquireStart, poolDone, setupDone); return wrapper; } catch (Throwable t) diff --git a/api/src/org/labkey/api/miniprofiler/MiniProfiler.java b/api/src/org/labkey/api/miniprofiler/MiniProfiler.java index 07b3316d895..f82d0a2fda4 100644 --- a/api/src/org/labkey/api/miniprofiler/MiniProfiler.java +++ b/api/src/org/labkey/api/miniprofiler/MiniProfiler.java @@ -21,6 +21,7 @@ import org.labkey.api.cache.Cache; import org.labkey.api.cache.CacheManager; import org.labkey.api.data.BeanObjectFactory; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.ContainerManager; import org.labkey.api.data.PropertyManager; import org.labkey.api.data.PropertyManager.WritablePropertyMap; @@ -127,8 +128,9 @@ public static boolean isEnabled(User user) { settings = SETTINGS_CACHE.get(user); - // Stacktrace setting isn't really cached, it just piggybacks on the MiniProfiler settings bean/form + // Stacktrace and connection usage settings aren't really cached, they just piggyback on the MiniProfiler settings bean/form settings.setCollectTroubleshootingStackTraces(_collectTroubleshootingStackTraces); + settings.setTrackConnectionUsage(ConnectionUsage.isEnabled()); } return settings; } @@ -136,8 +138,9 @@ public static boolean isEnabled(User user) /** Save per-user settings. */ public static void saveSettings(@NotNull Settings settings, @NotNull User user) { - // Troubleshooting stacktraces are site-wide only + // Troubleshooting stacktraces and connection usage are site-wide only setCollectTroubleshootingStackTraces(settings._collectTroubleshootingStackTraces); + ConnectionUsage.setEnabled(settings._trackConnectionUsage); WritablePropertyMap map = PropertyManager.getWritableProperties(user, ContainerManager.getRoot(), CATEGORY, true); SETTINGS_FACTORY.toStringMap(settings, map); @@ -328,6 +331,7 @@ public static class Settings private boolean _showControls = true; private RenderPosition _renderPosition = RenderPosition.BottomRight; private boolean _collectTroubleshootingStackTraces; + private boolean _trackConnectionUsage; private String _toggleShortcut = "alt+p"; public boolean isEnabled() @@ -420,6 +424,16 @@ public void setCollectTroubleshootingStackTraces(boolean collect) _collectTroubleshootingStackTraces = collect; } + public boolean isTrackConnectionUsage() + { + return _trackConnectionUsage; + } + + public void setTrackConnectionUsage(boolean track) + { + _trackConnectionUsage = track; + } + public String getToggleShortcut() { return _toggleShortcut; diff --git a/core/src/org/labkey/core/CoreModule.java b/core/src/org/labkey/core/CoreModule.java index 83fcf51d097..6c1c90dfb7d 100644 --- a/core/src/org/labkey/core/CoreModule.java +++ b/core/src/org/labkey/core/CoreModule.java @@ -48,6 +48,7 @@ import org.labkey.api.audit.provider.GroupAuditProvider; import org.labkey.api.audit.provider.ModulePropertiesAuditProvider; import org.labkey.api.cache.CacheManager; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.Container; import org.labkey.api.data.ContainerFilter; import org.labkey.api.data.ContainerManager; @@ -1051,7 +1052,8 @@ public void shutdownPre() } logTsv(new ActionsTsvWriter()); - logTsv(new ConnectionUsageTsvWriter()); + if (ConnectionUsage.isEnabled()) + logTsv(new ConnectionUsageTsvWriter()); LOG.info("Completed logging statistics for actions prior to web application shut down"); } diff --git a/core/src/org/labkey/core/admin/ActionsView.java b/core/src/org/labkey/core/admin/ActionsView.java index 6ba01174184..1d03222a158 100644 --- a/core/src/org/labkey/core/admin/ActionsView.java +++ b/core/src/org/labkey/core/admin/ActionsView.java @@ -19,6 +19,7 @@ import org.labkey.api.action.ActionType; import org.labkey.api.action.SpringActionController; import org.labkey.api.admin.ActionsHelper; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.ContainerManager; import org.labkey.api.util.Formats; import org.labkey.api.util.PageFlowUtil; @@ -41,10 +42,14 @@ class ActionsView extends HttpView @Override protected void renderInternal(Object model, PrintWriter out) throws Exception { + boolean connections = ConnectionUsage.isEnabled(); + int connectionColumns = connections ? 7 : 0; + if (!_summary) { out.println(PageFlowUtil.button("Export").href(new ActionURL(AdminController.ExportActionsAction.class, ContainerManager.getRoot()))); - out.println(PageFlowUtil.button("Export Connection Usage").href(new ActionURL(AdminController.ExportConnectionUsageAction.class, ContainerManager.getRoot()))); + if (connections) + out.println(PageFlowUtil.button("Export Connection Usage").href(new ActionURL(AdminController.ExportConnectionUsageAction.class, ContainerManager.getRoot()))); } Map>> modules = ActionsHelper.getActionStatistics(); @@ -67,13 +72,17 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception out.print("Cumulative Time"); out.print("Average Time"); out.print("Max Time"); - out.print("Borrows"); - out.print("Borrows/Invocation"); - out.print("Hold Time"); - out.print("Hold %"); - out.print("Max Concurrent"); - out.print("Acquire Time"); - out.print("Unreturned"); + if (connections) + { + out.print("Borrows"); + out.print("Borrows/Invocation"); + out.print("Hold Time"); + out.print("Hold %"); + out.print("Max Concurrent"); + out.print("Acquire Time"); + out.print("Unreturned"); + } + out.print(""); } int totalActions = 0; @@ -127,13 +136,16 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception renderTd(out, stats.getElapsedTime()); renderTd(out, 0 == stats.getCount() ? 0 : stats.getElapsedTime() / stats.getCount()); renderTd(out, stats.getMaxTime()); - renderTd(out, stats.getBorrows()); - renderTd(out, stats.getBorrowsPerInvocation(), Formats.f2); - renderTd(out, stats.getConnectionWallTime()); - renderTd(out, stats.getConnectionHoldFraction(), Formats.percent1); - renderTd(out, stats.getMaxConcurrent()); - renderTd(out, stats.getAcquireTime()); - renderTd(out, stats.getUnreturned()); + if (connections) + { + renderTd(out, stats.getBorrows()); + renderTd(out, stats.getBorrowsPerInvocation(), Formats.f2); + renderTd(out, stats.getConnectionWallTime()); + renderTd(out, stats.getConnectionHoldFraction(), Formats.percent1); + renderTd(out, stats.getMaxConcurrent()); + renderTd(out, stats.getAcquireTime()); + renderTd(out, stats.getUnreturned()); + } out.print(""); rowCount++; @@ -147,7 +159,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception if (!_summary) { out.print(""); - out.print(" Action Coverage"); + out.print(" Action Coverage"); } else { @@ -166,7 +178,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception if (!_summary) { out.print(""); - out.print(" "); + out.print(" "); rowCount++; } } @@ -186,7 +198,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception else { out.print(""); - out.print("Total Action Coverage"); + out.print("Total Action Coverage"); } out.print(""); diff --git a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java index 233bb77cdbc..34cb29324ac 100644 --- a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java +++ b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java @@ -36,7 +36,7 @@ protected void writeColumnHeaders() { writeLine(Arrays.asList("module", "controller", "action", "invocations", "cumulative", "borrows", "borrowsPerInvocation", "holdMs", "holdPercent", "connectionMs", "maxConcurrent", "acquireMs", "unreturned", - "acquirePoolMs", "acquireSetupMs", "acquireWrapperMs", "acquireCpuMs")); + "acquirePoolMs", "acquireSetupMs", "acquireWrapperMs")); } @Override @@ -80,8 +80,7 @@ protected int writeBody() String.valueOf(stats.getUnreturned()), String.valueOf(stats.getAcquirePoolTime()), String.valueOf(stats.getAcquireSetupTime()), - String.valueOf(Math.max(0, stats.getAcquireTime() - stats.getAcquirePoolTime() - stats.getAcquireSetupTime())), - String.valueOf(stats.getAcquireCpuTime()) + String.valueOf(Math.max(0, stats.getAcquireTime() - stats.getAcquirePoolTime() - stats.getAcquireSetupTime())) )); } diff --git a/core/src/org/labkey/core/admin/miniprofiler/manage.jsp b/core/src/org/labkey/core/admin/miniprofiler/manage.jsp index 00c6e42b762..df4addef896 100644 --- a/core/src/org/labkey/core/admin/miniprofiler/manage.jsp +++ b/core/src/org/labkey/core/admin/miniprofiler/manage.jsp @@ -16,6 +16,7 @@ */ %> <%@ page import="org.labkey.api.admin.AdminUrls" %> +<%@ page import="org.labkey.api.data.ConnectionUsage" %> <%@ page import="org.labkey.api.miniprofiler.MiniProfiler" %> <%@ page import="org.labkey.api.miniprofiler.MiniProfiler.RenderPosition" %> <%@ page import="org.labkey.api.miniprofiler.MiniProfiler.Settings" %> @@ -55,6 +56,14 @@ Some of them incur overhead to track or take space in the UI, and are thus confi + + + + + +   From 61aa1925522702fbf52496806bd4293e94fadd1e Mon Sep 17 00:00:00 2001 From: labkey-jeckels Date: Sat, 3 Oct 2026 16:35:52 -0700 Subject: [PATCH 9/9] Make per-action connection stats exact and reset them when tracking is turned off Each window now counts only connections borrowed within it, so a connection leaked earlier on the thread isn't charged to later requests, and per-invocation ratios use only tracked invocations. The pool stats API also reports whether tracking is on. --- .../api/action/SpringActionController.java | 71 +++++-- .../org/labkey/api/data/ConnectionUsage.java | 178 +++++++++++------- .../labkey/api/data/ConnectionWrapper.java | 10 +- .../labkey/api/module/SimpleController.java | 3 +- .../org/labkey/core/admin/ActionsView.java | 6 +- .../labkey/core/admin/AdminController.java | 9 +- .../core/admin/ConnectionUsageTsvWriter.java | 16 +- .../labkey/core/admin/miniprofiler/manage.jsp | 3 +- 8 files changed, 198 insertions(+), 98 deletions(-) diff --git a/api/src/org/labkey/api/action/SpringActionController.java b/api/src/org/labkey/api/action/SpringActionController.java index 4b569b57670..f4bca9a0ba1 100644 --- a/api/src/org/labkey/api/action/SpringActionController.java +++ b/api/src/org/labkey/api/action/SpringActionController.java @@ -193,7 +193,7 @@ protected static String h(@Nullable Object o) public interface ActionResolver { Controller resolveActionName(Controller actionController, String actionName); - void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage); + void addTime(Controller action, long elapsedTime, @Nullable ConnectionUsage.Snapshot connectionUsage); Collection getActionDescriptors(); } @@ -205,7 +205,7 @@ public interface ActionDescriptor Class getActionClass(); Controller createController(Controller actionController); - void addTime(long time, ConnectionUsage.Snapshot connectionUsage); + void addTime(long time, @Nullable ConnectionUsage.Snapshot connectionUsage); void addException(Exception x); ActionStats getStats(); } @@ -216,9 +216,12 @@ public interface ActionStats long getCount(); long getElapsedTime(); long getMaxTime(); + /** Invocations measured since connection tracking was last turned on; the connection stats cover only these */ + long getTrackedCount(); + long getTrackedElapsedTime(); long getBorrows(); /** Summed over connections, so exceeds wall time when a request holds several at once */ - long getConnectionHoldTime(); + long getConnectionHeldTime(); /** Time holding at least one connection */ long getConnectionWallTime(); int getMaxConcurrent(); @@ -233,13 +236,13 @@ public interface ActionStats default double getBorrowsPerInvocation() { - return 0 == getCount() ? 0 : getBorrows() / (double) getCount(); + return 0 == getTrackedCount() ? 0 : getBorrows() / (double) getTrackedCount(); } /** Clamped because elapsed time has millisecond resolution and connection time has nanosecond resolution */ - default double getConnectionHoldFraction() + default double getConnectionWallFraction() { - return 0 == getElapsedTime() ? 0 : Math.min(1.0, getConnectionWallTime() / (double) getElapsedTime()); + return 0 == getTrackedElapsedTime() ? 0 : Math.min(1.0, getConnectionWallTime() / (double) getTrackedElapsedTime()); } } @@ -825,10 +828,13 @@ public static abstract class BaseActionDescriptor implements ActionDescriptor private long _acquirePoolNanos = 0; private long _acquireSetupNanos = 0; private long _unreturned = 0; + private long _trackedCount = 0; + private long _trackedElapsedTime = 0; + private int _connectionGeneration = 0; private List _exceptions = null; @Override - synchronized public void addTime(long time, ConnectionUsage.Snapshot connectionUsage) + synchronized public void addTime(long time, @Nullable ConnectionUsage.Snapshot connectionUsage) { _count++; _elapsedTime += time; @@ -836,6 +842,12 @@ synchronized public void addTime(long time, ConnectionUsage.Snapshot connectionU if (time > _maxTime) _maxTime = time; + if (null == connectionUsage || !connectionUsage.isCurrent()) + return; + + syncConnectionGeneration(connectionUsage.generation()); + _trackedCount++; + _trackedElapsedTime += time; _borrows += connectionUsage.borrows(); _heldNanos += connectionUsage.heldNanos(); _wallNanos += connectionUsage.wallNanos(); @@ -846,6 +858,24 @@ synchronized public void addTime(long time, ConnectionUsage.Snapshot connectionU _unreturned += connectionUsage.unreturned(); } + private void syncConnectionGeneration(int generation) + { + if (generation == _connectionGeneration) + return; + + _connectionGeneration = generation; + _trackedCount = 0; + _trackedElapsedTime = 0; + _borrows = 0; + _heldNanos = 0; + _wallNanos = 0; + _maxConcurrent = 0; + _acquireNanos = 0; + _acquirePoolNanos = 0; + _acquireSetupNanos = 0; + _unreturned = 0; + } + @Override public void addException(Exception ex) { @@ -858,7 +888,8 @@ public void addException(Exception ex) @Override synchronized public ActionStats getStats() { - return new BaseActionStats(_count, _elapsedTime, _maxTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _acquirePoolNanos, _acquireSetupNanos, _unreturned, _exceptions); + syncConnectionGeneration(ConnectionUsage.getGeneration()); + return new BaseActionStats(_count, _elapsedTime, _maxTime, _trackedCount, _trackedElapsedTime, _borrows, _heldNanos, _wallNanos, _maxConcurrent, _acquireNanos, _acquirePoolNanos, _acquireSetupNanos, _unreturned, _exceptions); } // Immutable stats holder to eliminate external synchronization needs @@ -867,6 +898,8 @@ private class BaseActionStats implements ActionStats private final long _count; private final long _elapsedTime; private final long _maxTime; + private final long _trackedCount; + private final long _trackedElapsedTime; private final long _borrows; private final long _heldNanos; private final long _wallNanos; @@ -877,11 +910,13 @@ private class BaseActionStats implements ActionStats private final long _unreturned; private final List _exceptions; - private BaseActionStats(long count, long elapsedTime, long maxTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long acquirePoolNanos, long acquireSetupNanos, long unreturned, List ex) + private BaseActionStats(long count, long elapsedTime, long maxTime, long trackedCount, long trackedElapsedTime, long borrows, long heldNanos, long wallNanos, int maxConcurrent, long acquireNanos, long acquirePoolNanos, long acquireSetupNanos, long unreturned, List ex) { _count = count; _elapsedTime = elapsedTime; _maxTime = maxTime; + _trackedCount = trackedCount; + _trackedElapsedTime = trackedElapsedTime; _borrows = borrows; _heldNanos = heldNanos; _wallNanos = wallNanos; @@ -911,6 +946,18 @@ public long getMaxTime() return _maxTime; } + @Override + public long getTrackedCount() + { + return _trackedCount; + } + + @Override + public long getTrackedElapsedTime() + { + return _trackedElapsedTime; + } + @Override public long getBorrows() { @@ -918,7 +965,7 @@ public long getBorrows() } @Override - public long getConnectionHoldTime() + public long getConnectionHeldTime() { return TimeUnit.NANOSECONDS.toMillis(_heldNanos); } @@ -996,7 +1043,7 @@ public HTMLFileActionResolver(String controllerName) } @Override - public void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage) + public void addTime(Controller action, long elapsedTime, @Nullable ConnectionUsage.Snapshot connectionUsage) { /* Never called */ } @@ -1174,7 +1221,7 @@ public Controller resolveActionName(Controller actionController, String name) @Override - public void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage) + public void addTime(Controller action, long elapsedTime, @Nullable ConnectionUsage.Snapshot connectionUsage) { ActionDescriptor ad = getActionDescriptor(action.getClass()); if (null != ad) diff --git a/api/src/org/labkey/api/data/ConnectionUsage.java b/api/src/org/labkey/api/data/ConnectionUsage.java index a25adfe5d47..f05ab6aa8ad 100644 --- a/api/src/org/labkey/api/data/ConnectionUsage.java +++ b/api/src/org/labkey/api/data/ConnectionUsage.java @@ -34,6 +34,7 @@ * Counts connection pool borrows and hold time within a window opened by {@link #mark()}. Usage is keyed on * {@link DbScope#getEffectiveThread()}, so async threads sharing a request's connections are charged to that request. * Off by default unless assertions are enabled; admins can toggle it from the profiler settings until restart. + * Turning it off starts a new generation, which discards the per-action totals gathered so far. */ public class ConnectionUsage { @@ -41,11 +42,16 @@ public class ConnectionUsage private static final Mark DISABLED = new Mark(); private static volatile boolean _enabled = assertionsEnabled(); + private static volatile int _generation = 0; /** acquireNanos is the whole borrow: poolNanos in getConnection(), setupNanos for per-connection setup, and the remainder building the wrapper */ - public record Snapshot(long borrows, long acquireNanos, long poolNanos, long setupNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned) + public record Snapshot(long borrows, long acquireNanos, long poolNanos, long setupNanos, long heldNanos, long wallNanos, int maxConcurrent, long unreturned, int generation) { - public static final Snapshot EMPTY = new Snapshot(0, 0, 0, 0, 0, 0, 0, 0); + /** False once tracking has been turned off since the window opened */ + public boolean isCurrent() + { + return generation == _generation; + } } @SuppressWarnings({"AssertWithSideEffects", "ConstantValue"}) @@ -61,43 +67,74 @@ public static boolean isEnabled() return _enabled; } - public static void setEnabled(boolean enabled) + public static synchronized void setEnabled(boolean enabled) { + if (_enabled && !enabled) + _generation++; _enabled = enabled; } + public static int getGeneration() + { + return _generation; + } + /** Opaque token returned by {@link #mark()} */ public static final class Mark { private final @Nullable Usage _usage; + private final int _generation; + // Counters at the mark; a borrow belongs to this window when its sequence number exceeds _borrows private final long _borrows; private final long _acquireNanos; private final long _poolNanos; private final long _setupNanos; - private final long _heldNanos; - private final long _wallNanos; - private final int _active; + // Only connections borrowed within the window, so one leaked earlier on this thread isn't charged here + private int _active; private int _maxActive; + private long _openStartSum; + private long _heldClosedNanos; + private long _wallStart; + private long _wallClosedNanos; private Mark() { - this(null, 0); + _usage = null; + _generation = 0; + _borrows = _acquireNanos = _poolNanos = _setupNanos = 0; } - private Mark(@Nullable Usage usage, long now) + private Mark(@NotNull Usage usage) { _usage = usage; - _borrows = null == usage ? 0 : usage._borrows; - _acquireNanos = null == usage ? 0 : usage._acquireNanos; - _poolNanos = null == usage ? 0 : usage._poolNanos; - _setupNanos = null == usage ? 0 : usage._setupNanos; - _heldNanos = null == usage ? 0 : usage.held(now); - _wallNanos = null == usage ? 0 : usage.wall(now); - _active = null == usage ? 0 : usage._active; - _maxActive = _active; + _generation = ConnectionUsage._generation; + _borrows = usage._borrows; + _acquireNanos = usage._acquireNanos; + _poolNanos = usage._poolNanos; + _setupNanos = usage._setupNanos; + } + + private void borrow(long now) + { + if (_active++ == 0) + _wallStart = now; + _maxActive = Math.max(_maxActive, _active); + _openStartSum += now; + } + + private void release(long borrowedAt, long now) + { + _active--; + _heldClosedNanos += now - borrowedAt; + _openStartSum -= borrowedAt; + if (_active == 0) + _wallClosedNanos += now - _wallStart; } } + /** Identifies one borrow so its return is credited only to the windows that saw it */ + record Borrow(@NotNull Usage usage, long sequence, long borrowedAt) {} + // Sums of nanoTime() values may overflow; that's harmless because only differences are reported static final class Usage { @@ -105,48 +142,29 @@ static final class Usage private long _acquireNanos; private long _poolNanos; private long _setupNanos; - private long _heldClosedNanos; - private long _openStartSum; - private long _wallClosedNanos; - private long _wallStart; - private int _active; private final List _marks = new ArrayList<>(2); - private long held(long now) - { - return _heldClosedNanos + _active * now - _openStartSum; - } - - private long wall(long now) - { - return _wallClosedNanos + (_active > 0 ? now - _wallStart : 0); - } - - private synchronized void borrow(long acquireNanos, long poolNanos, long setupNanos, long now) + private synchronized Borrow borrow(long acquireNanos, long poolNanos, long setupNanos, long now) { _borrows++; _acquireNanos += acquireNanos; _poolNanos += poolNanos; _setupNanos += setupNanos; - if (_active++ == 0) - _wallStart = now; - _openStartSum += now; for (Mark mark : _marks) - mark._maxActive = Math.max(mark._maxActive, _active); + mark.borrow(now); + return new Borrow(this, _borrows, now); } - private synchronized void release(long borrowedAt, long now) + private synchronized void release(Borrow borrow, long now) { - _active--; - _heldClosedNanos += now - borrowedAt; - _openStartSum -= borrowedAt; - if (_active == 0) - _wallClosedNanos += now - _wallStart; + for (Mark mark : _marks) + if (borrow.sequence() > mark._borrows) + mark.release(borrow.borrowedAt(), now); } private synchronized Mark mark() { - Mark mark = new Mark(this, System.nanoTime()); + Mark mark = new Mark(this); _marks.add(mark); return mark; } @@ -160,17 +178,19 @@ private synchronized Snapshot measure(Mark mark) _acquireNanos - mark._acquireNanos, _poolNanos - mark._poolNanos, _setupNanos - mark._setupNanos, - held(now) - mark._heldNanos, - wall(now) - mark._wallNanos, + mark._heldClosedNanos + mark._active * now - mark._openStartSum, + mark._wallClosedNanos + (mark._active > 0 ? now - mark._wallStart : 0), mark._maxActive, - Math.max(0, _active - mark._active) + mark._active, + mark._generation ); } } /** - * Opens a measurement window for the current effective thread. Windows may nest. Every mark must be passed to - * {@link #measure(Mark)}, typically in a finally block, or it stays on the thread for the thread's lifetime. + * Opens a measurement window for the current effective thread. Windows may nest; each one counts only the + * connections borrowed within it. Every mark must be passed to {@link #measure(Mark)}, typically in a finally + * block, or it stays on the thread for the thread's lifetime. */ public static @NotNull Mark mark() { @@ -180,42 +200,44 @@ private synchronized Snapshot measure(Mark mark) return USAGE.computeIfAbsent(DbScope.getEffectiveThread(), _ -> new Usage()).mark(); } - /** Closes the window; unreturned counts connections borrowed since the mark and still held. */ - public static @NotNull Snapshot measure(@NotNull Mark mark) + /** + * Closes the window; unreturned counts connections borrowed within it and still held. + * @return null if tracking was off when the window opened + */ + public static @Nullable Snapshot measure(@NotNull Mark mark) { - return null == mark._usage ? Snapshot.EMPTY : mark._usage.measure(mark); + return null == mark._usage ? null : mark._usage.measure(mark); } - /** @return the Usage to credit when this connection is returned, or null if the thread has never been marked */ - static @Nullable Usage recordBorrow(long acquireNanos, long poolNanos, long setupNanos, long borrowedAt) + /** @return the Borrow to credit when this connection is returned, or null if the thread has never been marked */ + static @Nullable Borrow recordBorrow(long acquireNanos, long poolNanos, long setupNanos, long borrowedAt) { Usage usage = USAGE.get(DbScope.getEffectiveThread()); - if (null != usage) - usage.borrow(acquireNanos, poolNanos, setupNanos, borrowedAt); - return usage; + return null == usage ? null : usage.borrow(acquireNanos, poolNanos, setupNanos, borrowedAt); } - static void recordReturn(@Nullable Usage usage, long borrowedAt) + static void recordReturn(@Nullable Borrow borrow) { - if (null != usage) - usage.release(borrowedAt, System.nanoTime()); + if (null != borrow) + borrow.usage().release(borrow, System.nanoTime()); } public static class TestCase extends Assert { private boolean _wasEnabled; + // Bypasses setEnabled() so running these tests doesn't discard the server's per-action totals @Before public void enable() { _wasEnabled = isEnabled(); - setEnabled(true); + _enabled = true; } @After public void restore() { - setEnabled(_wasEnabled); + _enabled = _wasEnabled; } private static Snapshot measureOnNewThread(ThrowingRunnable block) throws Exception @@ -258,6 +280,7 @@ public void testConcurrentPooledBorrows() throws Exception Thread.sleep(5); } }); + assertTrue(snapshot.isCurrent()); assertEquals(3, snapshot.borrows()); assertEquals(3, snapshot.maxConcurrent()); assertTrue("Acquire phases can't exceed the whole", snapshot.poolNanos() + snapshot.setupNanos() <= snapshot.acquireNanos()); @@ -335,21 +358,48 @@ public void testNestedMarks() throws Exception assertEquals(2, outer.borrows()); assertEquals(2, outer.maxConcurrent()); assertEquals(1, inner.get().borrows()); - assertEquals(2, inner.get().maxConcurrent()); + assertEquals("Inner window shouldn't count the outer connection", 1, inner.get().maxConcurrent()); assertTrue(outer.wallNanos() >= inner.get().wallNanos()); } + @Test + public void testEarlierLeakNotCharged() throws Exception + { + DbScope scope = DbScope.getLabKeyScope(); + AtomicReference leaking = new AtomicReference<>(); + AtomicReference later = new AtomicReference<>(); + measureOnNewThread(() -> { + Mark first = mark(); + Connection leaked = scope.getPooledConnection(); + leaking.set(measure(first)); + + Mark second = mark(); + Thread.sleep(5); + try (Connection ignored = scope.getPooledConnection()) + { + leaked.close(); + later.set(measure(second)); + } + }); + Snapshot snapshot = later.get(); + assertEquals(1, leaking.get().unreturned()); + assertEquals(1, snapshot.borrows()); + assertEquals(1, snapshot.maxConcurrent()); + assertEquals("Returning the earlier leak shouldn't mask this window's", 1, snapshot.unreturned()); + assertTrue("Window shouldn't be charged for the earlier leak's hold time", snapshot.wallNanos() < 5_000_000); + } + @Test public void testDisabled() throws Exception { - setEnabled(false); + _enabled = false; DbScope scope = DbScope.getLabKeyScope(); Snapshot snapshot = measureOnNewThread(() -> { try (Connection ignored = scope.getPooledConnection()) { } }); - assertEquals(Snapshot.EMPTY, snapshot); + assertNull(snapshot); } } } diff --git a/api/src/org/labkey/api/data/ConnectionWrapper.java b/api/src/org/labkey/api/data/ConnectionWrapper.java index 9fd4b520c84..63f6b443f8b 100644 --- a/api/src/org/labkey/api/data/ConnectionWrapper.java +++ b/api/src/org/labkey/api/data/ConnectionWrapper.java @@ -161,9 +161,8 @@ private void realClose() private volatile boolean _allowClose = true; - // Captured at borrow because the return can happen on another thread, e.g. the Cleaner - private volatile @Nullable ConnectionUsage.Usage _usage; - private long _borrowedAt; + // Captured at borrow because the return can happen on another thread + private volatile @Nullable ConnectionUsage.Borrow _borrow; static { @@ -234,8 +233,7 @@ public ConnectionWrapper(Connection conn, DbScope scope, Integer spid, Connectio void trackUsage(long acquireStart, long poolDone, long setupDone) { long now = System.nanoTime(); - _borrowedAt = now; - _usage = ConnectionUsage.recordBorrow(now - acquireStart, poolDone - acquireStart, setupDone - poolDone, now); + _borrow = ConnectionUsage.recordBorrow(now - acquireStart, poolDone - acquireStart, setupDone - poolDone, now); } /** this is a best guess logger, pass one in to be predictable */ @@ -567,7 +565,7 @@ private void realClose() private void realCloseInternal() throws SQLException { _openConnections.remove(this); - ConnectionUsage.recordReturn(_usage, _borrowedAt); + ConnectionUsage.recordReturn(_borrow); _loggedLeaks.remove(this); // The Tomcat connection pool violates the API for close() - it throws an exception diff --git a/api/src/org/labkey/api/module/SimpleController.java b/api/src/org/labkey/api/module/SimpleController.java index 06bde7890ad..ea60fbde756 100644 --- a/api/src/org/labkey/api/module/SimpleController.java +++ b/api/src/org/labkey/api/module/SimpleController.java @@ -15,6 +15,7 @@ */ package org.labkey.api.module; +import org.jetbrains.annotations.Nullable; import org.labkey.api.action.SpringActionController; import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.Container; @@ -58,7 +59,7 @@ public Controller resolveActionName(Controller actionController, String actionNa } @Override - public void addTime(Controller action, long elapsedTime, ConnectionUsage.Snapshot connectionUsage) + public void addTime(Controller action, long elapsedTime, @Nullable ConnectionUsage.Snapshot connectionUsage) { } diff --git a/core/src/org/labkey/core/admin/ActionsView.java b/core/src/org/labkey/core/admin/ActionsView.java index 1d03222a158..5f35158d6b2 100644 --- a/core/src/org/labkey/core/admin/ActionsView.java +++ b/core/src/org/labkey/core/admin/ActionsView.java @@ -76,8 +76,8 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception { out.print("Borrows"); out.print("Borrows/Invocation"); - out.print("Hold Time"); - out.print("Hold %"); + out.print("Connection Wall Time"); + out.print("Connection Wall %"); out.print("Max Concurrent"); out.print("Acquire Time"); out.print("Unreturned"); @@ -141,7 +141,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception renderTd(out, stats.getBorrows()); renderTd(out, stats.getBorrowsPerInvocation(), Formats.f2); renderTd(out, stats.getConnectionWallTime()); - renderTd(out, stats.getConnectionHoldFraction(), Formats.percent1); + renderTd(out, stats.getConnectionWallFraction(), Formats.percent1); renderTd(out, stats.getMaxConcurrent()); renderTd(out, stats.getAcquireTime()); renderTd(out, stats.getUnreturned()); diff --git a/core/src/org/labkey/core/admin/AdminController.java b/core/src/org/labkey/core/admin/AdminController.java index 52a199081ed..4ed81e88ad0 100644 --- a/core/src/org/labkey/core/admin/AdminController.java +++ b/core/src/org/labkey/core/admin/AdminController.java @@ -108,6 +108,7 @@ import org.labkey.api.compliance.PhiColumnBehavior; import org.labkey.api.data.ButtonBar; import org.labkey.api.data.ColumnInfo; +import org.labkey.api.data.ConnectionUsage; import org.labkey.api.data.ConnectionWrapper; import org.labkey.api.data.Container; import org.labkey.api.data.Container.ContainerException; @@ -3064,9 +3065,11 @@ public static class GetConnectionPoolStatsAction extends ReadOnlyApiAction getPoolStats(DbScope scope) diff --git a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java index 34cb29324ac..cdf0b36e4f0 100644 --- a/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java +++ b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java @@ -26,7 +26,7 @@ import java.util.List; import java.util.Locale; -/** Invoked actions only, heaviest connection borrowers first */ +/** Actions invoked since connection tracking was last turned on, heaviest connection borrowers first */ public class ConnectionUsageTsvWriter extends TSVWriter { private record Row(String module, String controller, String action, ActionStats stats) {} @@ -35,7 +35,7 @@ private record Row(String module, String controller, String action, ActionStats protected void writeColumnHeaders() { writeLine(Arrays.asList("module", "controller", "action", "invocations", "cumulative", "borrows", "borrowsPerInvocation", - "holdMs", "holdPercent", "connectionMs", "maxConcurrent", "acquireMs", "unreturned", + "connectionWallMs", "connectionWallPercent", "connectionHeldMs", "maxConcurrent", "acquireMs", "unreturned", "acquirePoolMs", "acquireSetupMs", "acquireWrapperMs")); } @@ -50,9 +50,9 @@ protected int writeBody() .flatMap(module -> module.getValue().entrySet().stream() .flatMap(controller -> controller.getValue().entrySet().stream() .map(action -> new Row(module.getKey(), controller.getKey(), action.getKey(), action.getValue())))) - .filter(row -> row.stats().getCount() > 0) + .filter(row -> row.stats().getTrackedCount() > 0) .sorted(Comparator.comparingLong((Row row) -> row.stats().getBorrows()) - .thenComparingLong(row -> row.stats().getCount()) + .thenComparingLong(row -> row.stats().getTrackedCount()) .reversed()) .toList(); } @@ -68,13 +68,13 @@ protected int writeBody() row.module(), row.controller(), row.action(), - String.valueOf(stats.getCount()), - String.valueOf(stats.getElapsedTime()), + String.valueOf(stats.getTrackedCount()), + String.valueOf(stats.getTrackedElapsedTime()), String.valueOf(stats.getBorrows()), String.format(Locale.ROOT, "%.2f", stats.getBorrowsPerInvocation()), String.valueOf(stats.getConnectionWallTime()), - String.format(Locale.ROOT, "%.1f", stats.getConnectionHoldFraction() * 100), - String.valueOf(stats.getConnectionHoldTime()), + String.format(Locale.ROOT, "%.1f", stats.getConnectionWallFraction() * 100), + String.valueOf(stats.getConnectionHeldTime()), String.valueOf(stats.getMaxConcurrent()), String.valueOf(stats.getAcquireTime()), String.valueOf(stats.getUnreturned()), diff --git a/core/src/org/labkey/core/admin/miniprofiler/manage.jsp b/core/src/org/labkey/core/admin/miniprofiler/manage.jsp index df4addef896..985d1996ddf 100644 --- a/core/src/org/labkey/core/admin/miniprofiler/manage.jsp +++ b/core/src/org/labkey/core/admin/miniprofiler/manage.jsp @@ -59,7 +59,8 @@ Some of them incur overhead to track or take space in the UI, and are thus confi + "It adds a small cost to every connection borrow, so this setting resets to its default when the server is restarted. " + + "Turning it off discards the connection statistics collected so far.")%>