[omniORB] omniORB slow transfer when clientCallTimeOutPeriod != 0

[Igor Lautar]

Hi,

This is a follow up to my previous question on invoke hang in remote call.

(omniORB 4.1.1, VS8, Windows XP x86 client and Windows 2003 AMD64 for server)

It seams we are indeed seeing hang in certain cases. Currently, we cannot
reproduce it every time, but it seams something like this triggers it:

1) invoke remote call and stop call in servant (while (1) { sleep... })
2) do some other work with same ORBs from different threads, repeat this for
few hours
3) kill server
4) client does not detect COMM_FAILURE (or some other exception) for call from
point (1)

We will continue to pinpoint why this would occur, by talking to some other
guys with omniORB experience, it seams it has something to do with surviving
interruptions in TCP or maybe even a feature to support clustered
environments.


Now, the obvious solution is to use timeouts on calls. This is fine, but it
has a nasty sideeffect: transfer is slow as hell (20x decrease in 1 Gbit
network).

This is excerpt from omniORB debugs:
without timeout:

[00852 2009/08/11 09:54:38.374] D 2 omniORB: Invoke 'Send' on remote:
key<cmgrServer>
[00852 2009/08/11 09:54:38.374] D 2 omniORB: sendChunk: to
giop:tcp:10.41.4.49:23244 68 bytes
[00852 2009/08/11 09:54:38.374] D 2 omniORB:
[00852 2009/08/11 09:54:38.374] D 2 4749 4f50 0102 0300 3400 0400 d402 0000
GIOP....4.......
[00852 2009/08/11 09:54:38.374] D 2 0300 0000 0000 0000 0a00 0000 636d 6772
............cmgr
[00852 2009/08/11 09:54:38.374] D 2 5365 7276 6572 0000 0500 0000 5365 6e64
Server......Send
[00852 2009/08/11 09:54:38.374] D 2 0000 7400 0000 0000 0000 0000 8823 814a
..t..........#.J
[00852 2009/08/11 09:54:38.374] D 2 0000 0400
....
[00852 2009/08/11 09:54:38.374] D 2 omniORB: sendCopyChunk: to
giop:tcp:10.41.4.49:23244 262140 bytes
[00852 2009/08/11 09:54:38.374] D 2 omniORB: 128 bytes out of 262140
[00852 2009/08/11 09:54:38.374] D 2 afaf afaf afaf afaf 0000 0000 0000 0001
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0004 0000 0000 0000 0000 0000
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0000 0000 f5f5 f5f5 f5f5 f5f5
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0000 0002 0000 0000 0003 ffd8
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0000 0000 0000 0000 0000 0000
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0000 0001 0000 0000 0000 0002
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0000 0000 0000 0000 0000 0000
................
[00852 2009/08/11 09:54:38.374] D 2 0000 0000 0000 0000 2829 1bba 0c8f ec0b
........()......
[00852 2009/08/11 09:54:38.384] D 2 omniORB: sendChunk: to
giop:tcp:10.41.4.49:23244 20 bytes
[00852 2009/08/11 09:54:38.384] D 2 omniORB:
[00852 2009/08/11 09:54:38.384] D 2 4749 4f50 0102 0107 0800 0000 d402 0000
GIOP............
[00852 2009/08/11 09:54:38.384] D 2 0000 0000
....
[00852 2009/08/11 09:54:38.394] D 2 omniORB: inputMessage: from
giop:tcp:10.41.4.49:23244 24 bytes
[00852 2009/08/11 09:54:38.394] D 2 omniORB:
[00852 2009/08/11 09:54:38.394] D 2 4749 4f50 0102 0101 0c00 0000 d402 0000
GIOP............
[00852 2009/08/11 09:54:38.394] D 2 0000 0000 0000 0000
........


with timeout:

