As part of my long running activity to find out what is causing 1 million MQCONNects a day from an Oracle webLogic web server, I have found out how to monitor what is going on inside the webLogic instance.
Most web servers support a Java Management eXtension (JMX) interface. You can use gui tools like jconsole to do an ad-hoc display of the management beans – but these are not practical for long term monitoring.
Ive listed the data from the JMX query, what the data means, and also documented how I got the data.
There are three components to an MDB
- A listening task waits to be notified about messages arriving on the queue. As far as I can tell there is one thread doing this work. If you need more I think you need to create a second MDB.
- Multiple MDB threads which get woken up by the listener task, get a message and invoke the MDB application OnMessage() method with the message. The data for this part has Type=EJBPoolRuntime.
- The application part which processes the message – typically it connects to MQ and puts a reply, and disconnects. This application specified which connection pool to be used using ConnectionFactory cf = (ConnectionFactory)ctx.lookup(“CF3”); The data for this part has Type=ConnectorConnectionPoolRuntime.
The multiple MDB threads.
This data came from the JMX record with com.bea:ServerRuntime=AdminServer2,MessageDrivenEJBRuntime=WMQ_IVT_MDB,Name=WMQ_IVT_MDB,ApplicationRuntime=MDB3,Type=EJBPoolRuntime,EJBComponentRuntime=MDB3
Where
- ServerRuntime=AdminServer2. This is where the application runs
- MessageDrivenEJBRuntime=WMQ_IVT_MDB comes from display-name WMQ_IVT_MDB in the ejb-jar.xml file.,Name=WMQ_IVT_MDB,
- ApplicationRuntime=MDB3, This is the name of the deployed .jar file.
- Type=EJBPoolRuntime, this is the type for the MDB threads
- EJBComponentRuntime=MDB3, this is the name of the deployed .jar file.
From experiementing with MDBs and adjusting parameters my picture of how the EJB thread pool works is as follows
- There is a general free pool for threads.
- There is a pool for the EJB.
- When a message arrives the listener thread gets a thread from the EJB pool, and executes the OnMessage() method on the thread.
- If there are not available threads,
- it waits for a free thread.
- if, over a period of seconds, most of the requests have had to wait for a thread, then start a new thread
- it gets a thread from the general pool, if none available it creates a new thread.
- it executes the MDB application ejbCreate() method on the thread just obtained.
- It executes the OnMessage() method on the thread.
- Puts the thread into the EJB pool as a free thread.
- In the ejbCreate() method, I had it write to the job log. I could see threads started, after
- Periodically the EJB pool is cleaned up, for threads which have been idle for a specific time interval
- execute ejbRemove() on the thread
- return the thread to the general free pool
- Periodically the general pool is cleaned up
- Threads which have not been used for a while are disconnected from the queue manager, and deleted.
The data came from the JMX with the defintion
com.bea:ServerRuntime=AdminServer2, Name=WMQ_IVT_MDB, ApplicationRuntime=MDB3, Type=MessageDrivenEJBRuntime, EJBComponentRuntime=MDB3
See here for the documentation.
- AccessTotalCount = 28180, There were this many messages processed, and so this many OnMessage() methods executed
- BeansInUseCount = 2. Deprecated
- BeansInUseCurrentCount = 1 One thread is currently active.
- DestroyedTotalCount = 0.
- IdleBeansCount = 4 There are 4 free thread available in the EJB pool
- MissTotalCount = 19. For 19 (out of the 28180) requests, they failed to get a free thread, and so a new thread was obtained.
- Name = WMQ_IVT_MDB
- PooledBeansCurrentCount = 3. The numer of free threads inthe pool.
- TimeoutTotalCount = 0. Number of requests timed out waiting for a thread from the free pool.
- Type = EJBPoolRuntime. You can use Type=EJBPoolRuntime in the JMX query string.
- WaiterCurrentCount = 0. The number of requests waiting for a thread in the pool. This value should always be zero.
- WaiterTotalCount = 0. The total number of threads that have had to wait in the pool. This value should always be zero, if it is non zero you need to tune your connection pool.
The data for the connection factory.
See here for some documentation.
- ActiveConnectionsCurrentCount (Inte
- ger) = 9. How many connections were in use when the JMX request was issued.
- ActiveConnectionsHighCount (Integer) = 10. The highest number of connections in use since the connection pool was started or reset
- AverageActiveUsage (Integer) = 0. This value is always zero.
- CapacityIncrement (Integer) = 1. This is the value the connection pool is configured with
- CloseCount (Long) = 5682. How many connection.close() requests have been issued. This will be less than or equal to ConnectionsMatchedTotalCount below.
- ConnectionFactoryClassName (String) = com.ibm.mq.connector.outbound.ConnectionFactoryImpl. This is the name of the connection class being used
- ConnectionFactoryName (Null). I could not find where to change this, or if it has any value
- ConnectionIdleProfileCount (Integer) = 0. This was always zero.
- ConnectionIdleProfiles (Null). This was always zero.
- ConnectionLeakProfileCount (Integer) = 0. This was always zero. I believe this is to do with connections not being returned to a pool, perhaps connection.close() was not issued.
- ConnectionLeakProfiles (Null). This was always zero. I believe this is to do with connections not being returned to a pool, perhaps connection.close() was not issued.
- ConnectionProfilingEnabled (Boolean) = false. I could not see how to change this, or what value it adds
- Connections (ObjectName[]) = [Ljavax.management.ObjectName;@299a06ac] This will be an internal object within Java.
- ConnectionsCreatedTotalCount (Integer) = 21. This is the count of instances started. You could get connection started, connection freed, connection started, connection freed. This would could 2 connections started.
- ConnectionsDestroyedByErrorTotalCount (Integer) = 0.
- ConnectionsDestroyedByShrinkingTotalCount (Integer) = 11. After a time period, idle-timeout-seconds in weblogic-ejb-jar.xml, connections that have not processed messages for this time period are released back to the general pool.
- ConnectionsDestroyedTotalCount (Integer) = 11. This seems to be the same as the previous item
- ConnectionsMatchedTotalCount (Integer) = 5670. This many requests for a connection with matching userid etc were got from the pool
- ConnectionsRejectedTotalCount (Integer) = 0. I dont know what this is
- ConnectorEisType (String) = Java Message Service
- CurrentCapacity (Long) = 10. This is the size of the pool
- EISResourceId (String) = type=<eis>, application=colin, module=colin, eis=Java
- Message Service, destinationId=CF2
- FreeConnectionsCurrentCount (Integer) = 1. There is currently one free connection in the pool
- FreeConnectionsHighCount (Integer) = 10. This is the highest number of free connections in the pool – when there was no requests for the connection pool.
- FreePoolSizeHighWaterMark (Long) = 10. I dont know the difference between this and the previous item.
- FreePoolSizeLowWaterMark (Long) = 0. This is the lowest number of free connections – it is the gap between in use and the maximum pool size.
- HealthState (Null). I do not think connection pools for MDBs support this
- HighestNumWaiters (Long) = 0. This value was always zero. Even when I reduced the size of the connection pool, and specified 50 threads could wait, this value was still 0
- InitialCapacity (Integer) = 1. This is the specified value. This is used to set a lower limit of connections in the pool. Setting the initial capacity to 5 means there will always be at least 5 connections in the pool, and the pool will not be shrunk below this value
- JNDIName (String) = CF2. This is what is specified in the connection pool definition. This label is used in the application ConnectionFactory cf = (ConnectionFactory)ctx.lookup(“CF2”);
- Key (String) = CF2. This seems to the be same as the JNDI name.
- LastShrinkTime (Long) = 1565334529469. This is the number of milliseconds POSIX time (since Jan 1st 1970). To format it use time_t now = t/1000; strftime(buff, 20, “%H:%M:%S”, localtime(&now));
- LogFileName (Null). You can specify logging for this adapter. Deployments -> resource adapter -> configuration -> Outbound Connection Pools, javax.jsm.ConnectionFactory, select the connection pool, Logging tab. When this was active I got nothing logged in it.
- LogFileStreamOpened (Boolean) = false
- LoggingEnabled (Boolean) = true
- LogRuntime (Null)
- ManagedConnectionFactoryClassName (String) = com.ibm.mq.connector.outbound.ManagedConnectionFactoryImpl. This is the name of the resouce adapter class.
- MaxCapacity (Integer) = 20. This is the maximum size of the pool.
- MaxIdleTime (Integer) = 0. This was always zero for me.
- MCFClassName (String) = com.ibm.mq.connector.outbound.ManagedConnectionFactoryImpl. This is the ManagedConnectionFactoryClassName. Same as above.
- Name (String) = CF2. Another connection pool identifier
- NumberDetectedIdle (Integer) = 0. This was always zero.
- NumberDetectedLeaks (Integer) = 0. This was always zero. I believe this is to do with connections not being returned to a pool, perhaps connection.close() was not issued.
- NumUnavailableCurrentCount (Integer) = 9. This feels like the number threads waiting while the connection pool creates a connection in the connection pool.
- NumUnavailableHighCount (Integer) = 10. This feels like the number threads waiting while the connection pool creates a connection in the connection pool.
- NumWaiters (Long) = 0. This was always zero – even through I restricited the number of connections in the pool. I got a java exception, unable to get a connection, rather than have the thread wait.
- NumWaitersCurrentCount (Integer) = 0. See above.
- Parent (ObjectName) = com.bea:ServerRuntime=AdminServer2,Name=colin, ApplicationRuntime=colin, Type=ConnectorComponentRuntime
- PoolName (String) = CF2. Yet another field with the name of the connection pool/
- PoolSizeHighWaterMark (Long) = 10. This is the highest number of connections used in the pool
- PoolSizeLowWaterMark (Long) = 0. This is the lowest number of connecitons used in pool
- ProxyOn (Boolean) = false. I could not find what this means
- RecycledTotal (Integer) = 0. This was always zero for me.
- ResourceAdapterLinkRefName (Null). You can specify this field name in your MDB definition.
- RuntimeTransactionSupport (String) = NoTransaction. This defines if your connections are part of a unit of work or not. NoTransaction means out of syncpoint. You may want to specify. XATransaction.
- ShrinkCountDownTime (Integer) = 340. This is how long before a scan of the pool to remove any threads in the pool which have done no work for the specified interval.
- ShrinkingEnabled (Boolean) = true
- ShrinkPeriodMinutes (Integer) = 15. You can specify the interval on the resource adapter definition (Note: you specify it in seconds – it gets reported in minutes)
- State (String) = Running. This connection pool is started.
- Testable (Boolean) = false. You can defined some resources as “testable”
- TransactionSupport (String) = NoTransaction. This is the same as RuntimeTransactionSupport above.
- Type (String) = ConnectorConnectionPoolRuntime. This defines the object. You can use the Type=ConnectorConnectionPoolRuntime in the JMX query.
From this I can see there is a pool called CF2 which has maximum of 10 connections. The maximum connections used was 10, the lowest was 0.
There were Connections Matched Total Count = 5670 requests for a connection from the pool.
The pool has shrunk more than once as it has Connections Destroyed By Shrinking Total Count = 11 connections.
Using this data, you can now plot usage over time and see if you need to increase ( or decrease) the size of the pool, or the parameters to tune when the pool is shrunk.
I do not know enough about JMX to tell if the “high” and “low” value are reset on each query, or if you can use JMX to reset them periodically. These high and low value may have little value, if they are since the webLogic instance started (6 months ago).
The data fields are mentioned here.
How I got the data
There is a python package called JMXQuery which has a .jar file which allows you to query information in a JMX server. The output is in json format so you can use your favourite tools (python) to quickly convert this to other format, such as .csv .
The command I used was
java -jar “/usr/local/lib/python3.6/dist-packages/jmxquery/JMXQuery-0.1.8.jar” -url service:jmx:rmi:///jndi/rmi://127.0.0.1:8091/jmxrmi -json -u webLogic
-p passw0rd -q “com.bea:ServerRuntime=AdminServer2,Name=CF2,ApplicationRuntime=colin, Type=ConnectorConnectionPoolRuntime,ConnectorComponentRuntime=colin”
which breaks down as follows
- java – invoke java
- -jar “/usr/local/lib/python3.6/dist-packages/jmxquery/JMXQuery-0.1.8.jar” – this jar file
- -url service:jmx:rmi:///jndi/rmi://127.0.0.1:8091/jmxrmi – this is the url of my webLogic server
- -json – output it in json format
- -u webLogic -p passw0rd -q – userid and password
- “com.bea:ServerRuntime=AdminServer2,Name=CF2,ApplicationRuntime=colin, Type=ConnectorConnectionPoolRuntime,ConnectorComponentRuntime=colin”
- com.bea is the bean type
- The admin server was called AdminServer2
- The connection factory was CF2
- The resource adapter is installed under “Deployments” as colin
- Type=ConnectorConnectionPoolRuntime is the type of bean
I then used |jq . |grep -v mBean > bb to convert the one line json to one field per line, dropped the mBean value, and put it to a file. The output was like
[
{
"attribute": "Connections",
"attributeType": "ObjectName[]",
"value": "[Ljavax.management.ObjectName;@299a06ac"
},
{
"attribute": "FreeConnectionsCurrentCount",
"attributeType": "Integer",
"value": 4
},
etc
You can put generics in for example
java -jar “/usr/local/lib/python3.6/dist-packages/jmxquery/JMXQuery-0.1.8.jar” -url service:jmx:rmi:///jndi/rmi://127.0.0.1:8091/jmxrmi -json -u readonly -p read0nly -q “com.bea:ApplicationRuntime=*,ConnectorComponentRuntime=*,Name=”CP*”,ServerRuntime=*,Type=ConnectorConnectionPoolRuntime” e=*,Type=ConnectorConnectionPoolRuntime” > aa
Where this uses a userid set up as a monitor id, “*” has been specified for many values, and only give objects beginning with “CP”. Note blanks have meaning. “,,,=*, Name=…” looks for an object with blank,N,a,m,e,
Data when not using a resource adapter
The above information was for a resource adapter. When an EJB 2 MDB is deployed (non resource adapter)
from –q “com.bea:ApplicationRuntime=MDB3,EJBComponentRuntime=MDB3,
MessageDrivenEJBRuntime=WMQ_IVT_MDB_JMSQ1,
Name=WMQ_IVT_MDB_JMSQ1,ServerRuntime=AdminServer2,Type=EJBPoolRuntime”
Where the weblogic-jar-xml has
<weblogic-ejb-jar> <ejb-name>WMQ_IVT_MDB</ejb-name>
<destination-jndi-name>JMSQ1</destination-jndi-name>
The data was
BeansInUseCount (Integer) = 0
PooledBeansCurrentCount (Integer) = 10
IdleBeansCount (Integer) = 10
BeansInUseCurrentCount (Integer) = 0
DestroyedTotalCount (Long) = 0
WaiterCurrentCount (Integer) = 0
Name (String) = WMQ_IVT_MDB_JMSQ1
MissTotalCount (Long) = 7
AccessTotalCount (Long) = 28
Type (String) = EJBPoolRuntime
TimeoutTotalCount (Long) = 0
WaiterTotalCount (Long) = 0
With
-q “com.bea:ApplicationRuntime=MDB3,EJBComponentRuntime=MDB3, MessageDrivenEJBRuntime=WMQ_IVT_MDB_JMSQ1,Name=WMQ_IVT_MDB_JMSQ1,
ServerRuntime=AdminServer2,Type=EJBTransactionRuntime“
the output was
TransactionsRolledBackTotalCount (Long) = 0
TransactionsTimedOutTotalCount (Long) = 0
Name (String) = WMQ_IVT_MDB_JMSQ1
Type (String) = EJBTransactionRuntime
TransactionsCommittedTotalCount (Long) = 0