Viewing dump files for resource pools

You can view dump files that contain diagnostic information about the application's managed resource pool. You can use the files for troubleshooting purposes.

By default, dump files are automatically triggered when one of the following occurs:

Pool resources are exhausted
A potential leaked resource is detected
A previously potentially leaked resource is returned to the pool

Note: Pooled resource diagnostics settings are configured in the environment file in NexJ Studio and are enabled by default. Changes to the settings require a redeploy of the application to take effect.

Pool resources are exhausted

The following example shows the contents of a dump file that was generated when pool resources were exhausted for a database connection.

2016-12-10 11:05:12,680 WARN  [nexj.diagnostic.core.rpc.pool.PoolManager] Automatic pool dump: 
   
   RelationalDatabaseConnectionPool@159749931(fragment=RelationalDatabaseFragment ObjectQueueDatabase.[default], busyTimeout=10000, idleTimeout=60000, maxSize=33, activeCount=3, idleCount=0)
      Active:
         SQLConnection@620363089(lastUse=10013ms, refCount=1, xaResource=SQLConnection$XAResourceWrapper@883133689(xaResource=JtdsXAResource@1568426606))
            DiagnosticTraceFactory$DiagnosticTraceHolder@184200117(threadName=NexJ Worker #2, transaction=GenericTransaction@2096453709(status="Active", id=Tx(0700000000000000C805BE154AFB35F5538D633BD1D81B4D)))
               scriptStack:
                  at Object.read(attributes,where,orderBy,count,offset,xlock)$beginTransactionIfXLock
(class:Object.read(attributes,where,orderBy,count,offset,xlock)
$beginTransactionIfXLock:6)
                  at server.read-instance(syslibrary:server:975)
                  at SysObjectQueueDispatcher.getDispatcher(locked)$main
(class:SysObjectQueueDispatcher.getDispatcher(locked)$main:5)
               systemStack:
                  at nexj.core.rpc.pool.DiagnosticTraceFactory.createTrace(DiagnosticTraceFactory.java:73)
                  at nexj.core.util.pool.resource.GenericResourcePool.get(GenericResourcePool.java:226)
                 at nexj.core.rpc.sql.RelationalDatabaseConnectionPool
.getConnection(RelationalDatabaseConnectionPool.java:160)
                  at nexj.core.persistence.sql.SQLAdapter.open(SQLAdapter.java:945)
                  at nexj.core.persistence.sql.SQLAdapter.getConnection(SQLAdapter.java:892)
                  at nexj.core.persistence.sql.SQLCursor.query(SQLCursor.java:158)
                  at nexj.core.persistence.GenericCursor.run(GenericCursor.java:484)
                  at nexj.core.persistence.GenericCursor.init(GenericCursor.java:274)
                  at nexj.core.persistence.GenericCursor.<init>(GenericCursor.java:189)
                  at nexj.core.persistence.sql.SQLCursor.<init>(SQLCursor.java:78)
                  at nexj.core.persistence.sql.SQLAdapter.openCursor(SQLAdapter.java:1218)
                  at nexj.core.persistence.GenericPersistenceAdapter.read
(GenericPersistenceAdapter.java:82)
                  at nexj.core.persistence.Query.read(Query.java:6000)
                  at nexj.core.runtime.sys.SysObject.read(SysObject.java:53)
                  at sun.reflect.GeneratedMethodAccessor38.invoke(Unknown Source)
                  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                  at java.lang.reflect.Method.invoke(Method.java:597)
                  at nexj.core.scripting.JavaAction.invoke(JavaAction.java:67)
                  at nexj.core.scripting.Machine.run(Machine.java:2121)
                  at nexj.core.scripting.Machine.invoke(Machine.java:639)
                  at nexj.core.meta.Event.invoke(Event.java:1617)
                  at nexj.core.meta.Metaclass.invoke(Metaclass.java:4110)
                  at nexj.core.rpc.queueing.ObjectQueueDispatcher$DispatchStrategy.run(ObjectQueueDispatcher.java:2634)
                  at nexj.core.integration.ContextReceiver$1.run(ContextReceiver.java:123)
                  at nexj.core.runtime.InvocationContext.run(InvocationContext.java:3016)
                  at nexj.core.integration.ContextReceiver.run(ContextReceiver.java:84)
                  at nexj.core.rpc.queueing.ObjectQueueDispatcher.dispatch(ObjectQueueDispatcher.java:1137)
                  at nexj.core.rpc.queueing.ObjectQueueDispatcher.onMessage(ObjectQueueDispatcher.java:635)
                  at nexj.core.rpc.queueing.ObjectQueueDispatcher.onMessage(ObjectQueueDispatcher.java:578)
                  at nexj.core.rpc.queueing.ObjectReceiver.onMessage(ObjectReceiver.java:108)
                  at nexj.core.rpc.queueing.ObjectQueueServerMDB.onMessage(ObjectQueueServerMDB.java:77)
                  at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
                  at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:39)
                  at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)
                  at java.lang.reflect.Method.invoke(Method.java:597)
                  at nexj.core.container.platform.teee.ejb.GenericMDBContainer.invoke
