|
RSS Feed - WebSphere MQ Support
|
RSS Feed - Message Broker Support
|
|
|
C# MQGET blocks for 6 minutes, even though a message arrived |
« View previous topic :: View next topic » |
Author |
Message
|
r.nabben |
Posted: Wed Nov 04, 2020 8:27 am Post subject: C# MQGET blocks for 6 minutes, even though a message arrived |
|
|
Newbie
Joined: 04 Nov 2020 Posts: 2
|
We're using amqmdnet.dll to read from a single queue. We issue a Get, with a timeout of 5 seconds. But every so often, we see that the Get blocks for 5 to 6 minutes. We're doing simple reads, without filtering of any kind.
Looking at MQtrace logging shows that the Get has sent a request for new messsage, and has received one message. The ProxyQueue pulses all getters, but our reader thread is not woken up. After 5 minutes, MQ itself sends a heartbeat to the remote end, and 60 seconds later the connection is closed because MQ did not get a response .
My question: what could cause this? How do I prevent this?
For example, yesterday I saw the following
At 21:29:11.856152, we start a new MQGET operation. This operation times out after 6 minutes. The request for message to the queue manager appears to succeed, but there is a 5 second pause in this part that I cannot explain.
0012B7C5 21:29:11.856152 2392.16 -------} MQProxyQueue.CheckSelectionCriteria(MQMessageDescriptor,MQGetMessageOptions,MQLONG,ref MQLONG,ref MQLONG) rc=OK
0012B7C6 21:29:11.856152 2392.16 -------{ MQProxyQueue.ReleaseMutex() inputs [0] [True]
0012B7C7 21:29:11.856152 2392.16 -------} MQProxyQueue.ReleaseMutex() rc=OK
0012B7C8 21:29:16.856238 2392.16 -------{ MQProxyQueue.RequestMutex() inputs [0] [True]
0012B7C9 21:29:16.856238 2392.16 -------} MQProxyQueue.RequestMutex() rc=OK
0012B7CA 21:29:16.856238 2392.16 -------{ ManagedHconn.IsQuiescing() inputs [False] [False] [True]
0012B7CB 21:29:16.856238 2392.16 -------} ManagedHconn.IsQuiescing() rc=OK returns [False]
0012B7CC 21:29:16.856238 2392.16 -------{ MQProxyQueue.FlushQueue(Boolean) inputs [True]
0012B7CD 21:29:16.856238 2392.16 --------{ MQProxyQueue.RequestMessages(Boolean,int,Boolean) inputs [True] [0] [True] [False]
0012B7CE 21:29:16.856238 2392.16 Hconn value = 7,` Session = 414D514354315432514D4752422020209B837D5F2FD4CF20
0012B7CF 21:29:16.856238 2392.16 Constructing IBM.WMQ.MQREQUEST_MSGS#02D34535 MQMBID sn=p900-010-200430 su=_SIMXsI6_EeqgerCbjj3OkA pn=lib/dotnet/pc/winnt/nmqi/MQREQUEST_MSGS.cs
---------
0012B7F5 21:29:16.856238 2392.16 Send returned 76
0012B7F6 21:29:16.856238 2392.16 Send << - n = 76
0012B7F7 21:29:16.856238 2392.16 -----------} MQTCPConnection.Send(byte[],int,int,int,int) rc=OK
0012B7F8 21:29:16.856238 2392.16 -----------{ MQFAPConnection.ReleaseSendLock() inputs [4096] [True]
0012B7F9 21:29:16.856238 2392.16 -----------} MQFAPConnection.ReleaseSendLock() rc=OK
0012B7FA 21:29:16.856238 2392.16 ----------} MQSession.SendData(byte [],int,int,byte,int) rc=OK
At 21:29:29.090823, MQ received a message. All readers were pulsed, but our reader did not wake up. At this moment the MQ heartbeat timeout is set to 21:34:29.
0012BB29 21:29:29.090823 2392.7 Last data received at 11/3/2020 8:29:29 PM
0012BB2A 21:29:29.090823 2392.7 Due next heartbeat at 11/3/2020 8:34:29 PM
0012BB2B 21:29:29.090823 2392.7 Setting timeout to 300000 ms
-----
0012BAFC 21:29:29.090823 2392.7 Pulsing getter on this PQ
0012BAFD 21:29:29.090823 2392.7 Message added to Queue
Here thread 2392.16 should have been woken up…
At 21:34:29.103318, MQ decides to send an MQ heartbeat (because no data has been received for the last 5 minutes), expecting a reply in 60 seconds.
0012CEAA 21:34:29.103318 2392.7 ------{ MQFAPConnection.SendHeartbeat(int) inputs [1]
….
0012CEC3 21:34:29.103318 2392.7 Heartbeat was sent at 11/3/2020 8:34:29 PM
0012CEC4 21:34:29.103318 2392.7 Heartbeat response due by 11/3/2020 8:35:29 PM
0012CEC5 21:34:29.103318 2392.7 Setting timeout to 60000 ms
At 21:35:29.106177, the tcp receive operation timed out (the MQ heartbeat response did not arrive), with error code 2009. In MQ, the socket is closed.
0012D2AC 21:35:29.106177 2392.7 ----------------
0012D2AE 21:35:29.106177 2392.7 Data Length --> 0
0012D2AF 21:35:29.106177 2392.7 -----} MQTCPConnection.Receive(ref byte [ ],ref int,ref int) rc=OK
0012D2B0 21:35:29.106177 2392.7 Number of bytes read from Socket by RcvThread = 0
0012D2B1 21:35:29.106177 2392.7 New MQException CompCode: 2 Reason: 2009
0012D2B2 21:35:29.106177 2392.7 New NmqiException CompCode: 2 Reason: 2009
At 21:35:30.996831, the MQGET operation is completed and notified of this error
0012D390 21:35:30.996831 2392.16 New MQException CompCode: 2 Reason: 2009
0012D391 21:35:30.996831 2392.16 New NmqiException CompCode: 2 Reason: 2009
0012D392 21:35:30.996831 2392.16 CompCode: 2, Reason: 2009
0012D393 21:35:30.996831 2392.16 ---------} MQSession.ExchangeTSH(MQTSH) rc=OK
0012D394 21:35:30.996831 2392.16 ---------{ MQProxyQueue.RequestMutex() inputs [IBM.WMQ.Nmqi.ManagedHconn#037327DF]
0012D395 21:35:30.996831 2392.16 ---------} MQProxyQueue.RequestMutex() rc=OK
0012D396 21:35:30.996831 2392.16 --------} MQProxyQueue.RequestMessages(Boolean,int,Boolean) rc=OK
0012D397 21:35:30.996831 2392.16 -------} MQProxyQueue.FlushQueue(Boolean) rc=OK
0012D398 21:35:30.996831 2392.16 -------{ MQProxyQueue.ReleaseMutex() inputs [IBM.WMQ.Nmqi.ManagedHconn#037327DF] [0x2] [IBM.WMQ.MQMessageDescriptor#005520DA] [IBM.WMQ.MQGetMessageOptions#016847ED] [4096] [System.Byte[]] [dataLength : out] [null] [compCode : out] [reason : out]
0012D399 21:35:30.996831 2392.16 -------} MQProxyQueue.ReleaseMutex() rc=OK
0012D39A 21:35:30.996831 2392.16 ------} MQProxyQueue.ProxyMQGET(MQMessageDescriptor,MQGetMessageOptions,MQLONG,byte [ ],ref MQLONG,MQLPIGetOpts,ref MQLONG,ref MQLONG) rc=OK
0012D39B 21:35:30.996831 2392.16 !! - __________
0012D39C 21:35:30.996831 2392.16 !! - MQGET <<
0012D39D 21:35:30.996831 2392.16 !! - Hconn : Input Parm
0012D39E 21:35:30.996831 2392.16 !! - Hobj : Input Parm |
|
Back to top |
|
|
gbaddeley |
Posted: Wed Nov 04, 2020 1:59 pm Post subject: |
|
|
Jedi Knight
Joined: 25 Mar 2003 Posts: 2527 Location: Melbourne, Australia
|
Is there anything in the queue manager error logs at about 21:29:16, or after? The socket could have closed, due to a network error or other issue. _________________ Glenn |
|
Back to top |
|
|
r.nabben |
Posted: Thu Nov 05, 2020 2:40 am Post subject: |
|
|
Newbie
Joined: 04 Nov 2020 Posts: 2
|
I'm trying to get someone on the other end to look at the logs, but the guys I have contact with are working mostly on the application level. They're not the ones responsible for the MQ setup.
We've discussed changing the HBINT from the default of 300 seconds back to something much less, but I'm afraid that will make the other issue (reader thread not woken) less visible. The heartbeat shouldn't really be needed either, on application level there is a heartbeat message every 30 seconds.
We open 2 queues, one for writing, and another for reading. We use a separate connection to the queue manager for each. The writing part keeps working, it's the reading connection that fails.
So the message producing thread creates an MQQueueManager instance for QM 'A', and creates an MQQueue instance for queue 'Q1'
The message reader thread creates another MQQueueManager instance for QM 'A', and creates an MQQueue instance for queue 'Q2'
Once we get the 2009 error, we can restart communication by closing the reader's connection to QM 'A' and reconnect (new MQQueueManager instance, new MQQueue for 'Q2')
Did we trigger some sort of race condition by opening 2 connections to the QM?
I've refactored my code to test this, but the system is being prepared to be put into production and now I am not allowed to test |
|
Back to top |
|
|
gbaddeley |
Posted: Thu Nov 05, 2020 4:25 pm Post subject: |
|
|
Jedi Knight
Joined: 25 Mar 2003 Posts: 2527 Location: Melbourne, Australia
|
Hi r.nabben,
Quote: |
The message reader thread creates another MQQueueManager instance for QM 'A', and creates an MQQueue instance for queue 'Q2' |
This thread will be mostly sitting on a socket receive, for MQI responses and heart beats from the qmgr. However, it will do a send for regular heartbeats initiated from the client side. These should all appear in the trace.
There are no known race conditions with multiple MQ client connections.
This is a potential blocker for prod deployment, so it needs to be resolved.
You really need the MQ error logs from the qmgr. _________________ Glenn |
|
Back to top |
|
|
hughson |
Posted: Thu Nov 05, 2020 9:15 pm Post subject: |
|
|
Padawan
Joined: 09 May 2013 Posts: 1948 Location: Bay of Plenty, New Zealand
|
This sounds like a defect to me. I hope you have raised a case/PMR with IBM?
Cheers,
Morag _________________ Morag Hughson @MoragHughson
IBM MQ Technical Education Specialist
Get your IBM MQ training here!
MQGem Software |
|
Back to top |
|
|
|
|
|
|
Page 1 of 1 |
|
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
|
|
|
|