Tell me more ×
Unix & Linux Stack Exchange is a question and answer site for users of Linux, FreeBSD and other Un*x-like operating systems.. It's 100% free, no registration required.
up vote 2 down vote favorite
1

In our REHL server, latency between application send and tcpdump log is always very large for large messages, about 200 milliseconds (see below 697572-488690=208882 microseconds), whereas latency for small messages is very small, just a few microseconds.

I think none of the TCP timers can explain the 200ms delay. This kind of latency is usually because of the Nagle's algorithm for small messages, which is not the case here since the high latency is only for large messages.

With a large message:

IBM MQ trace logs extracts:

12:13:12.488685     4172.1      RSESS:000001 ----{  ccxSend
12:13:12.488688     4172.1      RSESS:000001 -----{  cciTcpSend
12:13:12.488690     4172.1      RSESS:000001 ------{  send
12:13:12.488697     4172.1      RSESS:000001 ------}  send rc=OK
12:13:12.488711     4172.1      RSESS:000001      Sending 1138 bytes
[large message]
12:13:12.488714     4172.1      RSESS:000001      RetCode (OK)
12:13:12.488716     4172.1      RSESS:000001 -----}  cciTcpSend rc=OK

tcpdump extracts:

12:13:05.884715 IP (tos 0x0, ttl  49, id 60415, offset 0, flags [DF], proto: TCP (6), length: 68) otherHost.otherPort > ourHost.ourPort: P, cksum 0x7673 (correct), 2893948259:2893948287(28) ack 1576932354 win 1024                           ....
12:13:05.884718 IP (tos 0x0, ttl  64, id 60352, offset 0, flags [DF], proto: TCP (6), length: 40) ourHost.ourPort > otherHost.otherPort: ., cksum 0xcd9c (correct), ack 2893948287 win 5768
12:13:12.697572 IP (tos 0x0, ttl  64, id 60353, offset 0, flags [DF], proto: TCP (6), length: 1064) ourHost.ourPort > otherHost.otherPort: P, cksum 0x0059 (incorrect (-> 0x6a5a), 1576932354:1576933378(1024) ack 2893948287 win 5768
[first packet of large message]
12:13:12.708367 IP (tos 0x0, ttl  49, id 61060, offset 0, flags [DF], proto: TCP (6), length: 40) otherHost.otherPort > ourHost.ourPort: ., cksum 0xe024 (correct), ack 1576933378 win 0
12:13:12.708865 IP (tos 0x0, ttl  49, id 61061, offset 0, flags [DF], proto: TCP (6), length: 40) otherHost.otherPort > ourHost.ourPort: ., cksum 0xdc24 (correct), ack 1576933378 win 1024
12:13:12.708869 IP (tos 0x0, ttl  64, id 60354, offset 0, flags [DF], proto: TCP (6), length: 154) ourHost.ourPort > otherHost.otherPort: P, cksum 0xfcca (incorrect (-> 0xa1fb), 1576933378:1576933492(114) ack 2893948287 win 5768
[second packet of large message]
12:13:12.716154 IP (tos 0x0, ttl  49, id 61062, offset 0, flags [DF], proto: TCP (6), length: 40) otherHost.otherPort > ourHost.ourPort: ., cksum 0xdc24 (correct), ack 1576933492 win 910
12:13:12.717202 IP (tos 0x0, ttl  49, id 61063, offset 0, flags [DF], proto: TCP (6), length: 68) otherHost.otherPort > ourHost.ourPort: P, cksum 0x71e5 (correct), 2893948287:2893948315(28) ack 1576933492 win 1024
12:13:12.717209 IP (tos 0x0, ttl  64, id 60355, offset 0, flags [DF], proto: TCP (6), length: 40) ourHost.ourPort > otherHost.otherPort: ., cksum 0xc90e (correct), ack 2893948315 win 5768

With a small message (less context in extracts):

15:15:33.133940     4215.1      RSESS:000001 ------{ send               
15:15:33.133954     4215.1      RSESS:000001 ------}  send rc=OK
...
15:15:33.133966     4215.1      RSESS:000001      Sending 512 bytes
[small message]
15:15:33.133969     4215.1      RSESS:000001      RetCode (OK)

tcpdump:

15:15:33.133949 IP (tos 0x0, ttl  64, id 37357, offset 0, flags [DF], proto: TCP (6), length: 552) ourHost.ourPort > otherHost.otherPort: P, cksum 0xfe58 (incorrect (-> 0x2dd8), 1566021015:1566021527(512) ack 2491002247 win 5768
[small message]

System and drivers versions:

Linux 2.6.18-128.el5 #1 SMP Wed Dec 17 11:41:38 EST 2008 x86_64 x86_64 x86_64 GNU/Linux

Red Hat Enterprise Linux Server release 5.3 (Tikanga)

# /usr/sbin/ethtool -i bond0
driver: bonding
version: 3.2.4
firmware-version: 2

$ cat /proc/net/bonding/bond0
Ethernet Channel Bonding Driver: v3.2.4 (January 28, 2008)
Bonding Mode: fault-tolerance (active-backup)
Currently Active Slave: eth2

# /usr/sbin/ethtool -i eth2
driver: e1000e
version: 1.2.10-NAPI
firmware-version: 5.12-2

Next steps?

Without finding the root cause for this issue, I am thinking of:

  • just trying to upgrade bonding or e1000e drivers. By the way, in order to check if any bonding bug could be involved, does anybody know where the bonding driver versions and release notes are?
  • asking the other side to set a bigger TCP window since there is no issue when only one packet has to be sent for a message. In addition, that would decrease latency by 10 milliseconds, the time between first and second packet for a large message.

Does anybody has any other idea? Is there any way to get trace logs for bonding or e1000e drivers?

share|improve this question

1 Answer

up vote 1 down vote

You're passing too few bytes in each call to send or write. You need to try to pass at least 2KB per call, or better, 4KB per call. If possible, accumulate the entire logical message and send it at once. This will save system calls, pack your packets more efficiently, and prevent delayed ACK from destroying your latency.

share|improve this answer
The 1138 bytes or 512 bytes in MQ trace are the full logical messages and are sent at once according to this same MQ trace. Anyway I don't understand how bigger messages could fix the latency issue since latency for small messages is fine. Where do you see a delayed ACK in tcpdump above? I don't see any. Your explanation doesn't seem to fit the tcpdump & MQ trace we get. – pba Feb 9 '12 at 23:21
1  
It fits the tcpdump perfectly. You have a pattern of 40-byte packets followed immediately by larger packets in the same direction. Something is causing those packets not to be consolidated. – David Schwartz Feb 9 '12 at 23:26
If you refer to the 40-byte packet at 12:13:05.884718, which is in fact just a TCP header for ACK, it is much earlier than the next large packet at 12:13:12.697572. So why should they be consolidated? – pba Feb 10 '12 at 0:01
@pba Look at the 12.708367 packet and the 12.708865 packet. Look at the 12.716154 packet and the 12.717202 packet. – David Schwartz Feb 10 '12 at 0:12
As written in this question, I am aware that a TCP window larger than 1024 on the other side would shave about 10 milliseconds from latency. This question is about the 200ms latency between 12.488690 MQ send and 12.697572 TCP packet. Can the TCP behavior after 12.69757 explain this? The 200ms latency is always reproducible for large messages (e.g. 1138 bytes) and never reproducible for small messages (e.g. 512 bytes), both on test and production servers, and for months. – pba Feb 10 '12 at 1:40
show 2 more comments

Your Answer

 
discard

By posting your answer, you agree to the privacy policy and terms of service.

Not the answer you're looking for? Browse other questions tagged or ask your own question.