(GenericMDBContainer.java:112)
                  at nexj.core.container.platform.teee.ejb.MDBMessageEndpointFactory$ProxyHandler.invoke(MDBMessageEndpointFactory.java:286)
                  at com.sun.proxy.$Proxy5.onMessage(Unknown Source)
                  at nexj.core.rpc.queueing.ra.ObjectConsumerPool.invokeLocalDispatcher
(ObjectConsumerPool.java:454)
                  at nexj.core.rpc.queueing.ra.ObjectConsumerPool$DispatcherState.processMessages(ObjectConsumerPool.java:1211)
                  at nexj.core.rpc.queueing.ra.ObjectConsumerPool$DispatcherState.listen(ObjectConsumerPool.java:1680)
                  at nexj.core.rpc.queueing.ra.ObjectConsumerPool.listen(ObjectConsumerPool.java:191)
                  at nexj.core.rpc.ra.GenericConsumerPool.run(GenericConsumerPool.java:287)
                  at nexj.core.rpc.queueing.ra.ObjectConsumerPool.run(ObjectConsumerPool.java:421)
                  at nexj.core.container.platform.teee.ra.RAWorkManager$CheckedWork.run(RAWorkManager.java:154)
                  at nexj.core.container.platform.teee.work.GenericWorkerPool$Worker.run(GenericWorkerPool.java:326)

The following example shows the stacktrace that accompanies the pool dump file.

Note: In the example, errors details are shown in the lines that contain the keywords (err.persistence.unavailable) and (err.pool.resource.busy).

2016-12-10 11:05:13,701 ERROR [nexj.core.rpc.cluster.ClusterManager] Error in heartbeat
nexj.core.persistence.AvailabilityException: Data source "DefaultRelationalDatabase" is temporarily unavailable. (err.persistence.unavailable)
                at nexj.core.persistence.sql.SQLAdapter.getConnection(SQLAdapter.java:896)
                at nexj.core.persistence.sql.SQLCursor.query(SQLCursor.java:158)
                at nexj.core.persistence.GenericCursor.run(GenericCursor.java:484)
                at nexj.core.persistence.GenericCursor.init(GenericCursor.java:274)
                at nexj.core.persistence.GenericCursor.<init>(GenericCursor.java:189)
                at nexj.core.persistence.sql.SQLCursor.<init>(SQLCursor.java:78)
                at nexj.core.persistence.sql.SQLAdapter.openCursor(SQLAdapter.java:1218)
                at nexj.core.persistence.GenericPersistenceAdapter.read
(GenericPersistenceAdapter.java:82)
                at nexj.core.persistence.Query.read(Query.java:6000)
                at nexj.core.rpc.cluster.ClusterManager.persist(ClusterManager.java:1277)
                at nexj.core.rpc.cluster.ClusterManager.heartbeat(ClusterManager.java:1391)
                at nexj.core.rpc.cluster.ClusterManager.timeout(ClusterManager.java:1456)
                at nexj.core.rpc.timer.PersistentTimer.process(PersistentTimer.java:479)
                at nexj.core.rpc.pool.GenericConsumerAdapter.process(GenericConsumerAdapter.java:157)
                at nexj.core.rpc.pool.DefaultConsumerAdapter.process(DefaultConsumerAdapter.java:22)
                at nexj.core.util.pool.consumer.GenericConsumer.process(GenericConsumer.java:303)
                at nexj.core.util.pool.consumer.GenericConsumer.consume(GenericConsumer.java:283)
                at nexj.core.rpc.timer.TimerConsumer.consume(TimerConsumer.java:66)
                at nexj.core.util.pool.consumer.GenericConsumer.run(GenericConsumer.java:200)
                at nexj.core.rpc.pool.ThreadPool$Worker$1$1.run(ThreadPool.java:244)
