Very slow SOAP response

Hello,

I have created a SOAP web service (using RemObjects SDK for Delphi - 9.0.92.1177) that is running on an IIS web server.

I’m using SOAPUI client to do my testing and when I request data of about 3MB in size the service takes about 5 minutes to actually return them back to the client!!

I have timed certain processes in the service, for example, request msg parsing, database queries etc and all these take about 4 seconds to complete. However, I’ve noticed that the ROMessageEnvelopeComplete event takes 1 minute since the request arrived to be fired up. After that it takes another 4 minutes until the response has been sent across to the client.

The server is an i7 and the CPU usage during this request is not going more than 10%. The internet link is very fast too, so no issues there.

Could you please help me out to pin point where the problem might be.

Many Thanks

I can’t reproduce this case with our MegaDemo sample.I’ve used message envelope on client and server sides
client-side log:

------------------ Test Parameters ------------------
Channel:	TROWinInetHTTPChannel
Target URL:		http://localhost:8099/soap
KeepConnection:	True
Message:	TROSOAPMessage
Encrypt:	False
-----------------------------------------------------

ROAESEncryptionEnvelope : processing outgoing message
ROAESEncryptionEnvelope : processing incoming message
EchoBinary
-------------
outgoing:	3192000 bytes
incoming:	3192000 bytes
Data is equivalent!

server-side log:

ROAESEncryptionEnvelope : processing incoming message
Request via TROSOAPMessage
Complete!
ROAESEncryptionEnvelope : processing outgoing message

this call takes 577ms

i see.

So, where do you think I should be looking for problems then. As I said the web service offers just on function that returns within 3-4 seconds so, what happens after that call and before the ROMessageEnvelopeComplete event fires up?

Are there any properties I need to double check…

Hi, could you please let me know the sequence of steps that occurring during a soap request and response handshake? Like which events are triggered first, second etc. I just need to pinpoint where the bottleneck occurs and I’m struggling massively at the moment to find.

Many thanks for you time and help.

server-side events for SOAP message:

// request part
OnBeforeProcessIncomingEnvelopes
OnAfterProcessIncomingEnvelopes
OnReadFromStream
OnBeforeParseEnvelope
OnAfterParseEnvelope

// service method execution

// response part
OnInitializeMessage
OnFinalizeMessage
OnEnvelopeComplete
OnWriteToStream
OnBeforeProcessOutgoingEnvelopes
OnAfterProcessOutgoingEnvelopes

Below I have logged the time these events take to complete. The response is a large dataset (>12000 nodes) but clearly there is a bottleneck after the service method has been executed. Any ideas why it takes 4 minutes to trigger the OnInitializeMessage event after the method execution?

// request part
OnBeforeProcessIncomingEnvelopes 09:24:56
OnAfterProcessIncomingEnvelopes  09:24:56
OnReadFromStream		 09:24:56
OnBeforeParseEnvelope            09:24:56  
OnAfterParseEnvelope		 09:24:56

// service method execution      09:25:07

// response part
OnInitializeMessage		 09:29:01		
OnFinalizeMessage		 09:29:01
OnEnvelopeComplete		 09:29:58
OnWriteToStream                  09:29:58
OnBeforeProcessOutgoingEnvelopes 09:29:58
OnAfterProcessOutgoingEnvelopes  09:29:58

Hi evgenyK, I understand that you cannot replicate the problem, but I would really appreciate it if I could get some help on how to deal with that issue please.

what parameters your service method has?

The response is a large dataset (>12000 nodes)

I can recommend to use DataAbstract for working with databases

The service has one input, which is a structure defined in the WSDL file. The output is another structure which has single elements and array elements all described in the WSDL file too. All these structures have been built with the RO service builder.

The service takes 10sec max to retrieve the data from the database and populate the structures and arrays of the output message. After that it takes 4 minutes to trigger the OnInitializeMessage! What’s happening between these two stages.

I’m totally baffled with this problem. Is there any buffer size that I need to adjust or any other property in the TROSOAPMessage or in the TROWebBrokerServer?

hmm, it can’t take 4 min for executing few lines of code.
can you set breakpoint inside OnInitializeMessage event and review callstack?
my one is

