Collecting a trace of the JMS API calls made by an MDB, message-driven bean, application.

Answer

WebSphere Application Server provides a diagnostic trace facility that can be used to diagnose problems. It is possible to configure this trace facility to generate trace information about the JMS API calls made by a message-driven bean application. This is useful for application developers who want to see the code path taken by their application.

To enable a trace of the JMS API calls made by a message-driven bean application, set up a WebSphere Application Server trace using the following trace string:

*=info:
com.ibm.ejs.jms.JMSConnectionFactoryHandle=all:
com.ibm.ejs.jms.JMSConnectionHandle=all:
com.ibm.ejs.jms.JMSMessageConsumer=all:
com.ibm.ejs.jms.JMSMessageProducerHandle=all:
com.ibm.ejs.jms.JMSQueueBrowserHandle=all:
com.ibm.ejs.jms.JMSQueueConnectionFactoryHandle=all:
com.ibm.ejs.jms.JMSQueueConnectionHandle=all:
com.ibm.ejs.jms.JMSQueueReceiverHandle=all:
com.ibm.ejs.jms.JMSQueueSenderHandle=all:
com.ibm.ejs.jms.JMSQueueSessionHandle=all:
com.ibm.ejs.jms.JMSSessionHandle=all:
com.ibm.ejs.jms.JMSTopicConnectionFactoryHandle=all:
com.ibm.ejs.jms.JMSTopicConnectionHandle=all:
com.ibm.ejs.jms.JMSTopicPublisherHandle=all:
com.ibm.ejs.jms.JMSTopicSessionHandle=all:
com.ibm.ejs.jms.JMSTopicSubscriberHandle=all:
com.ibm.ejs.j2c.work.WorkProxy=all:

The format of each statement in a WebSphere Application Server trace is shown below:

[timestamp] <thread id> <class> <type> <method> <object identifier> <data>

where:

• <timestamp> is the time when the trace statement was generated.
• <thread id> is the identifier of the application server thread that generated the trace statement.
• <class> is the class that generated the trace statement.
• <type> is the type of trace statement that was generated. A > in this column indicates an entry trace point, and a < is an exit trace point.
• <method> is the method that was called when the trace statement was generated.
• <object id> is the Java object that the method mentioned in the trace statement was called on.
• <data> is the trace data associated with the trace statement.

When looking at a WebSphere Application Server trace of the JMS API calls made by a message-driven bean application, the first thing to do is to determine:

• When the message-driven bean's onMessage() method was called.
• When the message-driven bean's onMessage() method exited.
• What thread within the application server was running the message-driven bean instance.

To do this, look in the trace for statements similar to the ones shown below:

[03/02/14 09:26:02:568 GMT] 00000019 WorkProxy     1   (id=1) Actual call to work.run
[03/02/14 09:26:33:057 GMT] 00000019 WorkProxy     1   (id=1) Returned from work.run

The first trace statement shows that the application server prepared to invoke a message-driven bean onMessage() method at 09:26:02.

The second trace statement indicates that the work carried out inside the onMessage() method completed at 09:26:33.

The identifier of the thread that the application server was running the message-driven bean instance on can be seen in the second column of each trace statement. In the two examples above, the message-driven bean's onMessage() method was running on thread 00000019.


The next step is to look through the trace for statements that occur on the thread that the message-driven bean instance was running on, between the time when the onMessage() method was called and when the method exited.

Trace statements that have a > in the fourth column are entry trace points, and in most cases indicate that an application has called the method shown in the trace statement. Similarly, trace statements that have a < in the fourth column are exit trace points, and in most cases show that the method called by the application has completed and returned control back to the message-driven bean application.

The exceptions to this are shown below:

JMSConnection > JMSConnectionHandle
JMSConnection < JMSConnectionHandle
JMSConnection > setManagedConnection
JMSConnection < setManagedConnection

JMSSessionHan > JMSSessionHandle
JMSSessionHan < JMSSessionHandle
JMSSessionHan > activate
JMSSessionHan < activate

JMSMessageCon > JMSMessageConsumerHandle
JMSMessageCon < JMSMessageConsumerHandle

JMSMessagePro > JMSMessageProducerHandle
JMSMessagePro < JMSMessageProducerHandle

These trace points represent internal methods called by the WebSphere Application Server WebSphere MQ messaging provider when creating JMS objects, such as JMS Connections, JMS Sessions and JMS MessageProducers. These trace statements can be ignored.


An example of a WebSphere Application Server trace of the JMS API calls made by a message-driven bean application is shown below (note that the trace statements that represent internal method calls made by the WebSphere Application Server WebSphere MQ messaging provider shown above have been omitted):

00000019 WorkProxy     1   (id=1) Actual call to work.run

