| Author |
Message
|
| imeh |
 Posted: Mon Feb 21, 2011 11:47 pm Post subject: Unexplained delay in posting and reading messages |
 |
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
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.  |
|
| Back to top |
|
 |
| Vitor |
| Posted: Tue Feb 22, 2011 4:20 am Post subject: |
|
|
Grand High Poobah
Joined: 11 Nov 2005
Posts: 26093
Location: Texas, USA
|
Don't double post - it's considered rude.
As to your problem, where in the trace does it show that WMQ is causing the block? How have you determined that WMQ is not waiting for I/O itself?
_________________
Honesty is the best policy.
Insanity is the best defence. |
|
| Back to top |
|
|
| imeh |
| Posted: Tue Feb 22, 2011 4:32 am Post subject: |
|
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
Apologies on the double post - i thot i had posted under incorrect forum. Will take all the care in the future.
In thread dump taken at the same time there are about 20+ threads doing only WMQ activities and waiting on the IO block. When i compared with MQ Trace, other threads were reading from writing to queues at the same time. This leads me to believe that WMQ is blocking IO - but not sure why it should block. |
|
| Back to top |
|
|
| Vitor |
| Posted: Tue Feb 22, 2011 4:54 am Post subject: |
|
|
Grand High Poobah
Joined: 11 Nov 2005
Posts: 26093
Location: Texas, USA
|
| imeh wrote: |
| Apologies on the double post - i thot i had posted under incorrect forum. Will take all the care in the future. |
If you post in the incorrect area in future, add a post asking a moderator to move it. We're nice people. Or at least the others are.
| imeh wrote: |
| In thread dump taken at the same time there are about 20+ threads doing only WMQ activities and waiting on the IO block. When i compared with MQ Trace, other threads were reading from writing to queues at the same time. This leads me to believe that WMQ is blocking IO - but not sure why it should block. |
Are all these threads of the same application? If not, does one application have it's commit processing working properly and another not?
Are all the threads properly configured set up for WMQ? Are you sharing connections, handles or anything like that in violation of the threading guidelines in the Application Programmer's Guide? Could the threads be blocking each other?
(And yes, I know that it's not the problem in Java it is in other languages because of Java's threading model. Just trying ideas here based on the class names looking like the native MQ ones rather than the JMS ones.)
_________________
Honesty is the best policy.
Insanity is the best defence. |
|
| Back to top |
|
|
| imeh |
| Posted: Tue Feb 22, 2011 5:14 am Post subject: |
|
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
All the threads are of the same application. We need concurrant connections to MQ. A single request for data is broken down into su requests and each message is posted to a JMS queue. A Java MDB picks up that message and connects to MQ queue to post the request. The same MDB waits to listen on to response from another MQ Queue.
We are using MQSimpleConnectionManager for sharing connections in a pool. (MaxConnections = 25, MaxUnused connections = 10). Connection pool is created on server startup and a new queue manager is created for every thread (MDB) to connect to MQ. |
|
| Back to top |
|
|
| mqjeff |
| Posted: Tue Feb 22, 2011 5:37 am Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
What does DIS CONN show on the qmgr at the time of this locking?
Well, DIS CONN and DIS CHSTATUS for the clientconn instances. |
|
| Back to top |
|
|
| imeh |
| Posted: Tue Feb 22, 2011 6:03 am Post subject: |
|
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
MQ queues and related utilities are managed by another team I have requested them to get this information for us.
Meanwhile, is there anything else that i can look into? |
|
| Back to top |
|
|
| mqjeff |
| Posted: Tue Feb 22, 2011 6:29 am Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
There are changes in the MQv7 client to allow for conversation sharing.
I don't recall off the top of my head how these options map to the JMS settings. But you could at least review the MQ JMS documentation and see if it shows how to disable conversation sharing.
This could be the source of the delay, if you are trying to share the conversation between too many things even though you think you have separate connections.
You can also look into enabling an MQ client trace on your side - without involvement per se from the MQ team. |
|
| Back to top |
|
|
| imeh |
| Posted: Tue Feb 22, 2011 7:14 am Post subject: |
|
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
I quickly searched MQ JMS documentation - could not find conversation sharing concept. However there are references to shared queues. There is also CONNOPT object with possible value that determine the level of sharing resources. Is this the one that you referring to?
Also there is MQC.ASSOCIATE_NONE, but this is the default value.
Not sure where I should search next? |
|
| Back to top |
|
|
| fjb_saper |
| Posted: Tue Feb 22, 2011 7:24 am Post subject: |
|
|
Grand High Poobah
Joined: 18 Nov 2003
Posts: 20756
Location: LI,NY
|
| Quote: |
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
|
Could that be waiting on the PrintStream due to excessive logging?
A wait on the PrintStream would have me looking somewhere else before I looked at WMQ... 
_________________
MQ & Broker admin |
|
| Back to top |
|
|
| imeh |
| Posted: Tue Feb 22, 2011 7:40 am Post subject: |
|
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
We have turned OFF all logging and monitored the response time using database trails, but it has almost no difference in the behaviour.
Another question - we are creating a new MQQueueManager for every thread. Although we are using a MQSimpleConnectionManager for the entire application level connection pooling, is it possible since that connections are reused some resources are shared? |
|
| Back to top |
|
|
| mqjeff |
| Posted: Tue Feb 22, 2011 7:49 am Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
| fjb_saper wrote: |
| Quote: |
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
|
Could that be waiting on the PrintStream due to excessive logging?
A wait on the PrintStream would have me looking somewhere else before I looked at WMQ... |
You need to look further up the call chain.
imeh - CONNOPT seems to relate to what I'm talking about, but it probably also varies if you're using a CCDTURL or not. |
|
| Back to top |
|
|
| fjb_saper |
| Posted: Tue Feb 22, 2011 7:50 am Post subject: |
|
|
Grand High Poobah
Joined: 18 Nov 2003
Posts: 20756
Location: LI,NY
|
So multiple areas of investigation:
- Check if JMS poolsize is adequate...
- Check that sharecnv is set to 1 if using a V7 client channel
- Find out what else (besides the logging) is using a PrintStream as this seems to be the locked object... a coverage analysis might help.
Have fun
_________________
MQ & Broker admin |
|
| Back to top |
|
|
| mqjeff |
| Posted: Tue Feb 22, 2011 8:19 am Post subject: |
|
|
Grand Master
Joined: 25 Jun 2008
Posts: 17447
|
| fjb_saper wrote: |
- Check that sharecnv is set to 1 if using a V7 client channel
- Find out what else (besides the logging) is using a PrintStream as this seems to be the locked object... a coverage analysis might help.
Have fun |
FJ -
The PrintStream is being called from the channel. It is an SSL enabled channel and clearly a client channel. This is from the call stack posted above.
And yes, I've pointed out SHARECNV. Are you aware of whether the JMS property CONNOPTS controls that or is there a different way (again, perhaps with the CCDT). |
|
| Back to top |
|
|
| imeh |
| Posted: Tue Feb 22, 2011 8:37 am Post subject: |
|
|
Newbie
Joined: 21 Feb 2011
Posts: 9
|
| We are not using MQ cleint v7, but we are using MQ API v 6.0.2.5 |
|
| Back to top |
|
|
|
|
