Sometimes long reply time for proxy generation

[HpGisler]

Hello,

I am encountering a (for me) hard to track timing problem, when creating a proxy on the server-side. Actually, I'am not sure at all, that the problem has to do with ICE; but anyway, perhaps anybody has observed a similar thing...

When the client (WinXP, .net/C#) requests a proxy from the server (WinCE,C++), sometimes the task is handled blazingly fast and at other times, it takes about 2 seconds to finish. I have analyzed the network traffic to find out what happens in these situations.

The ice protocol-log shows in both situations the exact same behaviour:
Here the relevant part for creating 2 proxies and casting them to the destination type:

-------------------------------------------------------------------

[ Protocol: sending request

message type = 0 (request)

compression status = 0 (not compressed; do not compress response, if any)

message size = 74

request id = 1

identity = 3853E3DF-53F3-4BD3-9AC1-FA0E320B8852

facet =

operation = ice_ping

mode = 1 (nonmutating)

context = ]


[ Network: sent 74 of 74 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 14 of 14 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 11 of 11 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Protocol: received reply

message type = 2 (reply)

compression status = 0 (not compressed; do not compress response, if any)

message size = 25

request id = 1

reply status = 0 (ok) ]


[ Protocol: sending request

message type = 0 (request)

compression status = 0 (not compressed; do not compress response, if any)

message size = 73

request id = 2

identity = 3853E3DF-53F3-4BD3-9AC1-FA0E320B8852

facet =

operation = Create

mode = 0 (normal)

context = ]


[ Network: sent 73 of 73 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 14 of 14 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 84 of 84 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Protocol: received reply

message type = 2 (reply)

compression status = 0 (not compressed; do not compress response, if any)

message size = 98

request id = 2

reply status = 0 (ok) ]


[ Protocol: sending request

message type = 0 (request)

compression status = 0 (not compressed; do not compress response, if any)

message size = 113

request id = 3

identity = 77D62462-E617-43C8-9FCB-1A69C01CE30D

facet =

operation = ice_isA

mode = 1 (nonmutating)

context = ]


[ Network: sent 113 of 113 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 14 of 14 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 12 of 12 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Protocol: received reply

message type = 2 (reply)

compression status = 0 (not compressed; do not compress response, if any)

message size = 26

request id = 3

reply status = 0 (ok) ]


[ Protocol: sending request

message type = 0 (request)

compression status = 0 (not compressed; do not compress response, if any)

message size = 74

request id = 4

identity = 3853E3DF-53F3-4BD3-9AC1-FA0E320B8852

facet =

operation = ice_ping

mode = 1 (nonmutating)

context = ]


[ Network: sent 74 of 74 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 14 of 14 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 11 of 11 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Protocol: received reply

message type = 2 (reply)

compression status = 0 (not compressed; do not compress response, if any)

message size = 25

request id = 4

reply status = 0 (ok) ]


[ Protocol: sending request

message type = 0 (request)

compression status = 0 (not compressed; do not compress response, if any)

message size = 73

request id = 5

identity = 3853E3DF-53F3-4BD3-9AC1-FA0E320B8852

facet =

operation = Create

mode = 0 (normal)

context = ]


[ Network: sent 73 of 73 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 14 of 14 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 84 of 84 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Protocol: received reply

message type = 2 (reply)

compression status = 0 (not compressed; do not compress response, if any)

message size = 98

request id = 5

reply status = 0 (ok) ]


[ Protocol: sending request

message type = 0 (request)

compression status = 0 (not compressed; do not compress response, if any)

message size = 113

request id = 6

identity = 6CD47EBA-3A62-4B5B-88BA-218C2C691235

facet =

operation = ice_isA

mode = 1 (nonmutating)

context = ]


[ Network: sent 113 of 113 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 14 of 14 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Network: received 12 of 12 bytes via tcp

local address = 192.168.0.209:3326

remote address = 192.168.0.120:10000 ]


[ Protocol: received reply

message type = 2 (reply)

compression status = 0 (not compressed; do not compress response, if any)

message size = 26

request id = 6

reply status = 0 (ok) ]


-------------------------------------------------------------------


For me, this looks ok.

But on the TCP level, things look as shown in the attached word document.
Perhaps somebody has any ideas?

I really do not see the problem causing this...

Any help is greatly appreciated, thanks.
hp.

[benoit]

Hi,

You should use a lower tracing level for Ice.Trace.Network (Ice.Trace.Network=2 for example) and enable timestamps with Ice.Logger.Timestamp=1. This would help to see where the delays occur with the Ice tracing.

In any case, I can't see anything wrong with your TCP network tracing. The delays appear to occur between succesfull Ice requests (after receiving the reply of the second request and before sending the third request and after receiving the reply of the 5th request and before sending the 6th request) so it would indicate that the delays occur in your code.

Cheers,
Benoit.

[HpGisler]

Hi,

First of all: Thanks very much for your quick reply. I appreciate your help very much.

Following, I've included the same log-situation as before, this time with Trace level 2 and time stamping enabled.

What strikes me here is, that between the reception of the packet on the Client side at time:
[ 04/16/2007 17:01:37 Protocol: received reply
....

and the sending of the next request:
[ 04/16/2007 17:01:39 Protocol: sending request
...

I see this "magic" delay.

Nothing special happens on the client side code. (ice handles this).
So in my understanding, it's not the server that waits 2 secs, but the client...
(if I interpret this correctly).

In the attached word document, I've pasted the TCP-Flow diagram of this exact same time period.

And what strikes me here is, that at time 17:01:37 and time 17:01:39, two packets are being sent from client to server; where in between those two, the waiting occurs.

Here, I do not really understand what's happening and I do not know whether this has to do with ICE or not.

Any way, this (for me) strange behavior does not seem to occur for other network protocols, e.g. FTP or the such...

Perhaps you see some possible causes for this?

Kind Regards
hp.


--------------------------------------------------------------------

[ 04/16/2007 17:01:37 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 74
request id = 21
identity = 9A13AB68-874D-4875-910C-C08A7AB8E084
facet =
operation = ice_ping
mode = 1 (nonmutating)
context = ]

[ 04/16/2007 17:01:37 Protocol: received reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 25
request id = 21
reply status = 0 (ok) ]

[ 04/16/2007 17:01:37 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 73
request id = 22
identity = 9A13AB68-874D-4875-910C-C08A7AB8E084
facet =
operation = Create
mode = 0 (normal)
context = ]

[ 04/16/2007 17:01:37 Protocol: received reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 98
request id = 22
reply status = 0 (ok) ]

[ 04/16/2007 17:01:39 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 113
request id = 23
identity = 10E08A3B-3F78-4AA7-8F84-575F8146E5A0
facet =
operation = ice_isA
mode = 1 (nonmutating)
context = ]

[ 04/16/2007 17:01:39 Protocol: received reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 26
request id = 23
reply status = 0 (ok) ]

[ 04/16/2007 17:01:39 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 74
request id = 24
identity = 9A13AB68-874D-4875-910C-C08A7AB8E084
facet =
operation = ice_ping
mode = 1 (nonmutating)
context = ]

[ 04/16/2007 17:01:39 Protocol: received reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 25
request id = 24
reply status = 0 (ok) ]

[ 04/16/2007 17:01:39 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 73
request id = 25
identity = 9A13AB68-874D-4875-910C-C08A7AB8E084
facet =
operation = Create
mode = 0 (normal)
context = ]

[ 04/16/2007 17:01:39 Protocol: received reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 98
request id = 25
reply status = 0 (ok) ]

[ 04/16/2007 17:01:41 Protocol: sending request
message type = 0 (request)
compression status = 0 (not compressed; do not compress response, if any)
message size = 113
request id = 26
identity = 6E1928A6-1A35-45C1-8AFE-523562241FC6
facet =
operation = ice_isA
mode = 1 (nonmutating)
context = ]

[ 04/16/2007 17:01:41 Protocol: received reply
message type = 2 (reply)
compression status = 0 (not compressed; do not compress response, if any)
message size = 26
request id = 26
reply status = 0 (ok) ]

[bernard]

The best would be to reduce your program to a simple test case, ideally just a Ice 3.2.0 C# client talking to an Ice 3.2.0 server.

Note that in environments with garbage collection (such as Java and .NET), you can get hangs/delays when the GC runs.

Cheers,
Bernard

[HpGisler]

Hi

...well at least I've found a quick work around for the moment.
If using a second network adapter on the WinXP machine, giving this one a fixed IP, connecting it directly (via crossed-Cable) to the server machine (WinCE also with fixed IP), then I do not "seem" to get the additional waiting.

Weird...

It seems that this has to do with the fact, that other TCP-packets are beeing received/sent in between an established connection between client/server. If this happens, I get the "Delay"-Problem, if not, everything seems to be fine.

Somehow I believe, this rather has to do with my networking infrastructure and not so much with ICE.

Anyhow, thanks for your help.

Regards
hp.

[benoit]

Hi,

Yes, I believe the two packets you were mentioning are TCP acknowledgment packets. Ice doesn't directly send these, the TCP/IP stack does. I don't know why these would be causing hangs however.

Btw, are you using Ice or Ice-E on WinCE? Note that we don't officially support Ice on WinCE, if you have a commercial need for this platform, please contact us at info@zeroc.com.

Cheers,
Benoit.

[HpGisler]

Just for the record:

Now it's official, the problem has nothing to do with ICE .
It had to do with our internal net infrastructure and the working together of our DNS and our DHCP server. While lease times were activated on DHCP, they were not on DNS. Thus old DNS-Entries collided with updated DHCP entries for certain IP-Adresses. Thus the WinXP machine issued a lot of NetBIOS requests for no more existing NetNames. Thus the additional waiting in between ICE communications.

Thanks a lot guys from ZeroC staff for your help in this matter!

Regards,
hp.