MegaDemoServerMain.TMegaDemoServerMainForm.MessageInitializeMessage($27EB1A0,???,'MegaDemoService','EchoBinaryResponse')
uROMessage.TROMessage.Initialize(TIndyHTTPTransport($2870D5C) as IROTransport,'MegaDemoService','EchoBinaryResponse',mtResponse)
uROSOAPMessage.TROSOAPMessage.Initialize(TIndyHTTPTransport($2870D5C) as IROTransport,'MegaDemoService','EchoBinaryResponse',mtResponse)
uROSOAPMessage.TROSOAPMessage.Initialize(TIndyHTTPTransport($2870D5C) as IROTransport,???,'MegaDemoService','EchoBinaryResponse',mtResponse)
uROMessage.TROMessage.InitializeResponseMessage(???,???,'MegaDemoService','EchoBinaryResponse')
MegaDemoLibrary_Invk.TMegaDemoService_Invoker.Invoke_EchoBinary(TMegaDemoService($27F2204) as IInterface,TROSOAPMessage($27EB2AC) as IROMessage,TIndyHTTPTransport($2870D5C) as IROTransport,[])

from TMegaDemoService_Invoker.Invoke_EchoBinary:

    __lintf.EchoBinary(l_BinIN, l_BinOUT);  // actual method call
    __Message.InitializeResponseMessage(__Transport, 'MegaDemoLibrary', 'MegaDemoService', 'EchoBinaryResponse'); // firing `OnInitializeMessage` inside

I’m struggling to setup the system in order to debug the service…

In the mean time maybe is worth mentioning that I have defined my own invoker in the implementation, which is derived from the one generated by the service builder and I have overwritten only the BeforeInvoke method of it. The code inside that runs instantly so no delay there either.

try to use standalone app with TROIndyHTTPServer - it will be more easily to debug in comparing with isapi dll with TROWebBrokerServer…

ok, I’ve managed to compile an app with a TROIndyHTTPServer and a TROSOAPMessage component. The app runs as expected and returns back responses but none of the TROSOAPMessage events is triggered! any ideas?

Can you check that you have one TROSOAPMessage instance and this instance has assigned events?

ok , got it thanks…that’s what I get in the call stack

Main.TForm1.ROMessageInitializeMessage($20FFA90,TIndyHTTPTransport($21502AC) as IROTransport,'GetDataInfo','GetDataInfoResponse')
uROMessage.TROMessage.Initialize(TIndyHTTPTransport($21502AC) as IROTransport,'GetDataInfo','GetDataInfoResponse',mtResponse)
uROSOAPMessage.TROSOAPMessage.Initialize(TIndyHTTPTransport($21502AC) as IROTransport,'GetDataInfo','GetDataInfoResponse',mtResponse)
uROSOAPMessage.TROSOAPMessage.Initialize(TIndyHTTPTransport($21502AC) as IROTransport,'NewLibrary','GetDataInfo','GetDataInfoResponse',mtResponse)
uROMessage.TROMessage.InitializeResponseMessage(TIndyHTTPTransport($21502AC) as IROTransport,'NewLibrary','GetDataInfo','GetDataInfoResponse')
NewLibrary_Invk.TGetSatelliteInfo_Invoker.Invoke_GetSatelliteInfo(TGetSatelliteInfo($21829E8) as IInterface,TROSOAPMessage($20FFB88) as IROMessage,TIndyHTTPTransport($21502AC) as IROTransport,[])

pls add logging and detect bottleneck

how do I add logging

you can use OutputDebugString method.
you can insert it in your and RO code for detecting problematic place.

Another piece of information that might help is that, the ROMessageEnvelopeComplete event is triggered twice when it comes to send the response!! As I said before the problem is happening when the response is a very large message. So, the ROMessageEnvelopeComplete is triggered once with not the full response messsage (also the ROMessageWriteToStream is triggered) and then after 4 minutes these events are triggered again but with the full response message this time.

It looks like there is a form buffering or fragmentation going on or some sort async response! I don’t know. BTW the client doesn’t receive the first response, only the second one, which is the complete.

Any ideas?

can you create a simple testcase, that reproduces this, pls?