[00176 2009/08/11 09:53:33.268] D 2 omniORB: Invoke 'Send' on remote:
key<cmgrServer>
[00176 2009/08/11 09:53:33.268] D 2 omniORB: sendChunk: to
giop:tcp:10.41.4.49:23244 68 bytes
[00176 2009/08/11 09:53:33.268] D 2 omniORB:
[00176 2009/08/11 09:53:33.268] D 2 4749 4f50 0102 0300 3400 0400 c601 0000
GIOP....4.......
[00176 2009/08/11 09:53:33.268] D 2 0300 0000 0000 0000 0a00 0000 636d 6772
............cmgr
[00176 2009/08/11 09:53:33.268] D 2 5365 7276 6572 0000 0500 0000 5365 6e64
Server......Send
[00176 2009/08/11 09:53:33.268] D 2 0000 7400 0000 0000 0000 0000 2623 814a
..t.........&#.J
[00176 2009/08/11 09:53:33.268] D 2 0000 0400
....
[00176 2009/08/11 09:53:33.268] D 2 omniORB: sendCopyChunk: to
giop:tcp:10.41.4.49:23244 262140 bytes
[00176 2009/08/11 09:53:33.268] D 2 omniORB: 128 bytes out of 262140
[00176 2009/08/11 09:53:33.268] D 2 afaf afaf afaf afaf 0000 0000 0000 0001
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0004 0000 0000 0000 0000 0000
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0000 0000 f5f5 f5f5 f5f5 f5f5
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0000 0002 0000 0000 0003 ffd8
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0000 0000 0000 0000 0000 0000
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0000 0001 0000 0000 0000 0002
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0000 0000 0000 0000 0000 0000
................
[00176 2009/08/11 09:53:33.268] D 2 0000 0000 0000 0000 2829 1bba 0c8f ec0b
........()......
[00176 2009/08/11 09:53:33.278] D 2 omniORB: sendChunk: to
giop:tcp:10.41.4.49:23244 20 bytes
[00176 2009/08/11 09:53:33.278] D 2 omniORB:
[00176 2009/08/11 09:53:33.278] D 2 4749 4f50 0102 0107 0800 0000 c601 0000
GIOP............
[00176 2009/08/11 09:53:33.278] D 2 0000 0000
....
[00176 2009/08/11 09:53:33.469] D 2 omniORB: inputMessage: from
giop:tcp:10.41.4.49:23244 24 bytes
[00176 2009/08/11 09:53:33.469] D 2 omniORB:
[00176 2009/08/11 09:53:33.469] D 2 4749 4f50 0102 0101 0c00 0000 c601 0000
GIOP............
[00176 2009/08/11 09:53:33.469] D 2 0000 0000 0000 0000
........



Notice the difference between time taken to do sendChunk (size 20) and
inputMessage (size 24).
In case where there is no timeout set, time is 10 milliseconds, and where
there is a timeout, time is 191 milliseconds.
Now, I plan to dive into it to figure out where this is coming from. I'm
wondering if you have any ideas to try next (maybe some config option I'm not
aware of?), or maybe just pointer where should I start looking in code to
speed things up.

Thank you for comments/suggestions.
Igor

[Sampo Ahokas]

Hi,

I know this doesn't help much, but just to let you know I can confirm we
have seen something very similar. Client connections sometimes just hang
like you described.

I looked into a hung process with debugger, and from what I recall it
seemed like a call to recv() just did not return, although the server
process was suddenly terminated either by a crash or call to exit().
However recv() not returning would suggest a problem in winsock, which
we found hard to believe and just thought that the call stack was not
fully correct, being optimized code.

All in all, we didn't spend all that much time debugging this problem,
as it occured only every few days of nonstop running during our internal
test and the rare times we caught it, we couldn't really get anywhere
with the debugger. This was with omniORB 4.1.3, client and server both
running on localhost. OS was most likely Vista64 Ultimate, but I cannot
be completely sure now. The application is built for 32bit architecture
with vs2008 and omniORB is linked statically.

Best regards,
Sampo

Post by Igor Lautar
Hi,
It seams we are indeed seeing hang in certain cases. Currently, we cannot
1) invoke remote call and stop call in servant (while (1) { sleep... })
2) do some other work with same ORBs from different threads, repeat this for
few hours
3) kill server
4) client does not detect COMM_FAILURE (or some other exception) for call from
point (1)
We will continue to pinpoint why this would occur, by talking to some other
guys with omniORB experience, it seams it has something to do with surviving
interruptions in TCP or maybe even a feature to support clustered
environments.

[Igor Lautar]

Hi,

Post by Sampo Ahokas
Hi,
I know this doesn't help much, but just to let you know I can confirm we
have seen something very similar. Client connections sometimes just hang
like you described.

<cut>

Have you been investigating other solution (workarounds), like before
mentioned timeout for outgoing calls?

Regards,

[Sampo Ahokas]

Hi,

Post by Igor Lautar

Post by Sampo Ahokas
Hi,
I know this doesn't help much, but just to let you know I can confirm we
have seen something very similar. Client connections sometimes just hang
like you described.

<cut>
Have you been investigating other solution (workarounds), like before
mentioned timeout for outgoing calls?

We thought about the timeout, but it's not really applicable to us.
There's just no way of knowing how long the call takes.

In our case this problem seemed to only occur when the server died or
had to be terminated unexpectedly and thus the we decided to put the
effort simply into making the server as robust as possible.

Best regards,
Sampo

[Igor Lautar]

Hi,

Post by Sampo Ahokas
We thought about the timeout, but it's not really applicable to us.
There's just no way of knowing how long the call takes.
In our case this problem seemed to only occur when the server died or
had to be terminated unexpectedly and thus the we decided to put the
effort simply into making the server as robust as possible.

