[omniORB] TCP configuration?

[Martin Kocian]

Hi Duncan,

> What does omniORB think is happening at this time?  Can you get a trace
> from both client and server with these options:

Here is the output with the additional options turned on. Tcpdump is 
running on the receiving Linux box so the time stamps between tcpdump and
the omniorb output on that machine are consistent.

Sender (rce12):

omniORB: (3) 1988-01-01 00:00:14.910000: Invoke 'update' on remote: root/is/replica<0>
omniORB: (3) 1988-01-01 00:00:14.910000: sendChunk: to giop:tcp:172.21.6.45:44449 212 bytes
omniORB: (3) 1988-01-01 00:00:14.910000: sendCopyChunk: to giop:tcp:172.21.6.45:44449 249620 bytes
omniORB: (3) 1988-01-01 00:00:14.960000: sendChunk: to giop:tcp:172.21.6.45:44449 100 bytes
omniORB: (3) 1988-01-01 00:00:14.960000: inputMessage: from giop:tcp:172.21.6.45:44449 24 bytes

Receiver (rdcds105):

omniORB: (4) 2011-08-08 15:20:34.809634: AsyncInvoker: thread id = 4 has started. Total threads = 3
omniORB: (4) 2011-08-08 15:20:34.809682: giopWorker task execute.
omniORB: (4) 2011-08-08 15:20:34.809718: inputMessage: from giop:tcp:[::ffff:172.21.6.24]:1027 212 bytes
omniORB: (4) 2011-08-08 15:20:34.850187: inputMessage: (body) from giop:tcp:[::ffff:172.21.6.24]:1027 1448 bytes
omniORB: (4) 2011-08-08 15:20:34.850232: inputMessage: (body) from giop:tcp:[::ffff:172.21.6.24]:1027 1448 bytes
omniORB: (4) 2011-08-08 15:20:34.850420: inputMessage: (body) from giop:tcp:[::ffff:172.21.6.24]:1027 2896 bytes
omniORB: (4) 2011-08-08 15:20:34.850457: inputMessage: (body) from giop:tcp:[::ffff:172.21.6.24]:1027 1448 bytes
omniORB: (4) 2011-08-08 15:20:34.850515: inputMessage: (body) from giop:tcp:[::ffff:172.21.6.24]:1027 740 bytes
omniORB: (4) 2011-08-08 15:20:34.850560: Dispatching remote call 'update' to: root/is/replica<0> (active)
omniORB: (4) 2011-08-08 15:20:34.850645: inputCopyChunk: from giop:tcp:[::ffff:172.21.6.24]:1027 241640 bytes
omniORB: (4) 2011-08-08 15:20:34.864043: inputMessage: from giop:tcp:[::ffff:172.21.6.24]:1027 100 bytes
omniORB: (4) 2011-08-08 15:20:34.865406: sendChunk: to giop:tcp:[::ffff:172.21.6.24]:1027 24 bytes


tcpdump:

15:20:34.809553 IP rce12.lab1.reg.1027 > rdcds105.lab1.reg.44449: P 399:611(212) ack 73 win 17376 <nop,nop,timestamp 27 3545665898>
15:20:34.849970 IP rdcds105.lab1.reg.44449 > rce12.lab1.reg.1027: . ack 611 win 62 <nop,nop,timestamp 3545676958 27>
15:20:34.850137 IP rce12.lab1.reg.1027 > rdcds105.lab1.reg.44449: . 611:2059(1448) ack 73 win 17376 <nop,nop,timestamp 27 3545676958>
15:20:34.850164 IP rdcds105.lab1.reg.44449 > rce12.lab1.reg.1027: . ack 2059 win 85 <nop,nop,timestamp 3545676958 27>
15:20:34.850191 IP rce12.lab1.reg.1027 > rdcds105.lab1.reg.44449: . 2059:3507(1448) ack 73 win 17376 <nop,nop,timestamp 27 3545676958>
15:20:34.850198 IP rdcds105.lab1.reg.44449 > rce12.lab1.reg.1027: . ack 3507 win 108 <nop,nop,timestamp 3545676959 27>

...

15:20:34.864015 IP rce12.lab1.reg.1027 > rdcds105.lab1.reg.44449: P 250231:250327(96) ack 73 win 17376 <nop,nop,timestamp 27 3545676972>
15:20:34.864021 IP rce12.lab1.reg.1027 > rdcds105.lab1.reg.44449: P 250327:250331(4) ack 73 win 17376 <nop,nop,timestamp 27 3545676972>
15:20:34.864027 IP rdcds105.lab1.reg.44449 > rce12.lab1.reg.1027: . ack 250327 win 505 <nop,nop,timestamp 3545676972 27>
15:20:34.864032 IP rdcds105.lab1.reg.44449 > rce12.lab1.reg.1027: . ack 250331 win 505 <nop,nop,timestamp 3545676972 27>
15:20:34.865436 IP rdcds105.lab1.reg.44449 > rce12.lab1.reg.1027: P 73:97(24) ack 250331 win 505 <nop,nop,timestamp 3545676974 27>
15:20:34.867110 IP rce12.lab1.reg.1027 > rdcds105.lab1.reg.44449: P 250331:251079(748) ack 97 win 17376 <nop,nop,timestamp 27 3545676974>


Thanks a lot,

Martin


On Fri, 5 Aug 2011, Duncan Grisby wrote:

> On Wed, 2011-07-20 at 10:20 -0700, Martin Kocian wrote:
>
>> I am experiencing delays in the TCP communication in omniorb 4.1.4 where
>> 212 bytes get sent to a Linux box (kernel 2.6.18-92.el5) immediately
>> followed by about 200 kB. The problem is that the Linux box does not send
>> the ack for the 212 bytes until 40 ms later(see time in the second line):
>
> What does omniORB think is happening at this time?  Can you get a trace
> from both client and server with these options:
>
> -ORBtraceLevel 25 -ORBtraceInvocations 1 -ORBtraceTime 1
> -ORBtraceThreadId 1
>
> And get another tcpdump. Then we can correlate them all.
>
> Cheers,
>
> Duncan.
>
> -- 
> -- Duncan Grisby         --
>  -- duncan at grisby.org     --
>   -- http://www.grisby.org --
>
>

| Martin Kocian                                       |
| kocian at slac.stanford.edu                            |
| Stanford Linear Accelerator Center                  |
| M.S. 95, P.O. Box 20450                             |
| Stanford, CA 94309                                  |
| Tel. (650)926-2887  Fax (650)926-2923               |