If you’ve done any work with the Spring frameworks for Java programs, then you will know that one of the good things about Spring is that it hides a lot of the underlying operations from you. But equally, one of the bad things about Spring is that it hides a lot of the underlying operations from you. I noticed that I was getting several questions about what was happening under the covers from people using the MQ Spring Boot starter. This post shows how you can see what Spring is doing to a queue manager.
The MQ Spring Boot starter has two primary concerns. I wrote a general introduction to the MQ starter in this post. But briefly, it first gives a single artifact that can be used in your programs without needing to know any further about dependencies.
It also enables simple configuration of the ConnectionFactory objects used by a JMS program, with sensible default values and non-default values or overrides provided by external configuration files. Just about everything else in the JMS API can be handled by the Spring core classes and methods. But in this starter, we need to get involved in the connection process which is so specific to the MQ provider – what are the configuration parameters, what are some of the default session options and so on.
Connection Types
It’s understanding a bit more about that connection management that I thought I’d write today. Spring has a number of APIs and mechanisms to configure how connections are made. In the simplest case, you use the JMSTemplate class. But that can be very inefficient if you use it frequently without additional options. The JavaDoc for that class even says:
“NOTE: The
ConnectionFactoryused with this template should return pooled Connections (or a single shared Connection) as well as pooled Sessions and MessageProducers. Otherwise, performance of ad-hoc JMS operations is going to suffer.“
But outside of a JEE environment, the MQ JMS classes do not directly provide cached connections. The MQ documentation suggests that you make use of framework provided mechanisms:
With Java™ SE (or with another framework such as Spring) the programming models are extremely flexible. Therefore a single pooling strategy does not suit all. You should consider if there is a framework in place that could do any form of pooling, for example, Spring.
Which is fine, because there are frameworks that can be utilised with the MQ Boot starter. In fact, there are two commonly-used approaches. Historically, people used an external connection pooling library. At one time, that was the only real option. But Spring has since added its own caching layer, with a CachingConnectionFactory class. There are different views on which is to be preferred, and “which is best” may depend on the underlying JMS provider and how the connections are going to be used. In the MQ Boot starter, we don’t take a prescriptive approach and allow either to be configured.
Though that leads to the question when testing and debugging applications of which type of connection was actually used. Did I correctly configure the JMS pool property? Am I getting too many real MQ connections being made?
The most recent version (2.4.4) of the MQ Spring Boot package tries to help, by providing some trace information using Spring’s logging mechanisms.
Using Spring logging
Spring provides integration with various Java logging frameworks. For the most part we don’t really need to care in this post about how all of that works or where the output goes to. But there are generally two things you need to configure:
- Which classes are going to be logged and
- What level of logging is applied
The default logging level is INFO. But additional detail can typically be obtained by turning on the TRACE level, reporting on aspects that a component developer considers to be useful information. Setting a global value for the logging level is done for an application with the logging.level.root property. But you can limit the output and just select trace reporting from the MQ Spring Boot component by setting the property for just its classes: logging.level.com.ibm.mq.spring.boot=TRACE
You might want to combine the MQ-specific piece of the logging with the generic Spring JMS framework trace: logging.level.org.springframework.jms=TRACE
What does the trace show?
The trace shows the configuration that’s going to be applied. It also shows which kind of connection is going to be made – whether that’s a regular one, or XA – and how caching or pooling is configured.
Here’s an example of the output from a simple program when tracing is enabled. With no additional configuration, the output goes direct to the screen. This first piece is the “full” output line
2021-04-07 14:34:08.528 TRACE 76969 --- [ main] i.m.s.b.MQConnectionFactoryConfiguration : Creating single MQConnectionFactory 2021-04-07 14:34:08.542 TRACE 76969 --- [ main] c.i.m.s.boot.MQConnectionFactoryFactory : constructor 2021-04-07 14:34:08.542 TRACE 76969 --- [ main] c.i.m.s.boot.MQConnectionFactoryFactory : createConnectionFactory for class MQConnectionFactory
This is the complete trace but lightly edited for clarity to remove the timestamps and part of the class name:
MQConnectionFactoryConfiguration : Creating single MQConnectionFactory MQConnectionFactoryFactory : constructor MQConnectionFactoryFactory : createConnectionFactory for class MQConnectionFactory MQConnectionFactoryFactory : createConnectionFactoryInstance for class MQConnectionFactory MQConnectionFactoryFactory : configureConnectionFactory MQConfigurationProperties : queueManager : QM1 MQConfigurationProperties : applicationName : MyAppName MQConfigurationProperties : ccdtUrl : null MQConfigurationProperties : channel : SYSTEM.DEF.SVRCONN MQConfigurationProperties : clientId : null MQConfigurationProperties : connName : localhost(1414) MQConfigurationProperties : sslCipherSpec : null MQConfigurationProperties : sslCipherSuite : null MQConfigurationProperties : sslKeyresetcount: -1 MQConfigurationProperties : sslPeerName : null MQConfigurationProperties : tempModel : null MQConfigurationProperties : tempQPrefix : null MQConfigurationProperties : tempTopicPrefix : null MQConfigurationProperties : user : '' MQConfigurationProperties : password : Not provided MQConfigurationProperties : sslFIPSRequired : false MQConfigurationProperties : useIBMCipherMappings : true MQConfigurationProperties : userAuthenticationMQCSP: true MQConfigurationProperties : Additional Property - WMQ_CLIENT_RECONNECT_OPTIONS : 67108864 MQConfigurationProperties : Pooling is disabled MQConnectionFactoryFactory : Successfully mapped WMQ_CLIENT_RECONNECT_OPTIONS to property name XMSC_WMQ_CLIENT_RECONNECT_OPTIONS MQConnectionFactoryFactory : Using setIntProperty with key XMSC_WMQ_CLIENT_RECONNECT_OPTIONS and value 67108864 [0x04000000]
You can see all the properties that are set on the connection including those those set by the additionalProperties property. The password line will not show the actual password of course – but it does show whether or not you have supplied one.
In this case, the first line of the output shows that a single MQConnectionFactory is created. If the connection were being handled by a transaction coordinator, then the relevant class becomes an MQXAConnectionFactory.
If I change the properties file to set ibm.mq.pool.enabled=true then the trace changes to
MQConnectionFactoryConfiguration : Creating pooled MQConnectionFactory
and the configuration block shows
MQConfigurationProperties : Pool blockIfFullTimeout : PT-0.001S MQConfigurationProperties : Pool idleTimeout : PT30S MQConfigurationProperties : Pool maxConnections : 1 MQConfigurationProperties : Pool maxSessionsPerConn : 500 MQConfigurationProperties : Pool timeBetweenExpirationCheck : PT-0.001S
The “PT” is how Duration strings are prefixed … it looks a bit odd, but you can thank the ISO standards people for that.
You can see a similar and suitable line about the MQCF when the alternative caching mechanism spring.jms.cache.enabled is configured. If the Spring Framework JMS trace is also turned on then we get lines later in the output when the connection is actually being used, and messages start to be produced:
CachingConnectionFactory : Registering cached JMS Session for mode 0: com.ibm.mq.jms.MQSession@4349754 JmsTemplate : Executing callback on JMS Session: Cached JMS Session: ibm.mq.jms.MQSession@4349754 In destination resolver CachingConnectionFactory : Registering cached JMS Session for mode 0: com.ibm.mq.jms.MQSession@421fc931 CachingConnectionFactory : Registering cached JMS MessageProducer for destination [queue:///DEV.QUEUE.1?mdMessageContext=2&mdWriteEnabled=true]: com.ibm.mq.jms.MQQueueSender@5fad41be In convertAndSend completion. MessageType = com.ibm.jms.JMSTextMessage JmsTemplate : Sending created message: JMSMessage class: jms_text JMSType: null ...
How does this relate to MQ Trace and other tools
The Spring logger does not directly interact with the MQ trace options. With the right configuration options you can get MQ’s JMS client trace to go to the same file as the Spring logger. But it’s going to be rare that you really want to look at both – they are going to have different reasons for existing.
I think the Spring trace is much higher level than the MQ JMS trace, and more useful for most application-level debugging. In fact I really don’t like using the JMS trace unless I have to: it seems to have so many layers of abstraction/obstruction in the output because of how the classes are layered and inherit that it can be very hard to interpret without writing additional filtering scripts. It always feels to me very unlike the queue manager traces, which do have lots of layers, but where each layer does something useful rather than just being a wrapper around another object class. So there have been times when I’ve taken an queue manager trace (which also captures the SVRCONN processes that are handling a JMS client). But rarely, I’ve had to look at problems that could only really be dealt with by looking at what’s going on in the client code.
Similar to taking the queue manager and SVRCONN internal traces, MQ’s Application Activity Trace can give an idea of what the application is doing. Although you have to remember that by the time the queue manager is seeing the API calls, they have been transformed from the JMS API into the MQ API, so you don’t see a call to create a MessageConsumer; instead you see an MQOPEN and perhaps an MQINQ.
How efficient is the application
Looking at the MQ Spring Boot trace is mostly capable of giving you an idea of how efficient the connection management is. The other kinds of trace can help determine how efficient other parts of the application are.
For example, using JMSTemplate.sendAndReceive looks like a very convenient method to use in a program. It wraps up a number of things in a single call. But when you look at it in more detail (and this is where Activity Trace can be one way to capture the behaviour), you will see that every invocation creates and destroys a new Temporary Dynamic Queue. Which is known to be a bad idea for performance, especially when connecting to a z/OS queue manager. Instead, you would probably want to switch to creating separate MessageProducers and Consumers that can be reused through the lifetime of the application.
And I used Activity Trace when investigating the looping JMSListener implementation that I wrote about in a previous post. Those same events showed that the fix I proposed was actually working.
While I’m here …
As well as the performance and configuration-related questions, I have seen a number of questions about general Spring JMS application programming. There seem to be quite a few simple examples published, but once you want to do something a bit more complex, then a lot more hunting is needed. The MQ Spring Boot github repository now holds a few sample programs to demonstrate some advanced features. But even more examples have been recently added to the mq-dev-patterns repository.
This post was last updated on May 4th, 2021 at 08:50 pm