MQSeries.net :: View topic - Unexplained delay in posting and reading messages

imeh · Posted: Tue Feb 22, 2011 4:18 am Post subject:

Hi,

We are using weblogic 10.3 and MQ API 6.0.2.5. We are reading and writing messages to 2 seperate queues. There is a delay in writing and reading messages for which we are not able to identifiy the root cause.

The thread dump on weblogic shows that the threads are blocked for IO operation. What is the cause of this block?
"[ACTIVE] ExecuteThread: '16' for queue: 'weblogic.kernel.Default (self-tuning)'" waiting for lock java.io.PrintStream@b596c4 BLOCKED

java.io.PrintStream.write(PrintStream.java:410)

java.io.PrintStream.write(PrintStream.java:412)

sun.nio.cs.StreamEncoder$CharsetSE.writeBytes(StreamEncoder.java:336)

sun.nio.cs.StreamEncoder$CharsetSE.implFlushBuffer(StreamEncoder.java:404)

sun.nio.cs.StreamEncoder.flushBuffer(StreamEncoder.java:115)

java.io.OutputStreamWriter.flushBuffer(OutputStreamWriter.java:169)

java.io.PrintStream.newLine(PrintStream.java:478)

java.io.PrintStream.println(PrintStream.java:629)

sun.misc.HexDumpEncoder.encodeLineSuffix(HexDumpEncoder.java:99)

sun.misc.CharacterEncoder.encodeBuffer(CharacterEncoder.java:280)

com.sun.net.ssl.internal.ssl.CipherBox.encrypt(CipherBox.java:179)

com.sun.net.ssl.internal.ssl.OutputRecord.encrypt(OutputRecord.java:185)

com.sun.net.ssl.internal.ssl.SSLSocketImpl.writeRecord(SSLSocketImpl.java:665)

com.sun.net.ssl.internal.ssl.AppOutputStream.write(AppOutputStream.java:59)

java.io.DataOutputStream.write(DataOutputStream.java:90)

java.io.FilterOutputStream.write(FilterOutputStream.java:80)

com.ibm.mq.MQInternalCommunications.writeToServer(MQInternalCommunications.java:2416)

com.ibm.mq.MQInternalCommunications.send(MQInternalCommunications.java:902)

com.ibm.mq.MQSESSIONClient.lowLevelComms(MQSESSIONClient.java:2840)

com.ibm.mq.MQSESSIONClient.MQOPEN(MQSESSIONClient.java:3495)

com.ibm.mq.MQQueueManager.<init>(MQQueueManager.java:2053)

com.ibm.mq.MQManagedConnectionJ11.getConnection(MQManagedConnectionJ11.java:426)

com.ibm.mq.MQSimpleConnectionManager.allocateConnection(MQSimpleConnectionManager.java:134)

com.ibm.mq.MQQueueManagerFactory.obtainBaseMQQueueManager(MQQueueManagerFactory.java:795)

com.ibm.mq.MQQueueManagerFactory.procure(MQQueueManagerFactory.java:709)

com.ibm.mq.MQQueueManagerFactory.constructQueueManager(MQQueueManagerFactory.java:664)

com.ibm.mq.MQQueueManagerFactory.createQueueManager(MQQueueManagerFactory.java:160)

com.ibm.mq.MQQueueManager.<init>(MQQueueManager.java:475)

com.hk.targetsystems.wldp.util.DSLMQConnection.<init>(DSLMQConnection.java:4

com.hk.targetsystems.wldp.util.DSLMQObjectPool.getDSLMQResource(DSLMQObjectPool.java:565)

com.hk.targetsystems.wldp.connector.WldpConnector.connectMQ(WldpConnector.java:553)

com.hk.targetsystems.wldp.connector.WldpConnector.connect(WldpConnector.java:126)

com.hk.targetsystems.wldp.handler.WldpDBHandler.processData(WldpDBHandler.java:82)

com.hk.targetsystems.wldp.multiplexer.WldpConnectorMDB.onMessage(WldpConnectorMDB.java:156)

weblogic.ejb.container.internal.MDListener.execute(MDListener.java:466)

weblogic.ejb.container.internal.MDListener.transactionalOnMessage(MDListener.java:371)

weblogic.ejb.container.internal.MDListener.onMessage(MDListener.java:327)

weblogic.jms.client.JMSSession.onMessage(JMSSession.java:4072)

weblogic.jms.client.JMSSession.execute(JMSSession.java:3964)

weblogic.jms.client.JMSSession$UseForRunnable.run(JMSSession.java:4490)

weblogic.work.SelfTuningWorkManagerImpl$WorkAdapterImpl.run(SelfTuningWorkManagerImpl.java:464)

weblogic.work.ExecuteThread.execute(ExecuteThread.java:200)

weblogic.work.ExecuteThread.run(ExecuteThread.java:172)

On the MQ trace there is a delay which we are not able to understand:

Snippet#1
Line 97625: [21/02/2011 06:29:44:333 EST] Thread: [ACTIVE] ExecuteThread: '30' for queue: 'weblogic.kernel.Default (self-tuning)', Object: com.ibm.mq.MQv6InternalCommunications@1d38787 ==> timedReadInt() entry
Line 98536: [21/02/2011 06:29:54:896 EST] Thread: [ACTIVE] ExecuteThread: '30' for queue: 'weblogic.kernel.Default (self-tuning)', Object: com.ibm.mq.MQv6InternalCommunications@1d38787 <== timedReadInt() exit

Snippet#2
Line 95942: [21/02/2011 06:29:27:287 EST] Thread: [ACTIVE] ExecuteThread: '30' for queue: 'weblogic.kernel.Default (self-tuning)', Object: com.ibm.mq.MQv6InternalCommunications@1d38787 ==> buildAPIHeader() entry
Line 95943: [21/02/2011 06:29:27:287 EST] Thread: [ACTIVE] ExecuteThread: '30' for queue: 'weblogic.kernel.Default (self-tuning)', Object: com.ibm.mq.MQv6InternalCommunications@1d38787 <== buildAPIHeader()

Snippet#3
Line 95953: [21/02/2011 06:29:27:288 EST] Thread: [ACTIVE] ExecuteThread: '30' for queue: 'weblogic.kernel.Default (self-tuning)', Object: com.ibm.mq.MQOutputStream@560ebc <== MQOutputStream.toByteArray()() exit
Line 97383: [21/02/2011 06:29:41:673 EST] Thread: [ACTIVE] ExecuteThread: '30' for queue: 'weblogic.kernel.Default (self-tuning)', Object: com.ibm.mq.MQv6InternalCommunications@1d38787 <== send() exit

Please help with any suggestions! We are trying to resolve this for weeks now.