00000019 JMSConnection >  JMSConnectionFactoryHandle (com.ibm.ejs.jms.JMSConnectionFactoryHandle) [21f9c2f] Entry
com.ibm.ejs.jms.WMQJMSRAManagedConnectionFactory@2288105
physical connection factory = null
default user name = null
object type = 9
properties = {CLIENTRECONNECTOPTIONS=DISABLED, SS=2, PINT=5000, BSUB=SYSTEM.JMS.ND.SUBSCRIBER.QUEUE, PORT=1414, DAUTH=BASIC, CLINT=3600000, SSUBS=NO, CCSUB=SYSTEM.JMS.ND.CC.SUBSCRIBER.QUEUE, CHAN=MY.SVRCONN, MC=NONE, CROPT=DISABLED, FIQ=1, QMGR=myQmgr, XMSC_WMQ_CLIENT_RECONNECT_OPTIONS=33554432, CL=SAFE, CLIENTRECONNECTTIMEOUT=1800, BPUB=SYSTEM.BROKER.DEFAULT.STREAM, HOST=localhost, CCS=819, PVER=6, MAPNAMESTYLE=COMPATIBLE, CRT=1800, TCM=YES, MSEL=0, XMSC_WMQ_CLIENT_RECONNECT_TIMEOUT=1800, BCON=SYSTEM.BROKER.CONTROL.QUEUE, BVER=0, PAI=25, TM=SYSTEM.DEFAULT.MODEL.QUEUE, HC=NONE, SRI=60000, RINT=5000, SRC=0, MCAST=DISABLED, TRAN=1}
   [ConnectionManager]@21f2d6c
JNDI Name <jms/connectionFactory>
shareable <false>
00000019 JMSConnection <  JMSConnectionFactoryHandle (com.ibm.ejs.jms.JMSConnectionFactoryHandle) [21f9c2f] Exit

00000019 JMSConnection >  createConnection (com.ibm.ejs.jms.JMSConnectionFactoryHandle) [21f9c2f] Entry
myUserName
password not traced
    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :
00000019 JMSConnection <  createConnection (com.ibm.ejs.jms.JMSConnectionFactoryHandle) [21f9c2f] Exit
com.ibm.ejs.jms.JMSConnectionHandle@223da0d
managed connection = com.ibm.ejs.jms.JMSManagedConnection@21ff2b3
physical connection = com.ibm.mq.jms.MQXAConnection@21ffebd
closed = false
invalid = false
restricted methods enabled = false
open session handles = []


00000019 JMSConnection >  start (com.ibm.ejs.jms.JMSConnectionHandle) [223da0d] Entry
00000019 JMSConnection <  start (com.ibm.ejs.jms.JMSConnectionHandle) [223da0d] Exit

00000019 JMSConnection >  createSession (com.ibm.ejs.jms.JMSConnectionHandle) [223da0d] Entry
true
1
    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :
00000019 JMSConnection <  createSession (com.ibm.ejs.jms.JMSConnectionHandle) [223da0d] Exit
                                 com.ibm.ejs.jms.JMSSessionHandle@226ebea
managed session = com.ibm.ejs.jms.JMSManagedSession@224155f
state = ACTIVE
restricted methods enabled = false
open children = []

00000019 JMSSessionHan >  createProducer (com.ibm.ejs.jms.JMSSessionHandle) [226ebea] Entry
 queue:///outputQueue?destDescription=A+JNDI+definition+that+maps+to+the+queue+%22outputQueue%22%2C+which+is+where+message-driven+beans+send+messages+to%2C
    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :    :
00000019 JMSSessionHan <  createProducer (com.ibm.ejs.jms.JMSSessionHandle) [226ebea] Exit
                                 com.ibm.ejs.jms.JMSMessageProducerHandle@2272fa7
session handle = com.ibm.ejs.jms.JMSSessionHandle@226ebea
message ID disabled = null
message timestamp disabled = null
delivery mode = null
priority = null
time to live = null
closed = false


00000019 JMSSessionHan >  createTextMessage (com.ibm.ejs.jms.JMSSessionHandle) [226ebea] Entry
00000019 JMSSessionHan <  createTextMessage (com.ibm.ejs.jms.JMSSessionHandle) [226ebea] Exit
                                 
  JMSMessage class: jms_text
  JMSType:          null
  JMSDeliveryMode:  2
  JMSExpiration:    0
  JMSPriority:      4
  JMSMessageID:     null
  JMSTimestamp:     0
  JMSCorrelationID: null
  JMSDestination:   null
  JMSReplyTo:       null
  JMSRedelivered:   false
<null>

00000019 JMSMessagePro >  send (com.ibm.ejs.jms.JMSMessageProducerHandle) [2272fa7] Entry
                                 
  JMSMessage class: jms_text
  JMSType:          null
  JMSDeliveryMode:  2
  JMSExpiration:    0
  JMSPriority:      4
  JMSMessageID:     null
  JMSTimestamp:     0
  JMSCorrelationID: null
  JMSDestination:   null
  JMSReplyTo:       null
  JMSRedelivered:   false
hello
00000019 JMSMessagePro <  send (com.ibm.ejs.jms.JMSMessageProducerHandle) [2272fa7] Exit

00000019 JMSConnection >  close (com.ibm.ejs.jms.JMSConnectionHandle) [223da0d] Entry
00000019 JMSConnection <  close (com.ibm.ejs.jms.JMSConnectionHandle) [223da0d] Exit

00000019 WorkProxy     1   (id=1) Returned from work.run

From this trace, it can be seen that the message-driven bean's onMessage() method looked up a JMS Connection Factory definition that had the JNDI name jms/connectionFactory, and then made the following JMS API calls:

• ConnectionFactory.createConnection("myUserName", "password");
• Connection.start();
• Connection.createSession(true, Session.AUTO_ACKNOWLEDGE);
• Session.createProducer("queue://outputQueue")l
• Session.createTextMessage();
• Producer.send(TextMessage);
• Connection.close();