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 IndexIBM MQ API SupportC# MQGET blocks for 6 minutes, even though a message arrived

Post new topicReply to topic
C# MQGET blocks for 6 minutes, even though a message arrived View previous topic :: View next topic
Author Message
r.nabben
PostPosted: Wed Nov 04, 2020 8:27 am Post subject: C# MQGET blocks for 6 minutes, even though a message arrived Reply with quote

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
View user's profile Send private message
gbaddeley
PostPosted: Wed Nov 04, 2020 1:59 pm Post subject: Reply with quote

Jedi

Joined: 25 Mar 2003
Posts: 2192
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
View user's profile Send private message
r.nabben
PostPosted: Thu Nov 05, 2020 2:40 am Post subject: Reply with quote

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
View user's profile Send private message
gbaddeley
PostPosted: Thu Nov 05, 2020 4:25 pm Post subject: Reply with quote

Jedi

Joined: 25 Mar 2003
Posts: 2192
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
View user's profile Send private message
hughson
PostPosted: Thu Nov 05, 2020 9:15 pm Post subject: Reply with quote

Padawan

Joined: 09 May 2013
Posts: 1512
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
View user's profile Send private message Visit poster's website
Display posts from previous:
Post new topicReply to topic Page 1 of 1

MQSeries.net Forum IndexIBM MQ API SupportC# MQGET blocks for 6 minutes, even though a message arrived
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.