Yeah, sounds like what we are experiencing.

In our case, its not a problem of server dying, but intentional restart or a
complete crash of server (power loss situation).

One thing crossed my mind now. Did you experience these hangs only on crash or
also if server was shutdown properly (ie. ORB was properly de-initialized)?

In our case, due to other reasons (speed needed, and proper de-init takes time
- do not see a point as we are shutting down anyway), we have decided to not
shutdown orb before exiting from server program. Maybe if we shutdown the ORB,
problem would not be reproduced? Have to test this, but thx for idea ;)

Regards,

[Duncan Grisby]

Post by Igor Lautar
Now, the obvious solution is to use timeouts on calls. This is fine, but it
has a nasty sideeffect: transfer is slow as hell (20x decrease in 1 Gbit
network).

[...]

Post by Igor Lautar
Notice the difference between time taken to do sendChunk (size 20) and
inputMessage (size 24).
In case where there is no timeout set, time is 10 milliseconds, and where
there is a timeout, time is 191 milliseconds.

That sounds like a bug in Windows that means nonblocking sockets impose
ridiculous delays if you do large transfers:

http://support.microsoft.com/kb/823764

In my experiments, the default transfer and socket send buffer sizes
that omniORB uses are suitable to avoid the delays, but there must be
something about your access pattern that triggers it. Your trace shows
that much of the data for the call is sent as a single large transfer
(the sendCopyChunk message), which could be the trigger.

Try modifying the values of the maxSocketSend and / or socketSendBuffer
parameters. In particular, try setting maxSocketSend to something
smaller than socketSendBuffer.

Cheers,

Duncan.

[Igor Lautar]

Hi,

Post by Duncan Grisby
That sounds like a bug in Windows that means nonblocking sockets impose
http://support.microsoft.com/kb/823764
In my experiments, the default transfer and socket send buffer sizes
that omniORB uses are suitable to avoid the delays, but there must be
something about your access pattern that triggers it. Your trace shows
that much of the data for the call is sent as a single large transfer
(the sendCopyChunk message), which could be the trigger.

Yes, we send data in chunks of 256k. Its just an arbitrary number that is easy
to work with (also processing this data on server side is faster if it is done
in larger chunks).

Post by Duncan Grisby
Try modifying the values of the maxSocketSend and / or socketSendBuffer
parameters. In particular, try setting maxSocketSend to something
smaller than socketSendBuffer.

Thats it!

I've just tested it with larger socket buffer and it works the same if timeout
is set.


I remember playing with maxSocketSend to increase transfer speed (it helped a
little bit), but have not read the comment in description of socketSendBuffer
(duh).

Anyhow, thx for omniORB and support you're providing here on list. Hopefully
somebody will find this useful (besides me).

Btw, we are able to throttle full 1 Gbit network with omniORB sending data
using 256k message sizes. Transfer in this case is around 70-80 MB/s, which is
really good, especially taking into consideration we do not have to fiddle
with raw sockets to get there.

Thx again and take care,
Igor

[Igor Lautar]

Hi,

Post by Igor Lautar
I remember playing with maxSocketSend to increase transfer speed (it helped
a little bit), but have not read the comment in description of
socketSendBuffer (duh).

Word of warning of other users of omniORB in windows...

We have not altered maxSocketSend from default. On windows, it seams to be set
to 131072 where socketSendBuffer is set to 16384, which triggers extra delay
on non-blocking sockets.

So if someone enables call timeouts, it will immediately be hit by this
windows bug.

One could do:
1) report warning to user where such combination of settings is found on
windows platforms (where non-blocking socket bug is present)
2) update clientCallTimeOutPeriod documentation to include word of caution for
windows users

Regards,

[Duncan Grisby]

Post by Igor Lautar
Word of warning of other users of omniORB in windows...
We have not altered maxSocketSend from default. On windows, it seams to be set
to 131072 where socketSendBuffer is set to 16384, which triggers extra delay
on non-blocking sockets.
So if someone enables call timeouts, it will immediately be hit by this
windows bug.

That's not completely true. The Windows bug is more subtle than that.

The slowdown only occurs if the CORBA call arguments / return values can
be transferred as a single large block, and the block size happens to
interact with the Windows TCP buffering. If the call data is either
small, or involves complex types that require marshalling, the slowdown
doesn't occur.

Cheers,

Duncan.

[Igor Lautar]

Post by Duncan Grisby
That's not completely true. The Windows bug is more subtle than that.
The slowdown only occurs if the CORBA call arguments / return values can
be transferred as a single large block, and the block size happens to
interact with the Windows TCP buffering. If the call data is either
small, or involves complex types that require marshalling, the slowdown
doesn't occur.

Thats true, I should have been more clear what triggers the bug (besides non-
blocking sockets and socket send buf size.

Regards,