Caused by: nexj.core.util.pool.resource.PoolBusyException: Unable to allocate a resource in 10,000 ms due to reaching the maximum pool size of 33. (err.pool.resource.busy)
                at nexj.core.util.pool.resource.GenericResourcePool.get(GenericResourcePool.java:270)
                at nexj.core.rpc.sql.RelationalDatabaseConnectionPool.getConnection
(RelationalDatabaseConnectionPool.java:160)
                at nexj.core.persistence.sql.SQLAdapter.open(SQLAdapter.java:945)
                at nexj.core.persistence.sql.SQLAdapter.getConnection(SQLAdapter.java:892)
                ... 19 more

Potential leaked resource is detected

The following example shows the contents of a dump file that was generated when a potential leaked resource was detected for a database connection.

2016-12-10 11:20:29,625 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] Pool dump: The following resource(s) have been in use for more than 86400 s
   
   RelationalDatabaseConnectionPool@2112392140(fragment=RelationalDatabaseFragment DefaultRelationalDatabase.[default], busyTimeout=10000, idleTimeout=60000, maxSize=33, activeCount=1, idleCount=2)
      Active:
         SQLConnection@1250839995(lastUse=1000ms, refCount=1)
            DiagnosticTraceFactory$DiagnosticTraceHolder@256757984(threadName=NexJ TimerConsumer@1614732944(pool=TimerConsumerPool@210363069(config=Timer SystemTimer)) #342650404)
               systemStack:
                  at nexj.core.rpc.pool.DiagnosticTraceFactory.createTrace(DiagnosticTraceFactory.java:73)
                  at nexj.core.util.pool.resource.GenericResourcePool.get(GenericResourcePool.java:226)
                  at nexj.core.rpc.sql.RelationalDatabaseConnectionPool.getConnection
(RelationalDatabaseConnectionPool.java:160)
                  at nexj.core.persistence.sql.SQLAdapter.open(SQLAdapter.java:945)
                  at nexj.core.persistence.sql.SQLAdapter.getConnection(SQLAdapter.java:892)
                  at nexj.core.persistence.sql.SQLCursor.query(SQLCursor.java:158)
                  at nexj.core.persistence.GenericCursor.run(GenericCursor.java:484)
                  at nexj.core.persistence.GenericCursor.init(GenericCursor.java:274)
                  at nexj.core.persistence.GenericCursor.<init>(GenericCursor.java:189)
                  at nexj.core.persistence.sql.SQLCursor.<init>(SQLCursor.java:78)
                  at nexj.core.persistence.sql.SQLAdapter.openCursor(SQLAdapter.java:1218)
                  at nexj.core.persistence.GenericPersistenceAdapter.read
(GenericPersistenceAdapter.java:82)
                  at nexj.core.persistence.Query.read(Query.java:6000)
                  at nexj.core.rpc.cluster.ClusterManager.persist(ClusterManager.java:1277)
                  at nexj.core.rpc.cluster.ClusterManager.heartbeat(ClusterManager.java:1391)
                  at nexj.core.rpc.cluster.ClusterManager.timeout(ClusterManager.java:1456)
                  at nexj.core.rpc.timer.PersistentTimer.process(PersistentTimer.java:479)
                  at nexj.core.rpc.pool.GenericConsumerAdapter.process(GenericConsumerAdapter.java:157)
                  at nexj.core.rpc.pool.DefaultConsumerAdapter.process(DefaultConsumerAdapter.java:22)
                  at nexj.core.util.pool.consumer.GenericConsumer.process(GenericConsumer.java:303)
                  at nexj.core.util.pool.consumer.GenericConsumer.consume(GenericConsumer.java:283)
                  at nexj.core.rpc.timer.TimerConsumer.consume(TimerConsumer.java:66)
                  at nexj.core.util.pool.consumer.GenericConsumer.run(GenericConsumer.java:200)
                  at nexj.core.rpc.pool.ThreadPool$Worker$1$1.run(ThreadPool.java:244)

The following example shows the contents of a dump file that was generated when a potential leaked resource was detected for a timer.

2016-12-10 11:20:29,626 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] Pool dump: The following resource(s) have been in use for more than 86400 s
   
   TimerConsumerPool@210363069(config=Timer SystemTimer, idleTimeout=60000, maxSize=-1, activeCount=4, idleCount=4)
      Active:
         TimerConsumer@1689510533(lastUse=9905ms)
            DiagnosticTraceFactory$DiagnosticTraceHolder@982345134(threadName=NexJ TimerConsumerPool@210363069(config=Timer SystemTimer) #243642492)
               systemStack:
                  at nexj.core.rpc.pool.DiagnosticTraceFactory.createTrace(DiagnosticTraceFactory.java:73)
                  at nexj.core.util.pool.consumer.GenericConsumerPool.getConsumer
(GenericConsumerPool.java:612)
                  at nexj.core.rpc.timer.TimerConsumerPool.listen(TimerConsumerPool.java:213)
                  at nexj.core.util.pool.consumer.GenericConsumerPool.run(GenericConsumerPool.java:339)
                  at nexj.core.rpc.pool.ThreadPool$Worker$1$1.run(ThreadPool.java:244)
            
         TimerConsumer@1614732944(lastUse=1001ms)
            DiagnosticTraceFactory$DiagnosticTraceHolder@420389002(threadName=NexJ TimerConsumerPool@210363069(config=Timer SystemTimer) #243642492)
               systemStack:
                  at nexj.core.rpc.pool.DiagnosticTraceFactory.createTrace(DiagnosticTraceFactory.java:73)
                  at nexj.core.util.pool.consumer.GenericConsumerPool.getConsumer
(GenericConsumerPool.java:612)
                  at nexj.core.rpc.timer.TimerConsumerPool.listen(TimerConsumerPool.java:213)
                  at nexj.core.util.pool.consumer.GenericConsumerPool.run(GenericConsumerPool.java:339)
                  at nexj.core.rpc.pool.ThreadPool$Worker$1$1.run(ThreadPool.java:244)

The following example shows the contents of a dump file that was generated when a potential leaked resource was detected for a UDP connection.

2016-12-10 11:20:39,627 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] Pool dump: The following resource(s) have been in use for more than 86400 s
   
   UDPConsumerPool@1373030859(config=UDPChannel ClusterMulticastReceiver, idleTimeout=60000, maxSize=4, activeCount=1, idleCount=2)
      Active:
         UDPConsumer@795336456(lastUse=1753ms)
            DiagnosticTraceFactory$DiagnosticTraceHolder@94610066(threadName=NexJ UDPConsumerPool@1373030859(config=UDPChannel ClusterMulticastReceiver) #294728597)
               systemStack:
                  at nexj.core.rpc.pool.DiagnosticTraceFactory.createTrace(DiagnosticTraceFactory.java:73)
                  at nexj.core.util.pool.consumer.GenericConsumerPool.getConsumer
(GenericConsumerPool.java:612)
                  at nexj.core.rpc.udp.UDPConsumerPool.listen(UDPConsumerPool.java:153)
                  at nexj.core.util.pool.consumer.GenericConsumerPool.run(GenericConsumerPool.java:368)
                  at nexj.core.rpc.pool.ThreadPool$Worker$1$1.run(ThreadPool.java:244

Previously potentially leaked resource is returned to the pool

The following example shows the contents of a dump file that was generated when a previously potentially leaked resource for a database connection was returned to the pool.

2016-12-10 11:20:42,123 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] The following resource was previously reported as active but has been deactivated after 13 s:
   
   RelationalDatabaseConnectionPool@2112392140(fragment=RelationalDatabaseFragment DefaultRelationalDatabase.[default], busyTimeout=10000, idleTimeout=60000, maxSize=33, activeCount=2, idleCount=1)
      Idle:
         SQLConnection@1250839995(lastUse=13497ms, refCount=0)

The following example shows the contents of a dump file that was generated when a previously potentially leaked resource for a timer was returned to the pool.

2016-12-10 11:20:30,626 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] The following resource was previously reported as active but has been deactivated after 10 s:
   
   TimerConsumerPool@210363069(config=Timer SystemTimer, idleTimeout=60000, maxSize=-1, activeCount=3, idleCount=5)
      Idle:
         TimerConsumer@1689510533(lastUse=10906ms)

2016-12-10 11:20:42,149 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] The following resource was previously reported as active but has been deactivated after 13 s:
   
   TimerConsumerPool@210363069(config=Timer SystemTimer, idleTimeout=60000, maxSize=-1, activeCount=2, idleCount=6)
      Idle:
         TimerConsumer@1614732944(lastUse=13525ms)

The following example shows the contents of a dump file that was generated when a previously potentially leaked resource for a UDP connection was returned to the pool.

2016-12-10 11:20:40,863 INFO  [nexj.diagnostic.core.rpc.pool.PoolManager] The following resource was previously reported as active but has been deactivated after 0 s:
   
   UDPConsumerPool@1373030859(config=UDPChannel ClusterMulticastReceiver, idleTimeout=60000, maxSize=4, activeCount=2, idleCount=1)
      Idle:
         UDPConsumer@795336456(lastUse=7ms)