| |
|
RSS Feed - WebSphere MQ Support
|
RSS Feed - Message Broker Support
|
  |
|
| Help!Http request being blocked in a specific period |
« View previous topic :: View next topic » |
| Author |
Message
|
| liamf |
 Posted: Mon Feb 05, 2024 1:47 am Post subject: Help!Http request being blocked in a specific period |
 |
|
Novice
Joined: 22 Apr 2021
Posts: 13
|
I'm working with IBM ACE v11 on Linux, recently i have encountered a quite strange issue.
I found that some of the http request will cost 5 seconds to get a response but normally it would only cost 15-30ms. So i built a test messageflow which contains only a HttpInput Node and a HttpReply Node, but even in this such a simple messageflow the request still could be blocked for 5 seconds sometimes.
So, here are the steps that i have tried to figure it out.
1. I noticed that I'm using a integration node httplistener which will coordinate with IBMMQ, e.g. SYSTEM.BROKER.WS.INPUT, SYSTEM.BROKER.WS.REPLY, SYSTEM.BROKER.WS.ACK, so i checked the trace log found that whenever the request get blocked, the broker will trying to connect to SYSTEM.BROKER.WS.ACK and idk why, i've search the documentation and there is no description about this queue. Could someone please interpret it?
2. Then i wonder if it is the latency when broker trying to interact with IBMMQ? so i change the node listener to server embedded listener (Execution group level listener), but it still makes no effect, but i found some similar behaviours to those trace log above, the execution group (maybe?) is trying to process the following steps:
(1)About to get message from in-memory request queue
(2)Setting PAUSED flag
(3)Disabling EV_READ and EV_WRITE
(4)Connection already paused
(5)Start to execute a timeout sweeper thread till 5 seconds later, the httpinput receive a new request
Regarding to the attempts above, i made some assumptions here:
1.When the system receive a tcp request, it then will be received by httplistener of the broker (or execution group), and httplistener will deliver this message to system input queue (For broker listener - SYSTEM.BROKER.WS.INPUT, for embedded listener - in-memory queue), then HTTPInput node will get those requests and process it, pass it to HTTPReply node then return to a system reply queue, finally listener will pass this reply to the client, correct me if wrong.
2.With the assumptions and trace log above, i think the listener did not receive any request in those 5 seconds wait, because the broker already start to processing a idel logic which either do some ACK (in broker listener) or pause connection and clean connection (in embedded listener).
Therefore, i think it is the system queue that play a key-role in this issue, the request is either blocked in system input queue or blocked in system reply queue, or, the listener thread is in a racing condition cause the thread have to wait.
Could somebody help? I'm really curious about this.
Bellow are some trace log:
| Code: |
{ Imb::EvHtp::Request::storeEventHTTPHandle
2024-02-05 13:15:26.042274 49706 { ImbHandleManager::storeInputNodeMessageHandle(ImbInFlightCppHandle), 6, (*ptr)0x7f882c0689d0, 1707110427, 6, false
2024-02-05 13:15:26.042286 49706 { ImbInFlightHandleIndexList::storeMessageHandle, (*ptr)0x7f882c0689d0, 6
2024-02-05 13:15:26.042294 49706 { ImbInFlightGenericHandle::ImbInFlightGenericHandle(cpp), 2, (*ptr)0x7f8801239470
2024-02-05 13:15:26.042304 49706 } ImbInFlightGenericHandle::ImbInFlightGenericHandle(cpp)
2024-02-05 13:15:26.042312 49706 { ImbInFlightHandleIndexList::storeMessageHandleInternal, true, 1707110427, 6, 6
2024-02-05 13:15:26.042324 49706 { ImbInFlightGenericHandle::operator=, 0, 2, (*ptr)0x7f882c0adf60
2024-02-05 13:15:26.042334 49706 } ImbInFlightGenericHandle::operator=
2024-02-05 13:15:26.042342 49706 { ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 0, 5113, 2008109530, 49706
2024-02-05 13:15:26.042350 49706 } ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 0
2024-02-05 13:15:26.042360 49706 { ImbInFlightUserMessageHandle::asBlob, 0, 5113, 49706
2024-02-05 13:15:26.042370 49706 } ImbInFlightUserMessageHandle::asBlob, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042386 49706 } ImbInFlightHandleIndexList::storeMessageHandleInternal, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042398 49706 } ImbInFlightHandleIndexList::storeMessageHandle, 1, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042412 49706 { ImbInFlightGenericHandle::~ImbInFlightGenericHandle, 2, (*ptr)0x7f8801239470
2024-02-05 13:15:26.042426 49706 } ImbInFlightGenericHandle::~ImbInFlightGenericHandle
2024-02-05 13:15:26.042434 49706 } ImbHandleManager::storeInputNodeMessageHandle(ImbInFlightCppHandle), 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042446 49706 } Imb::EvHtp::Request::storeEventHTTPHandle, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042470 49706 libevhtp::htp__connection_readcb_, '[DEBUG]', 'nread = 85'
2024-02-05 13:15:26.042482 49706 libevhtp::htp__connection_readcb_, '[DEBUG]', 'Pausing connection'
2024-02-05 13:15:26.042492 49706 libevhtp::evhtp_connection_pause, '[DEBUG]', 'connection is already paused'
2024-02-05 13:15:26.042494 49708 { Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPHandle
2024-02-05 13:15:26.042516 49708 { Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPCPPHandle
2024-02-05 13:15:26.042526 49708 { Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPInternalHandle
2024-02-05 13:15:26.042536 49708 { ImbHandleManager::retrieveInputNodeMessageHandle
2024-02-05 13:15:26.042546 49708 { ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042560 49708 } ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 0
2024-02-05 13:15:26.042574 49708 { ImbInFlightHandleIndexList::retrieveMessageHandleDirect, 'X'4556485400000000f9130000da51b1772ac2000000000000'', 49708
2024-02-05 13:15:26.042586 49708 { ImbInFlightHandleIndexList::retrieveMessageHandleInternalDirect
2024-02-05 13:15:26.042596 49708 { ImbInFlightMessageHandle::validateAndMatchHandle, 5113, 2008109530, 49706, 'X'4556485400000000f9130000da51b1772ac2000000000000'', true, true, 1707110427
2024-02-05 13:15:26.042610 49708 } ImbInFlightMessageHandle::validateAndMatchHandle, true, 1707110126
2024-02-05 13:15:26.042620 49708 } ImbInFlightHandleIndexList::retrieveMessageHandleInternalDirect
2024-02-05 13:15:26.042630 49708 } ImbInFlightHandleIndexList::retrieveMessageHandleDirect, 1
2024-02-05 13:15:26.042638 49708 } ImbHandleManager::retrieveInputNodeMessageHandle, (*ptr)0x7f882c0adf20, 1
2024-02-05 13:15:26.042658 49708 } Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPInternalHandle, (*ptr)0x7f882c0adf20
2024-02-05 13:15:26.042672 49708 { ImbInFlightGenericHandle::ImbInFlightGenericHandle(copy), 2, (*ptr)0x7f87ff0b2610
2024-02-05 13:15:26.042680 49708 } ImbInFlightGenericHandle::ImbInFlightGenericHandle(copy)
2024-02-05 13:15:26.042688 49708 { ImbInFlightGenericHandle::~ImbInFlightGenericHandle, 2, (*ptr)0x7f87ff0b2610
2024-02-05 13:15:26.042698 49708 } ImbInFlightGenericHandle::~ImbInFlightGenericHandle
2024-02-05 13:15:26.042706 49708 } Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPCPPHandle, (*ptr)0x7f882c0adf20, (*ptr)0x7f882c0689d0
|
| Code: |
2024-02-05 13:15:26.041962 49706 libevhtp::hook_hostname_run, '[DEBUG]', 'enter'
2024-02-05 13:15:26.041972 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[69] = (a)'
2024-02-05 13:15:26.041980 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_almost_done'
2024-02-05 13:15:26.041990 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[70] = A (41)'
2024-02-05 13:15:26.042000 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_done'
2024-02-05 13:15:26.042010 49706 libevhtp::hook_hdr_val_run, '[DEBUG]', 'enter'
2024-02-05 13:15:26.042018 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[71] = c (63)'
2024-02-05 13:15:26.042028 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_key'
2024-02-05 13:15:26.042042 49706 libevhtp::hook_hdr_key_run, '[DEBUG]', 'enter'
2024-02-05 13:15:26.042052 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[77] = (20)'
2024-02-05 13:15:26.042060 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_space_before_val'
2024-02-05 13:15:26.042070 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[78] = * (2a)'
2024-02-05 13:15:26.042080 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_space_before_val'
2024-02-05 13:15:26.042090 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[79] = / (2f)'
2024-02-05 13:15:26.042100 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_val'
2024-02-05 13:15:26.042110 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_val'
2024-02-05 13:15:26.042122 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_val'
2024-02-05 13:15:26.042132 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[82] = (a)'
2024-02-05 13:15:26.042140 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_almost_done'
2024-02-05 13:15:26.042150 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[83] = (d)'
2024-02-05 13:15:26.042160 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_hdr_done'
2024-02-05 13:15:26.042170 49706 libevhtp::hook_hdr_val_run, '[DEBUG]', 'enter'
2024-02-05 13:15:26.042180 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] data[84] = (a)'
2024-02-05 13:15:26.042188 49706 libevhtp::htparser_run, '[DEBUG]', '[0x7f886c031480] s_hdrline_almost_done'
2024-02-05 13:15:26.042198 49706 libevhtp::hook_on_hdrs_complete_run, '[DEBUG]', 'enter'
2024-02-05 13:15:26.042210 49706 libevhtp::hook_on_msg_complete_run, '[DEBUG]', 'enter'
2024-02-05 13:15:26.042222 49706 libevhtp::evhtp_connection_pause, '[DEBUG]', 'setting PAUSED flag'
2024-02-05 13:15:26.042230 49706 libevhtp::evhtp_connection_pause, '[DEBUG]', 'disabling EV_READ'
2024-02-05 13:15:26.042246 49706 libevhtp::evhtp_connection_pause, '[DEBUG]', 'disabling EV_WRITE'
2024-02-05 13:15:26.042264 49706 { Imb::EvHtp::Request::storeEventHTTPHandle
2024-02-05 13:15:26.042274 49706 { ImbHandleManager::storeInputNodeMessageHandle(ImbInFlightCppHandle), 6, (*ptr)0x7f882c0689d0, 1707110427, 6, false
2024-02-05 13:15:26.042286 49706 { ImbInFlightHandleIndexList::storeMessageHandle, (*ptr)0x7f882c0689d0, 6
2024-02-05 13:15:26.042294 49706 { ImbInFlightGenericHandle::ImbInFlightGenericHandle(cpp), 2, (*ptr)0x7f8801239470
2024-02-05 13:15:26.042304 49706 } ImbInFlightGenericHandle::ImbInFlightGenericHandle(cpp)
2024-02-05 13:15:26.042312 49706 { ImbInFlightHandleIndexList::storeMessageHandleInternal, true, 1707110427, 6, 6
2024-02-05 13:15:26.042324 49706 { ImbInFlightGenericHandle::operator=, 0, 2, (*ptr)0x7f882c0adf60
2024-02-05 13:15:26.042334 49706 } ImbInFlightGenericHandle::operator=
2024-02-05 13:15:26.042342 49706 { ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 0, 5113, 2008109530, 49706
2024-02-05 13:15:26.042350 49706 } ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 0
2024-02-05 13:15:26.042360 49706 { ImbInFlightUserMessageHandle::asBlob, 0, 5113, 49706
2024-02-05 13:15:26.042370 49706 } ImbInFlightUserMessageHandle::asBlob, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042386 49706 } ImbInFlightHandleIndexList::storeMessageHandleInternal, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042398 49706 } ImbInFlightHandleIndexList::storeMessageHandle, 1, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042412 49706 { ImbInFlightGenericHandle::~ImbInFlightGenericHandle, 2, (*ptr)0x7f8801239470
2024-02-05 13:15:26.042426 49706 } ImbInFlightGenericHandle::~ImbInFlightGenericHandle
2024-02-05 13:15:26.042434 49706 } ImbHandleManager::storeInputNodeMessageHandle(ImbInFlightCppHandle), 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042446 49706 } Imb::EvHtp::Request::storeEventHTTPHandle, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042470 49706 libevhtp::htp__connection_readcb_, '[DEBUG]', 'nread = 85'
2024-02-05 13:15:26.042482 49706 libevhtp::htp__connection_readcb_, '[DEBUG]', 'Pausing connection'
2024-02-05 13:15:26.042492 49706 libevhtp::evhtp_connection_pause, '[DEBUG]', 'connection is already paused'
2024-02-05 13:15:26.042494 49708 { Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPHandle
2024-02-05 13:15:26.042516 49708 { Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPCPPHandle
2024-02-05 13:15:26.042526 49708 { Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPInternalHandle
2024-02-05 13:15:26.042536 49708 { ImbHandleManager::retrieveInputNodeMessageHandle
2024-02-05 13:15:26.042546 49708 { ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 'X'4556485400000000f9130000da51b1772ac2000000000000''
2024-02-05 13:15:26.042560 49708 } ImbInFlightUserMessageHandle::ImbInFlightUserMessageHandle, 0
2024-02-05 13:15:26.042574 49708 { ImbInFlightHandleIndexList::retrieveMessageHandleDirect, 'X'4556485400000000f9130000da51b1772ac2000000000000'', 49708
2024-02-05 13:15:26.042586 49708 { ImbInFlightHandleIndexList::retrieveMessageHandleInternalDirect
2024-02-05 13:15:26.042596 49708 { ImbInFlightMessageHandle::validateAndMatchHandle, 5113, 2008109530, 49706, 'X'4556485400000000f9130000da51b1772ac2000000000000'', true, true, 1707110427
2024-02-05 13:15:26.042610 49708 } ImbInFlightMessageHandle::validateAndMatchHandle, true, 1707110126
2024-02-05 13:15:26.042620 49708 } ImbInFlightHandleIndexList::retrieveMessageHandleInternalDirect
2024-02-05 13:15:26.042630 49708 } ImbInFlightHandleIndexList::retrieveMessageHandleDirect, 1
2024-02-05 13:15:26.042638 49708 } ImbHandleManager::retrieveInputNodeMessageHandle, (*ptr)0x7f882c0adf20, 1
2024-02-05 13:15:26.042658 49708 } Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPInternalHandle, (*ptr)0x7f882c0adf20
2024-02-05 13:15:26.042672 49708 { ImbInFlightGenericHandle::ImbInFlightGenericHandle(copy), 2, (*ptr)0x7f87ff0b2610
2024-02-05 13:15:26.042680 49708 } ImbInFlightGenericHandle::ImbInFlightGenericHandle(copy)
2024-02-05 13:15:26.042688 49708 { ImbInFlightGenericHandle::~ImbInFlightGenericHandle, 2, (*ptr)0x7f87ff0b2610
2024-02-05 13:15:26.042698 49708 } ImbInFlightGenericHandle::~ImbInFlightGenericHandle
2024-02-05 13:15:26.042706 49708 } Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPCPPHandle, (*ptr)0x7f882c0adf20, (*ptr)0x7f882c0689d0
2024-02-05 13:15:26.042716 49708 } Imb::EvHtp::RequestTimeoutControlBlock::acquireEventHTTPHandle, (*ptr)0x7f882c0adf20, (*ptr)0x7f882c0689d0
2024-02-05 13:15:26.042732 49708 { Imb::WSInputNode::useHTTPS() SAA_ACK_LATENCY_TEST_Messageflow#FCMComposite_1_1 ComIbmWSInputNode, false, SAA_ACK_LATENCY_TEST_Messageflow.HTTP Input
2024-02-05 13:15:26.042746 49708 } Imb::WSInputNode::useHTTPS() SAA_ACK_LATENCY_TEST_Messageflow#FCMComposite_1_1 ComIbmWSInputNode, false, SAA_ACK_LATENCY_TEST_Messageflow.HTTP Input
2024-02-05 13:15:26.042758 49708 { Imb::EvHtp::Request::addHeadersToBuffer
2024-02-05 13:15:26.042772 49708 { ImbBuffer::ImbBuffer , (*ptr)0, (*ptr)0x7f87ff0b2508, 0
2024-02-05 13:15:26.042784 49708 } ImbBuffer::ImbBuffer
2024-02-05 13:15:26.042792 49708 { ImbWriteBuffer::ImbWriteBuffer , (*ptr)0
2024-02-05 13:15:26.042800 49708 } ImbWriteBuffer::ImbWriteBuffer
2024-02-05 13:15:26.042816 49708 { ImbCommonBuffer::ImbCommonBuffer , (*ptr)0, 4096
2024-02-05 13:15:26.042826 49708 { ImbBuffer::allocateBuffer , 4096
2024-02-05 13:15:26.042840 49708 } ImbBuffer::allocateBuffer
2024-02-05 13:15:26.042850 49708 } ImbCommonBuffer::ImbCommonBuffer
2024-02-05 13:15:26.054882 43244 { Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:26.054944 43244 { ImbHandleManager::handleManager, (*ptr)0x7f888529d2f8
2024-02-05 13:15:26.054962 43244 } ImbHandleManager::handleManager
2024-02-05 13:15:26.054974 43244 } Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:26.075088 43244 { Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:26.075156 43244 { ImbHandleManager::handleManager, (*ptr)0x7f888529d2f8
2024-02-05 13:15:26.075166 43244 } ImbHandleManager::handleManager
2024-02-05 13:15:26.075178 43244 } Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:26.095338 43244 { Imb::EvHtp::TimeoutSweeper::sweep |
[/img] |
|
| Back to top |
|
 |
| liamf |
| Posted: Tue Feb 06, 2024 12:40 am Post subject: |
|
|
Novice
Joined: 22 Apr 2021
Posts: 13
|
We are using a CURL script to do a loop request, basically each request would cost 30 ~ 50ms to get a response in average. But randomlly some request cost 5000ms to get a response. In those 5000ms, the userTrace log stop printing any log while trace log still printing.
more log details during 5000ms block
| Code: |
2024-02-05 13:15:30.781688 43244 } Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:30.799668 43170 } ImbServerSocket::accept, false
2024-02-05 13:15:30.799740 43170 { ImbBasicSocket::~ImbBasicSocket
2024-02-05 13:15:30.799750 43170 } ImbBasicSocket::~ImbBasicSocket
2024-02-05 13:15:30.799758 43170 } ImbNamedServerComms::accept
2024-02-05 13:15:30.799768 43170 { ImbNamedServerComms::accept, 5000
2024-02-05 13:15:30.799780 43170 { ImbBasicSocket::ImbBasicSocket, 'Comms layer usage'
2024-02-05 13:15:30.799788 43170 } ImbBasicSocket::ImbBasicSocket
2024-02-05 13:15:30.799798 43170 { ImbBasicSocket::setReuseAddress, true
2024-02-05 13:15:30.799808 43170 } ImbBasicSocket::setReuseAddress
2024-02-05 13:15:30.799818 43170 { ImbServerSocket::accept, 5000
2024-02-05 13:15:30.801822 43244 { Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:30.801896 43244 { ImbHandleManager::handleManager, (*ptr)0x7f888529d2f8
2024-02-05 13:15:30.801908 43244 } ImbHandleManager::handleManager
2024-02-05 13:15:30.801920 43244 } Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:30.802602 43229 } imbSleep
2024-02-05 13:15:30.802668 43229 { ImbMQHAManager::isBrokerHAQueueManagerRunning, true
2024-02-05 13:15:30.802702 43229 { ImbCPPConnectorFactory::CPPSharedConnector::CPPConnection::changeAdminObject, 'TestConnection', 0, '', ''
2024-02-05 13:15:30.802720 43229 { MQConnection::changeAdminObject, 'TestConnection', 0, '', ''
2024-02-05 13:15:30.802748 43229 { MQConnection::testConnection, 20971527, 'Connection0'
2024-02-05 13:15:30.802762 43229 { MQOPEN
2024-02-05 13:15:30.802912 43229 } MQOPEN
2024-02-05 13:15:30.802928 43229 MQConnection::testConnection, 'Opened QM ', 0, 0
2024-02-05 13:15:30.802942 43229 { MQCLOSE
2024-02-05 13:15:30.802998 43229 } MQCLOSE
2024-02-05 13:15:30.803012 43229 } MQConnection::testConnection, true
2024-02-05 13:15:30.803026 43229 } MQConnection::changeAdminObject
2024-02-05 13:15:30.803038 43229 } ImbCPPConnectorFactory::CPPSharedConnector::CPPConnection::changeAdminObject
2024-02-05 13:15:30.803052 43229 } ImbMQHAManager::isBrokerHAQueueManagerRunning, true
2024-02-05 13:15:30.803068 43229 { imbSleep, 5000
2024-02-05 13:15:30.822028 43244 { Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:30.822114 43244 { ImbHandleManager::handleManager, (*ptr)0x7f888529d2f8
2024-02-05 13:15:30.822130 43244 } ImbHandleManager::handleManager
2024-02-05 13:15:30.822140 43244 } Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:30.842254 43244 { Imb::EvHtp::TimeoutSweeper::sweep
2024-02-05 13:15:30.842336 43244 { ImbHandleManager::handleManager, (*ptr)0x7f888529d2f8
2024-02-05 13:15:30.842350 43244 } ImbHandleManager::handleManager
2024-02-05 13:15:30.842362 43244 } Imb::EvHtp::TimeoutSweeper::sweep |
Seems the broker was sleeping and tring to reach a MQConnection.
If you have any thing unclear or any questions, please, just ask.
Much appreciate! |
|
| Back to top |
|
|
| AndreasMartens |
| Posted: Wed Feb 07, 2024 3:42 am Post subject: Re: Help!Http request being blocked in a specific period |
|
|
Acolyte
Joined: 30 Jan 2006
Posts: 65
Location: Hursley, UK
|
Hello,
Very interesting problem.
Before I go digging too much in the code, the 5 seconds make me think of a close-wait or similar problem.
During the 5 second freeze, could you do a `ss -napt` to see what sockets are active, and what state they're in?
(the -n gives numerical port numbers, don't bother with looking up /etc/services, -a is to get all sockets, -p to get the pid of the process and -t to focus on TCP sockets)
I thought it might be Nagle going weird, but I'm fairly sure that's already disabled. |
|
| Back to top |
|
|
| liamf |
| Posted: Sat Feb 17, 2024 7:01 pm Post subject: Re: Help!Http request being blocked in a specific period |
|
|
Novice
Joined: 22 Apr 2021
Posts: 13
|
| AndreasMartens wrote: |
Hello,
Very interesting problem.
Before I go digging too much in the code, the 5 seconds make me think of a close-wait or similar problem.
During the 5 second freeze, could you do a `ss -napt` to see what sockets are active, and what state they're in?
(the -n gives numerical port numbers, don't bother with looking up /etc/services, -a is to get all sockets, -p to get the pid of the process and -t to focus on TCP sockets)
I thought it might be Nagle going weird, but I'm fairly sure that's already disabled. |
Hi, Andreas.
I'm using port 7080 as the http port, and after trying the ss command as what you suggested, i found that during the request freezing, there either be no established scoket or a blocked socket exist till the freezing ends.
The blocked socket below:
| Code: |
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
ESTAB 0 0 xx.xxx.xx.30:7080 xx.xxx.xx.15:33982 users:(("DataFlowEngine",pid=11112,fd=197))
|
and no established socket like below:
| Code: |
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
LISTEN 0 128 *:7080 *:* users:(("DataFlowEngine",pid=11112,fd=252))
|
|
|
| Back to top |
|
|
| AndreasMartens |
| Posted: Mon Feb 19, 2024 4:12 am Post subject: |
|
|
Acolyte
Joined: 30 Jan 2006
Posts: 65
Location: Hursley, UK
|
thanks,
did you have the `ss -napt` in a loop? I've never seen duplicated output from it before! (i.e. for each ip+pid+fd entry there should only be a single line)
In the blocked case, it doesn't look blocked from that output, an ESTABlised socket just means it's expecting communication to continue (i.e. neither end of the connection have said "I'm done").
What's "missing" essentially are any CLOSE_WAIT, TIME_WAIT or FIN_WAIT which is what I was expecting.
Soooo, to debug further what would be handy would be to:
sudo ss -lvnni <NIC> port 7080
then start hitting it with curl till it freezes, hit CTRL-C to interrupt the tcpdump and then look at the last few entries to see what's going on.
For example on my system, when I run an `ss -napt | grep 7800` I see:
| Code: |
$ss -napt | grep 7800
LISTEN 0 100 0.0.0.0:7800 0.0.0.0:* users:(("IntegrationServ",pid=1147533,fd=177))
TIME-WAIT 0 0 x.x.x.x:7800 y.y.y.y:56235
TIME-WAIT 0 0 x.x.x.x:7800 y.y.y.y:56236
|
(I'm using an standalone integration server, rather than node-owned, but we should see the same behaviour)
So I have two sockets in TIME-WAIT from aborted browsing sessions to my server (browser tried to use https and failed) which will get cleaned up shortly.
In another run, I get:
| Code: |
LISTEN 0 100 0.0.0.0:7800 0.0.0.0:* users:(("IntegrationServ",pid=1147533,fd=177))
TIME-WAIT 0 0 x.x.x.x:7800 y.y.y.y:56317
ESTAB 0 0 x.x.x.x:7800 y.y.y.y:56318 users:(("IntegrationServ",pid=1147533,fd=209))
TIME-WAIT 0 0 x.x.x.x:7800 y.y.y.y:56316
|
In this case my browser has opened three sockets against my server (yes, browsers over http will often spam sockets), two of them are in TIME_WAIT and one is ESTABlished. When I close the browser tab all three get cleaned up.
And running tcpdump I can see that the two TIME_WAIT sockets have received FIN packets that have been ACKnowledged, and when I close the browser tab I see the final socket being FINished and ACKnowledged:
| Code: |
11:59:59.811210 IP (tos 0x0, ttl 58, id 43675, offset 0, flags [none], proto TCP (6), length 40)
y.y.y.y.56318 > x.x.x.x.7800: Flags [.], cksum 0x27fd (correct), ack 12356, win 2048, length 0
11:59:59.811256 IP (tos 0x0, ttl 64, id 33414, offset 0, flags [DF], proto TCP (6), length 52)
x.x.x.x.7800 > y.y.y.y.56318: Flags [.], cksum 0x36ea (incorrect -> 0xe298), ack 463, win 506, options [nop,nop,TS val 3134006591 ecr 1626657104], length 0
12:00:03.821669 IP (tos 0x0, ttl 58, id 0, offset 0, flags [DF], proto TCP (6), length 52)
y.y.y.y.56318 > x.x.x.x.7800: Flags [F.], cksum 0x6d0c (correct), seq 463, ack 12356, win 2048, options [nop,nop,TS val 1626751188 ecr 3134006591], length 0
12:00:03.822763 IP (tos 0x0, ttl 64, id 33415, offset 0, flags [DF], proto TCP (6), length 52)
x.x.x.x.7800 > y.y.y.y.56318: Flags [F.], cksum 0x36ea (incorrect -> 0x6365), seq 12356, ack 464, win 506, options [nop,nop,TS val 3134010603 ecr 1626751188], length 0
12:00:03.823344 IP (tos 0x0, ttl 58, id 0, offset 0, flags [DF], proto TCP (6), length 52)
y.y.y.y.56318 > x.x.x.x.7800: Flags [.], cksum 0x5d5d (correct), ack 12357, win 2048, options [nop,nop,TS val 1626751190 ecr 3134010603], length 0
|
after which my ss -napt output only has the single LISTEN socket again.
So, in short:
1. Please say your ss -napt was in a loop, as having duplicate LISTENs points to something very strange
2. Does tcpdump point a finger as to what's happening?
I'll run this past the rest of the team to see if they have any ideas.
cheers,
Andreas |
|
| Back to top |
|
|
| AndreasMartens |
| Posted: Mon Feb 19, 2024 5:46 am Post subject: DNS? |
|
|
Acolyte
Joined: 30 Jan 2006
Posts: 65
Location: Hursley, UK
|
A colleague has suggested DNS (which is far too often the culprit)...
Is your curl using IP addresses to DNS names?
could we have the output of
| Code: |
| mqsireportproperties <NODE> -e <default> -o HTTPConnector -r |
please? Specifically I want to see if EnableLookups is enabled |
|
| Back to top |
|
|
| liamf |
| Posted: Tue Feb 20, 2024 2:51 am Post subject: |
|
|
Novice
Joined: 22 Apr 2021
Posts: 13
|
Hi, Andreas
After checking my curl script, i found some of the freezing was caused by writing log to ouput file, though this is not the only reason that cause the freezing but still give some misleading information, sorry about that.
| AndreasMartens wrote: |
1. Please say your ss -napt was in a loop, as having duplicate LISTENs points to something very strange
|
Yes, i did put the ss -napt in a loop to keep monitoring the socket state of port 7080.
| Quote: |
What's "missing" essentially are any CLOSE_WAIT, TIME_WAIT or FIN_WAIT which is what I was expecting.
|
For port 7080, i didn't find any socket that's CLOSE_WAIT,TIME_WAIT or FIN_WAIT, but some sockets can be observed from local 1414 port to a random port as TIME-WAIT, which i think is normal?:
| Code: |
TIME-WAIT 0 0 127.0.0.1:42694 127.0.0.1:1414
|
| Quote: |
| 2. Does tcpdump point a finger as to what's happening? |
Yes, tcpdump shows a gap between request and response:
| Code: |
15:45:00.061295 IP xx.xxx.xx.15.38444 > localhost.localdomain.empowerid: Flags [S], seq 1830337799, win 29200, options [mss 1460,sackOK,TS val 3600735089 ecr 0,nop,wscale 7], length 0
15:45:00.061316 IP localhost.localdomain.empowerid > xx.xxx.xx.15.38444: Flags [S.], seq 590945778, ack 1830337800, win 28960, options [mss 1460,sackOK,TS val 2850186990 ecr 3600735089,nop,wscale 7], length 0
15:45:00.061488 IP xx.xxx.xx.15.38444 > localhost.localdomain.empowerid: Flags [.], ack 1, win 229, options [nop,nop,TS val 3600735089 ecr 2850186990], length 0
15:45:00.061560 IP xx.xxx.xx.15.38444 > localhost.localdomain.empowerid: Flags [P.], seq 1:86, ack 1, win 229, options [nop,nop,TS val 3600735090 ecr 2850186990], length 85
15:45:00.061565 IP localhost.localdomain.empowerid > xx.xxx.xx.15.38444: Flags [.], ack 86, win 227, options [nop,nop,TS val 2850186990 ecr 3600735090], length 0
15:45:03.802467 IP localhost.localdomain.empowerid > xx.xxx.xx.15.38444: Flags [P.], seq 1:150, ack 86, win 227, options [nop,nop,TS val 2850190731 ecr 3600735090], length 149
15:45:03.802726 IP xx.xxx.xx.15.38444 > localhost.localdomain.empowerid: Flags [.], ack 150, win 237, options [nop,nop,TS val 3600738831 ecr 2850190731], length 0
15:45:03.803769 IP xx.xxx.xx.15.38444 > localhost.localdomain.empowerid: Flags [F.], seq 86, ack 150, win 237, options [nop,nop,TS val 3600738832 ecr 2850190731], length 0
15:45:03.803995 IP localhost.localdomain.empowerid > xx.xxx.xx.15.38444: Flags [F.], seq 150, ack 87, win 227, options [nop,nop,TS val 2850190733 ecr 3600738832], length 0
15:45:03.804135 IP xx.xxx.xx.15.38444 > localhost.localdomain.empowerid: Flags [.], ack 151, win 237, options [nop,nop,TS val 3600738832 ecr 2850190733], length 0 |
Apparently, there is an interval for about 3 seconds between server ack request and server proceed a response.
| Quote: |
| Is your curl using IP addresses to DNS names? |
We are using IP Address only, and HTTPConnector properties:
| Code: |
HTTPConnector
name='HTTPConnector'
type='Policy'
AutoRespondToHTTPHEADRequests='false'
CORSAllowCredentials='false'
CORSAllowHeaders='Accept,Accept-Language,Content-Language,Content-Type'
CORSAllowMethods='GET,HEAD,POST,PUT,PATCH,DELETE,OPTIONS'
CORSAllowOrigins='*'
CORSEnabled='false'
CORSExposeHeaders='Content-Type'
CORSMaxAge='-1'
ConnBacklog='1000'
ContentSecurityPolicy=''
EnableLookups='false'
IWATimeout='300'
IntegratedWindowsAuthentication=''
ListenerAddress='0.0.0.0'
ListenerPort='7080'
ListenerThreads='-1'
MaxConnections='-1'
MaxKeepAliveRequests='-1'
MaxPostSize='-1'
QueueCapacity='5000'
QueueWait='5000'
ServerName=''
TimeoutSweepInterval='1000'
XContentTypeOptions=''
XSSProtection=''
active
ListenerPort='7080'
serverRestartRequired='false'
detailed
connectors
Embedded
discardedRequests='0'
port='7080'
secure='false'
urlRegistrations
urlRegistration
outstandingRequests='0'
outstandingTimeoutRequests='0'
url='/test'
usedByHTTPNodes='true'
usedBySOAPNodes='false'
nodes
node
flowLabel='TEST_Messageflow'
nodeLabel='HTTP Input'
urlRegistration
outstandingRequests='0'
url='/xxx/xxx/x'
usedByHTTPNodes='true'
usedBySOAPNodes='false'
nodes
node
flowLabel='com.xxx.xxx.xxxxx.xxx.x.xTEST'
nodeLabel='HTTP Input'
|
Attach with the curl script:
| Code: |
URL="http://xx.xxx.xx.xx:7080/test"
while true
do
{ time curl -o /dev/null -s -w "Total time: %{time_total} seconds\n" $URL; }
done
|
Best regards,
Liam |
|
| Back to top |
|
|
| AndreasMartens |
| Posted: Tue Feb 20, 2024 5:17 am Post subject: |
|
|
Acolyte
Joined: 30 Jan 2006
Posts: 65
Location: Hursley, UK
|
Well that's a telling 3.8 seconds! It's pointing the finger of blame firmly in our direction!
The full service trace might tell us something, those sweep threads should be entirely separate from the worker threads, so *should* be a red herring, we'd need to see what the other threads are up to.
You could also try capturing the Listener Log:
| Code: |
mqsichangeproperties HTTP_ECHO? -e default -o ComIbmInternalSupportManager/Parms/HTTPConnectorManager -n ListenerLogging -v true
|
which would write to
| Code: |
$MQSI_WORKPATH/common/stats/HTTP_ECHO_default_httpListenerStats.txt
|
I think we're nearing the point where a PMR is the right choice! |
|
| Back to top |
|
|
| Muggy |
| Posted: Sun Feb 25, 2024 9:09 pm Post subject: |
|
|
Newbie
Joined: 11 Aug 2012
Posts: 4
|
Not any help I'm sure, but back end of 2021, IIB 10.0.0.17 (on Windows), we had an issue where after an amount of time, like 36 hours and millions of requests, a SOAPRequest would then consistently return results at around the 5 second mark.
A scheduled restart of the execution group was the solution at the time to restore operation as it was months away from decommissioning. Monitoring of the SOAP endpoint (outside of broker) was showing response times of < 50ms, but response from the broker was much slower, very similar to the figures here.
The flow was an MQ to SOAP call in our instance. Two cases I think were raised, but at the time someone looked at what fixpacks provided and fitted their argument to a particular APAR, when none of that seemed to apply. I was never able to reproduce though. |
|
| 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
|
|
|
|
