ASG
IBM
Zystems
Cressida
Icon
Netflexity
 
  MQSeries.net
Search  Search       Tech Exchange      Education      Certifications      Library      Info Center      SupportPacs      LinkedIn  Search  Search                                                                   FAQ  FAQ   Usergroups  Usergroups
 
Register  ::  Log in Log in to check your private messages
 
RSS Feed - WebSphere MQ Support RSS Feed - Message Broker Support

MQSeries.net Forum Index » IBM MQ Java / JMS » Unexplained delay in posting and reading messages

Post new topic  Reply to topic Goto page 1, 2  Next
 Unexplained delay in posting and reading messages « View previous topic :: View next topic » 
Author Message
imeh
PostPosted: Mon Feb 21, 2011 11:47 pm    Post subject: Unexplained delay in posting and reading messages Reply with quote

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
View user's profile Send private message
Vitor
PostPosted: Tue Feb 22, 2011 4:20 am    Post subject: Reply with quote

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
View user's profile Send private message
imeh
PostPosted: Tue Feb 22, 2011 4:32 am    Post subject: Reply with quote

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
View user's profile Send private message
Vitor
PostPosted: Tue Feb 22, 2011 4:54 am    Post subject: Reply with quote

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
View user's profile Send private message
imeh
PostPosted: Tue Feb 22, 2011 5:14 am    Post subject: Reply with quote

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
View user's profile Send private message
mqjeff
PostPosted: Tue Feb 22, 2011 5:37 am    Post subject: Reply with quote

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
View user's profile Send private message
imeh
PostPosted: Tue Feb 22, 2011 6:03 am    Post subject: Reply with quote

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
View user's profile Send private message
mqjeff
PostPosted: Tue Feb 22, 2011 6:29 am    Post subject: Reply with quote

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
View user's profile Send private message
imeh
PostPosted: Tue Feb 22, 2011 7:14 am    Post subject: Reply with quote

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
View user's profile Send private message
fjb_saper
PostPosted: Tue Feb 22, 2011 7:24 am    Post subject: Reply with quote

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
View user's profile Send private message Send e-mail
imeh
PostPosted: Tue Feb 22, 2011 7:40 am    Post subject: Reply with quote

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
View user's profile Send private message
mqjeff
PostPosted: Tue Feb 22, 2011 7:49 am    Post subject: Reply with quote

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
View user's profile Send private message
fjb_saper
PostPosted: Tue Feb 22, 2011 7:50 am    Post subject: Reply with quote

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
View user's profile Send private message Send e-mail
mqjeff
PostPosted: Tue Feb 22, 2011 8:19 am    Post subject: Reply with quote

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
View user's profile Send private message
imeh
PostPosted: Tue Feb 22, 2011 8:37 am    Post subject: Reply with quote

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
View user's profile Send private message
Display posts from previous:   
Post new topic  Reply to topic Goto page 1, 2  Next Page 1 of 2

MQSeries.net Forum Index » IBM MQ Java / JMS » Unexplained delay in posting and reading messages
Jump to:  



You cannot post new topics in this forum
You cannot reply to topics in this forum
You cannot edit your posts in this forum
You cannot delete your posts in this forum
You cannot vote in polls in this forum
Protected by Anti-Spam ACP
 
 


Theme by Dustin Baccetti
Powered by phpBB © 2001, 2002 phpBB Group

Copyright © MQSeries.net. All rights reserved.