diff --git a/api/src/org/labkey/api/ApiModule.java b/api/src/org/labkey/api/ApiModule.java index d484ce6e7ee..f34ed6050c0 100644 --- a/api/src/org/labkey/api/ApiModule.java +++ b/api/src/org/labkey/api/ApiModule.java @@ -54,6 +54,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; @@ -540,6 +541,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..f4bca9a0ba1 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, @Nullable 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, @Nullable ConnectionUsage.Snapshot connectionUsage); void addException(Exception x); ActionStats getStats(); } @@ -214,8 +216,34 @@ 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 getConnectionHeldTime(); + /** Time holding at least one connection */ + 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(); + long getUnreturned(); boolean hasExceptions(); List getExceptions(); + + default double getBorrowsPerInvocation() + { + return 0 == getTrackedCount() ? 0 : getBorrows() / (double) getTrackedCount(); + } + + /** Clamped because elapsed time has millisecond resolution and connection time has nanosecond resolution */ + default double getConnectionWallFraction() + { + return 0 == getTrackedElapsedTime() ? 0 : Math.min(1.0, getConnectionWallTime() / (double) getTrackedElapsedTime()); + } } ApplicationContext _applicationContext = null; @@ -421,6 +449,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; @@ -556,11 +585,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); + if (null != controller) + _actionResolver.addTime(controller, System.currentTimeMillis() - startTime, connectionUsage); + } } return null; @@ -783,16 +820,60 @@ 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 _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) + synchronized public void addTime(long time, @Nullable ConnectionUsage.Snapshot connectionUsage) { _count++; _elapsedTime += time; 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(); + _maxConcurrent = Math.max(_maxConcurrent, connectionUsage.maxConcurrent()); + _acquireNanos += connectionUsage.acquireNanos(); + _acquirePoolNanos += connectionUsage.poolNanos(); + _acquireSetupNanos += connectionUsage.setupNanos(); + _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 @@ -807,7 +888,8 @@ public void addException(Exception ex) @Override synchronized public ActionStats getStats() { - return new BaseActionStats(_count, _elapsedTime, _maxTime, _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 @@ -816,13 +898,33 @@ 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; + private final int _maxConcurrent; + private final long _acquireNanos; + private final long _acquirePoolNanos; + private final long _acquireSetupNanos; + 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 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; + _maxConcurrent = maxConcurrent; + _acquireNanos = acquireNanos; + _acquirePoolNanos = acquirePoolNanos; + _acquireSetupNanos = acquireSetupNanos; + _unreturned = unreturned; _exceptions = ex; } @@ -844,6 +946,66 @@ public long getMaxTime() return _maxTime; } + @Override + public long getTrackedCount() + { + return _trackedCount; + } + + @Override + public long getTrackedElapsedTime() + { + return _trackedElapsedTime; + } + + @Override + public long getBorrows() + { + return _borrows; + } + + @Override + public long getConnectionHeldTime() + { + 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 getAcquirePoolTime() + { + return TimeUnit.NANOSECONDS.toMillis(_acquirePoolNanos); + } + + @Override + public long getAcquireSetupTime() + { + return TimeUnit.NANOSECONDS.toMillis(_acquireSetupNanos); + } + + @Override + public long getUnreturned() + { + return _unreturned; + } + @Override @Nullable public Class getActionType() @@ -881,7 +1043,7 @@ public HTMLFileActionResolver(String controllerName) } @Override - public void addTime(Controller action, long elapsedTime) + public void addTime(Controller action, long elapsedTime, @Nullable ConnectionUsage.Snapshot connectionUsage) { /* Never called */ } @@ -1059,11 +1221,11 @@ public Controller resolveActionName(Controller actionController, String name) @Override - public void addTime(Controller action, long elapsedTime) + public void addTime(Controller action, long elapsedTime, @Nullable 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..f05ab6aa8ad --- /dev/null +++ b/api/src/org/labkey/api/data/ConnectionUsage.java @@ -0,0 +1,405 @@ +/* + * 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.After; +import org.junit.Assert; +import org.junit.Before; +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. + * 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 +{ + private static final Map USAGE = Collections.synchronizedMap(new WeakHashMap<>()); + 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, int generation) + { + /** False once tracking has been turned off since the window opened */ + public boolean isCurrent() + { + return generation == _generation; + } + } + + @SuppressWarnings({"AssertWithSideEffects", "ConstantValue"}) + private static boolean assertionsEnabled() + { + boolean enabled = false; + assert enabled = true; + return enabled; + } + + public static boolean isEnabled() + { + return _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; + // 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() + { + _usage = null; + _generation = 0; + _borrows = _acquireNanos = _poolNanos = _setupNanos = 0; + } + + private Mark(@NotNull Usage usage) + { + _usage = usage; + _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 + { + private long _borrows; + private long _acquireNanos; + private long _poolNanos; + private long _setupNanos; + private final List _marks = new ArrayList<>(2); + + private synchronized Borrow borrow(long acquireNanos, long poolNanos, long setupNanos, long now) + { + _borrows++; + _acquireNanos += acquireNanos; + _poolNanos += poolNanos; + _setupNanos += setupNanos; + for (Mark mark : _marks) + mark.borrow(now); + return new Borrow(this, _borrows, now); + } + + private synchronized void release(Borrow borrow, long now) + { + for (Mark mark : _marks) + if (borrow.sequence() > mark._borrows) + mark.release(borrow.borrowedAt(), now); + } + + private synchronized Mark mark() + { + Mark mark = new Mark(this); + _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, + _poolNanos - mark._poolNanos, + _setupNanos - mark._setupNanos, + mark._heldClosedNanos + mark._active * now - mark._openStartSum, + mark._wallClosedNanos + (mark._active > 0 ? now - mark._wallStart : 0), + mark._maxActive, + mark._active, + mark._generation + ); + } + } + + /** + * 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() + { + if (!_enabled) + return DISABLED; + + return USAGE.computeIfAbsent(DbScope.getEffectiveThread(), _ -> new Usage()).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 ? null : mark._usage.measure(mark); + } + + /** @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()); + return null == usage ? null : usage.borrow(acquireNanos, poolNanos, setupNanos, borrowedAt); + } + + static void recordReturn(@Nullable Borrow borrow) + { + 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(); + _enabled = true; + } + + @After + public void restore() + { + _enabled = _wasEnabled; + } + + 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); + } + }); + 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()); + 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("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 + { + _enabled = false; + DbScope scope = DbScope.getLabKeyScope(); + Snapshot snapshot = measureOnNewThread(() -> { + try (Connection ignored = scope.getPooledConnection()) + { + } + }); + assertNull(snapshot); + } + } +} diff --git a/api/src/org/labkey/api/data/ConnectionWrapper.java b/api/src/org/labkey/api/data/ConnectionWrapper.java index 6e67fdb90ca..63f6b443f8b 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 { @@ -159,6 +161,9 @@ private void realClose() private volatile boolean _allowClose = true; + // Captured at borrow because the return can happen on another thread + private volatile @Nullable ConnectionUsage.Borrow _borrow; + static { // Issue 51483: DB query can be left running after shutting down server @@ -224,21 +229,26 @@ 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 poolDone, long setupDone) + { + long now = System.nanoTime(); + _borrow = ConnectionUsage.recordBorrow(now - acquireStart, poolDone - acquireStart, setupDone - poolDone, now); + } + /** this is a best guess logger, pass one in to be predictable */ 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() @@ -555,6 +565,7 @@ private void realClose() private void realCloseInternal() throws SQLException { _openConnections.remove(this); + 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/data/DbScope.java b/api/src/org/labkey/api/data/DbScope.java index 10539fbb4a5..24a5d7bc18c 100644 --- a/api/src/org/labkey/api/data/DbScope.java +++ b/api/src/org/labkey/api/data/DbScope.java @@ -1472,6 +1472,8 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg } Connection conn; + boolean trackUsage = ConnectionUsage.isEnabled(); + long acquireStart = trackUsage ? System.nanoTime() : 0; try { @@ -1482,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 = trackUsage ? System.nanoTime() : 0; + try { if (!conn.getAutoCommit()) @@ -1506,7 +1510,11 @@ public ConnectionWrapper getPooledConnection(ConnectionType type, @Nullable Logg _initializedConnections.put(delegate, spid == null ? spidUnknown : spid); } - return new ConnectionWrapper(conn, this, spid, type, log); + long setupDone = trackUsage ? System.nanoTime() : 0; + ConnectionWrapper wrapper = new ConnectionWrapper(conn, this, spid, type, log); + if (trackUsage) + wrapper.trackUsage(acquireStart, poolDone, setupDone); + return wrapper; } catch (Throwable t) { 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) diff --git a/api/src/org/labkey/api/data/dialect/SqlDialect.java b/api/src/org/labkey/api/data/dialect/SqlDialect.java index 51e9863d93a..c3869828cda 100644 --- a/api/src/org/labkey/api/data/dialect/SqlDialect.java +++ b/api/src/org/labkey/api/data/dialect/SqlDialect.java @@ -1726,6 +1726,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/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/api/src/org/labkey/api/module/SimpleController.java b/api/src/org/labkey/api/module/SimpleController.java index 03c06d3cbdd..ea60fbde756 100644 --- a/api/src/org/labkey/api/module/SimpleController.java +++ b/api/src/org/labkey/api/module/SimpleController.java @@ -15,7 +15,9 @@ */ 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; import org.labkey.api.util.Path; import org.labkey.api.view.ActionURL; @@ -57,7 +59,7 @@ public Controller resolveActionName(Controller actionController, String actionNa } @Override - public void addTime(Controller action, long elapsedTime) + public void addTime(Controller action, long elapsedTime, @Nullable ConnectionUsage.Snapshot connectionUsage) { } 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/CoreModule.java b/core/src/org/labkey/core/CoreModule.java index a96ce5ad774..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; @@ -215,6 +216,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 +1051,26 @@ public void shutdownPre() { } - Logger logger = LogManager.getLogger(ActionsTsvWriter.class); - - if (null != logger) - { - StringBuilder buf = new StringBuilder(); + logTsv(new ActionsTsvWriter()); + if (ConnectionUsage.isEnabled()) + 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..5f35158d6b2 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; @@ -26,6 +27,7 @@ import org.labkey.api.view.HttpView; import java.io.PrintWriter; +import java.text.NumberFormat; import java.util.Map; class ActionsView extends HttpView @@ -40,8 +42,15 @@ 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()))); + if (connections) + out.println(PageFlowUtil.button("Export Connection Usage").href(new ActionURL(AdminController.ExportConnectionUsageAction.class, ContainerManager.getRoot()))); + } Map>> modules = ActionsHelper.getActionStatistics(); @@ -62,7 +71,18 @@ 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"); + if (connections) + { + out.print("Borrows"); + out.print("Borrows/Invocation"); + out.print("Connection Wall Time"); + out.print("Connection Wall %"); + out.print("Max Concurrent"); + out.print("Acquire Time"); + out.print("Unreturned"); + } + out.print(""); } int totalActions = 0; @@ -116,6 +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()); + if (connections) + { + renderTd(out, stats.getBorrows()); + renderTd(out, stats.getBorrowsPerInvocation(), Formats.f2); + renderTd(out, stats.getConnectionWallTime()); + renderTd(out, stats.getConnectionWallFraction(), Formats.percent1); + renderTd(out, stats.getMaxConcurrent()); + renderTd(out, stats.getAcquireTime()); + renderTd(out, stats.getUnreturned()); + } out.print(""); rowCount++; @@ -129,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 { @@ -148,7 +178,7 @@ protected void renderInternal(Object model, PrintWriter out) throws Exception if (!_summary) { out.print(""); - out.print(" "); + out.print(" "); rowCount++; } } @@ -168,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(""); @@ -179,9 +209,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 6a59699f699..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; @@ -138,6 +139,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; @@ -3043,6 +3045,59 @@ 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); + } + } + } + + @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( + "connectionUsageTracked", ConnectionUsage.isEnabled(), + "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()); @@ -12716,6 +12771,8 @@ controller.new ShowPrimaryLogAction(), controller.new ShowCspReportLogAction(), controller.new ShowThreadsAction(), new ExportActionsAction(), + new ExportConnectionUsageAction(), + new GetConnectionPoolStatsAction(), 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..cdf0b36e4f0 --- /dev/null +++ b/core/src/org/labkey/core/admin/ConnectionUsageTsvWriter.java @@ -0,0 +1,89 @@ +/* + * 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; + +/** 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) {} + + @Override + protected void writeColumnHeaders() + { + writeLine(Arrays.asList("module", "controller", "action", "invocations", "cumulative", "borrows", "borrowsPerInvocation", + "connectionWallMs", "connectionWallPercent", "connectionHeldMs", "maxConcurrent", "acquireMs", "unreturned", + "acquirePoolMs", "acquireSetupMs", "acquireWrapperMs")); + } + + @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().getTrackedCount() > 0) + .sorted(Comparator.comparingLong((Row row) -> row.stats().getBorrows()) + .thenComparingLong(row -> row.stats().getTrackedCount()) + .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.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.getConnectionWallFraction() * 100), + String.valueOf(stats.getConnectionHeldTime()), + String.valueOf(stats.getMaxConcurrent()), + String.valueOf(stats.getAcquireTime()), + String.valueOf(stats.getUnreturned()), + String.valueOf(stats.getAcquirePoolTime()), + String.valueOf(stats.getAcquireSetupTime()), + String.valueOf(Math.max(0, stats.getAcquireTime() - stats.getAcquirePoolTime() - stats.getAcquireSetupTime())) + )); + } + + return rows.size(); + } +} diff --git a/core/src/org/labkey/core/admin/miniprofiler/manage.jsp b/core/src/org/labkey/core/admin/miniprofiler/manage.jsp index 00c6e42b762..985d1996ddf 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,15 @@ Some of them incur overhead to track or take space in the UI, and are thus confi + + + + + +