MQSeries.net :: View topic - C# MQGET blocks for 6 minutes, even though a message arrived

r.nabben · Posted: Wed Nov 04, 2020 1:59 pm Post subject:

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