Date: Wed, 22 Jan 2014 23:12:54 -0500 (EST) From: Rick Macklem <rmacklem@uoguelph.ca> To: J David <j.david.lists@gmail.com> Cc: freebsd-net@freebsd.org Subject: Re: Terrible NFS performance under 9.2-RELEASE? Message-ID: <1891524918.14888294.1390450374695.JavaMail.root@uoguelph.ca> In-Reply-To: <CABXB=RQ2ck=kc7AH9GLcmVuKyTAfiDbSZ9N6XQ4A%2Bw-q9NqSmA@mail.gmail.com>
next in thread | previous in thread | raw e-mail | index | archive | help
J David wrote:
> On Mon, Jan 20, 2014 at 8:27 PM, Rick Macklem <rmacklem@uoguelph.ca>
> wrote:
> >> random random
> >> write rewrite read reread read write
> >>
> >> S:FBSD,C:FBSD,Z:64k
> >> 67246 2923 103295 1272407 172475 196
> >>
> >> S:FBSD,C:FBSD,Z:32k
> >> 11951 99896 223787 1051948 223276 13686
>
> > Since I've never used the benchmark you're using, I'll admit I have
> > no idea what these numbers mean? (Are big values fast or slow
> > or???)
>
> These numbers are kiB/sec read or written. Larger is better.
>
So, do you consider the 32K results as reasonable or terrible performance?
(They are obviously much better than 64K, except for the reread case.)
> > I'd be looking at a packet trace in wireshark and looking for TCP
> > retransmits
> > and delays between packets. However, any significant improvement
> > (like 50% or
> > more faster for a smaller I/O size) indicates that something is
> > broken in the
> > network (in your case virtual) fabric, imho.
>
> If Debian were also affected in the same environment, I would tend to
> agree. As it is not, the problem seems to be pretty squarely on
> FreeBSD's shoulders, rather than the environment.
>
I didn't mean to imply it had nothing to do with FreeBSD. When I said
"network fabric", I meant that to include everything below the TCP socket
that the NFS krpc code uses for RPC transport. (ie. Including FreeBSD's
TCP stack and the device driver for the virtual network interface you
are using.)
Btw, I don't think you've mentioned what network device driver gets used
for this virtual environment. That might be useful, in case the maintainer
of that driver is aware of some issue/patch.
> > (You saw that the smaller I/O
> > size results in more RPCs, so that would suggest slower, not
> > faster.
>
> It's not clear to me what this refers to. More RPCs would only
> indicate slower for the same throughput level, right?
>
> I.e. nominally you would expect to see twice as many RPCs for 32k as
> for 64k. But if 32k is transferring 200x faster than 64k, the net
> effect would be 100x more RPCs, right?
>
> The packet traces for the 64k size are pretty interesting. On the
> sequential write test, the client packets start out very small, and
> slowly scale up to just under 64k, then they abruptly fall to 1500
> bytes and sit there for a good long while:
>
> 00:32:42.156107 IP (tos 0x0, ttl 64, id 5352, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.255894 IP (tos 0x0, ttl 64, id 46951, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0xa59c), seq 15072, ack 5909085, win 29127, options
> [nop,nop,TS val 3447942732 ecr 316758762], length 0
>
I don't know why tcpdump keeps flagging these as having incorrect
checksums? Maybe someone else has an answer for this.
> 00:32:42.256078 IP (tos 0x0, ttl 64, id 5353, offset 0, flags [DF],
> proto TCP (6), length 5844)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.355958 IP (tos 0x0, ttl 64, id 46953, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0x8e34), seq 15072, ack 5914877, win 29127, options
> [nop,nop,TS val 3447942832 ecr 316758862], length 0
>
> 00:32:42.356152 IP (tos 0x0, ttl 64, id 5354, offset 0, flags [DF],
> proto TCP (6), length 8740)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.455891 IP (tos 0x0, ttl 64, id 46954, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0x6b7c), seq 15072, ack 5923565, win 29127, options
> [nop,nop,TS val 3447942932 ecr 316758962], length 0
>
> 00:32:42.456036 IP (tos 0x0, ttl 64, id 5355, offset 0, flags [DF],
> proto TCP (6), length 11636)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.456185 IP (tos 0x0, ttl 64, id 46955, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728916: reply ok 160
>
> 00:32:42.456370 IP (tos 0x0, ttl 64, id 5356, offset 0, flags [DF],
> proto TCP (6), length 14532)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.555949 IP (tos 0x0, ttl 64, id 46957, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0x0440), seq 15236, ack 5949629, win 29127, options
> [nop,nop,TS val 3447943032 ecr 316759062], length 0
>
> 00:32:42.556139 IP (tos 0x0, ttl 64, id 5357, offset 0, flags [DF],
> proto TCP (6), length 17428)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.655929 IP (tos 0x0, ttl 64, id 46958, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0xbf97), seq 15236, ack 5967005, win 29127, options
> [nop,nop,TS val 3447943132 ecr 316759162], length 0
>
> 00:32:42.656142 IP (tos 0x0, ttl 64, id 5358, offset 0, flags [DF],
> proto TCP (6), length 20324)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.755893 IP (tos 0x0, ttl 64, id 46959, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0x6f9f), seq 15236, ack 5987277, win 29127, options
> [nop,nop,TS val 3447943232 ecr 316759262], length 0
>
> 00:32:42.756085 IP (tos 0x0, ttl 64, id 5359, offset 0, flags [DF],
> proto TCP (6), length 23220)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.756198 IP (tos 0x0, ttl 64, id 46960, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728917: reply ok 160
>
> 00:32:42.756394 IP (tos 0x0, ttl 64, id 5360, offset 0, flags [DF],
> proto TCP (6), length 26116)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.855956 IP (tos 0x0, ttl 64, id 46961, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0xade2), seq 15400, ack 6036509, win 29127, options
> [nop,nop,TS val 3447943332 ecr 316759362], length 0
>
> 00:32:42.856162 IP (tos 0x0, ttl 64, id 5361, offset 0, flags [DF],
> proto TCP (6), length 29012)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.856310 IP (tos 0x0, ttl 64, id 46962, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728918: reply ok 160
>
> 00:32:42.856469 IP (tos 0x0, ttl 64, id 5362, offset 0, flags [DF],
> proto TCP (6), length 31908)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.955895 IP (tos 0x0, ttl 64, id 47036, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0xbee5), seq 15564, ack 6097325, win 29127, options
> [nop,nop,TS val 3447943432 ecr 316759462], length 0
>
> 00:32:42.956089 IP (tos 0x0, ttl 64, id 5363, offset 0, flags [DF],
> proto TCP (6), length 34804)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:42.956199 IP (tos 0x0, ttl 64, id 47037, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728919: reply ok 160
>
> 00:32:42.956404 IP (tos 0x0, ttl 64, id 5364, offset 0, flags [DF],
> proto TCP (6), length 37700)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.055906 IP (tos 0x0, ttl 64, id 47038, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0xa2a8), seq 15728, ack 6169725, win 29127, options
> [nop,nop,TS val 3447943532 ecr 316759562], length 0
>
> 00:32:43.056068 IP (tos 0x0, ttl 64, id 5365, offset 0, flags [DF],
> proto TCP (6), length 40596)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.056221 IP (tos 0x0, ttl 64, id 47040, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728921: reply ok 160
>
> 00:32:43.056400 IP (tos 0x0, ttl 64, id 5366, offset 0, flags [DF],
> proto TCP (6), length 43492)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.155935 IP (tos 0x0, ttl 64, id 47044, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0x592b), seq 15892, ack 6253709, win 29127, options
> [nop,nop,TS val 3447943632 ecr 316759662], length 0
>
> 00:32:43.156133 IP (tos 0x0, ttl 64, id 5368, offset 0, flags [DF],
> proto TCP (6), length 46388)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.156273 IP (tos 0x0, ttl 64, id 47045, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728933: reply ok 160
>
> 00:32:43.156481 IP (tos 0x0, ttl 64, id 5369, offset 0, flags [DF],
> proto TCP (6), length 49284)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.156632 IP (tos 0x0, ttl 64, id 47046, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728934: reply ok 160
>
> 00:32:43.156835 IP (tos 0x0, ttl 64, id 5370, offset 0, flags [DF],
> proto TCP (6), length 52180)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.156953 IP (tos 0x0, ttl 64, id 47047, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728937: reply ok 160
>
> 00:32:43.157144 IP (tos 0x0, ttl 64, id 5371, offset 0, flags [DF],
> proto TCP (6), length 55076)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.157285 IP (tos 0x0, ttl 64, id 47048, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728938: reply ok 160
>
> 00:32:43.157459 IP (tos 0x0, ttl 64, id 5372, offset 0, flags [DF],
> proto TCP (6), length 57972)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.255927 IP (tos 0x0, ttl 64, id 47049, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x819a
> (incorrect -> 0x5baf), seq 16548, ack 6514349, win 29127, options
> [nop,nop,TS val 3447943732 ecr 316759762], length 0
>
> 00:32:43.256132 IP (tos 0x0, ttl 64, id 5373, offset 0, flags [DF],
> proto TCP (6), length 60868)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.256251 IP (tos 0x0, ttl 64, id 47050, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728939: reply ok 160
>
> 00:32:43.485942 IP (tos 0x0, ttl 64, id 47056, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874728939: reply ok 160
>
> 00:32:43.486099 IP (tos 0x0, ttl 64, id 5376, offset 0, flags [DF],
> proto TCP (6), length 1500)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.486117 IP (tos 0x0, ttl 64, id 47057, offset 0, flags [DF],
> proto TCP (6), length 64)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x81a6
> (incorrect -> 0xbaf5), seq 16712, ack 6575165, win 29127, options
> [nop,nop,TS val 3447943962 ecr 316759862,nop,nop,sack 1
> {6638877:6640325}], length 0
>
> 00:32:43.486271 IP (tos 0x0, ttl 64, id 5377, offset 0, flags [DF],
> proto TCP (6), length 1500)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.486288 IP (tos 0x0, ttl 64, id 47058, offset 0, flags [DF],
> proto TCP (6), length 64)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x81a6
> (incorrect -> 0xb54d), seq 16712, ack 6575165, win 29127, options
> [nop,nop,TS val 3447943962 ecr 316759862,nop,nop,sack 1
> {6638877:6641773}], length 0
>
> 00:32:43.486440 IP (tos 0x0, ttl 64, id 5378, offset 0, flags [DF],
> proto TCP (6), length 1500)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.486470 IP (tos 0x0, ttl 64, id 47059, offset 0, flags [DF],
> proto TCP (6), length 64)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x81a6
> (incorrect -> 0xaec2), seq 16712, ack 6576613, win 29124, options
> [nop,nop,TS val 3447943962 ecr 316760092,nop,nop,sack 1
> {6638877:6641773}], length 0
>
> 00:32:43.486622 IP (tos 0x0, ttl 64, id 5379, offset 0, flags [DF],
> proto TCP (6), length 1500)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:32:43.486652 IP (tos 0x0, ttl 64, id 47060, offset 0, flags [DF],
> proto TCP (6), length 64)
>
> 172.20.20.162.2049 > 172.20.20.169.689: Flags [.], cksum 0x81a6
> (incorrect -> 0xa91a), seq 16712, ack 6578061, win 29124, options
> [nop,nop,TS val 3447943962 ecr 316760092,nop,nop,sack 1
> {6638877:6641773}], length 0
>
>
> After ahile, it tries again. Wash, rinse, repeat.
>
Hopefully someone who is conversant with TCP and tcpdump can make sense
of this. I suggested wireshark because it recognizes the NFS requests,
flags retransmits etc, so I find it much easier to understand.
I normally use tcpdump to capture the packets into a file:
# tcpdump -s 0 -w <file>.pcap host <client or server>
- then I read this file into wireshark. A raw capture like the above
usually keeps up and doesn't miss much.
> With the 32k size, they scale up to between 50000 and 59000 bytes per
> packet and sit there for long periods of time, seeming to reset only
> after some other intervening RPC activity:
>
> 00:38:07.932518 IP (tos 0x0, ttl 64, id 38911, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.932530 IP (tos 0x0, ttl 64, id 22486, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686965: reply ok 160
>
> 00:38:07.932622 IP (tos 0x0, ttl 64, id 22487, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686941: reply ok 160
>
> 00:38:07.932732 IP (tos 0x0, ttl 64, id 38912, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
I don't know why this would be so large. A 32K write should be under
33Kbytes in size, not 53Kbytes. I suspect tcpdump is confused?
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.932747 IP (tos 0x0, ttl 64, id 22488, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686968: reply ok 160
>
> 00:38:07.932857 IP (tos 0x0, ttl 64, id 22489, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686967: reply ok 160
>
> 00:38:07.932963 IP (tos 0x0, ttl 64, id 38913, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.933060 IP (tos 0x0, ttl 64, id 22490, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686946: reply ok 160
>
> 00:38:07.933120 IP (tos 0x0, ttl 64, id 22491, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686971: reply ok 160
>
> 00:38:07.933176 IP (tos 0x0, ttl 64, id 38914, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.933270 IP (tos 0x0, ttl 64, id 22492, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686970: reply ok 160
>
> 00:38:07.933329 IP (tos 0x0, ttl 64, id 22493, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686972: reply ok 160
>
> 00:38:07.933386 IP (tos 0x0, ttl 64, id 38915, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.933483 IP (tos 0x0, ttl 64, id 22494, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686974: reply ok 160
>
> 00:38:07.933602 IP (tos 0x0, ttl 64, id 38916, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.933689 IP (tos 0x0, ttl 64, id 22495, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686973: reply ok 160
>
> 00:38:07.933754 IP (tos 0x0, ttl 64, id 22496, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686975: reply ok 160
>
> 00:38:07.933820 IP (tos 0x0, ttl 64, id 38917, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.933892 IP (tos 0x0, ttl 64, id 22497, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686976: reply ok 160
>
> 00:38:07.934017 IP (tos 0x0, ttl 64, id 38918, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.934112 IP (tos 0x0, ttl 64, id 22498, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686977: reply ok 160
>
> 00:38:07.934202 IP (tos 0x0, ttl 64, id 22499, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686978: reply ok 160
>
> 00:38:07.934234 IP (tos 0x0, ttl 64, id 38919, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.934312 IP (tos 0x0, ttl 64, id 22500, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686942: reply ok 160
>
> 00:38:07.934400 IP (tos 0x0, ttl 64, id 22501, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686979: reply ok 160
>
> 00:38:07.934426 IP (tos 0x0, ttl 64, id 38920, offset 0, flags [DF],
> proto TCP (6), length 53628)
>
> 172.20.20.169.0 > 172.20.20.162.2049: 0 null
>
> 00:38:07.934520 IP (tos 0x0, ttl 64, id 22502, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.169.1874686980: reply ok 160
>
>
> It does seem weird that the client seems to double up the 216 replies
> all the time, but the throughput is still very good.
>
> With Debian as the client, it's so fast tcpdump can't keep up, but
> this is what it does see:
>
> 00:43:10.310980 IP (tos 0x0, ttl 64, id 30448, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2036438470 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824033280 <filesync>
>
Btw, here the Debian NFS client is writing 4096 bytes, so it is nowhere
near 64K. It appears to be writing single pages at this point.
Notice that, for the above FreeBSD traces, it never figures out that
there is an NFS write. Wireshark is much better at NFS related stuff,
from my limited experience.
> 00:43:10.311002 IP (tos 0x0, ttl 64, id 30450, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.311013 IP (tos 0x0, ttl 64, id 52178, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x376f), seq 38376, ack 988417, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651075], length 0
>
> 00:43:10.311266 IP (tos 0x0, ttl 64, id 52179, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2036438470: reply ok 160 write
> PRE: sz 824033280 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824037376 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.311356 IP (tos 0x0, ttl 64, id 30451, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2053215686 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824037376 <filesync>
>
> 00:43:10.311378 IP (tos 0x0, ttl 64, id 30453, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.311389 IP (tos 0x0, ttl 64, id 52180, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x264b), seq 38540, ack 992641, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651075], length 0
>
> 00:43:10.311648 IP (tos 0x0, ttl 64, id 52181, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2053215686: reply ok 160 write
> PRE: sz 824037376 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824041472 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.311734 IP (tos 0x0, ttl 64, id 30454, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2069992902 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824041472 <filesync>
>
> 00:43:10.311756 IP (tos 0x0, ttl 64, id 30456, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.311767 IP (tos 0x0, ttl 64, id 52182, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x1527), seq 38704, ack 996865, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651075], length 0
>
> 00:43:10.312021 IP (tos 0x0, ttl 64, id 52183, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2069992902: reply ok 160 write
> PRE: sz 824041472 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824045568 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.312107 IP (tos 0x0, ttl 64, id 30457, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2086770118 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824045568 <filesync>
>
> 00:43:10.312129 IP (tos 0x0, ttl 64, id 30459, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.312140 IP (tos 0x0, ttl 64, id 52184, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x0403), seq 38868, ack 1001089, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651075], length 0
>
> 00:43:10.312393 IP (tos 0x0, ttl 64, id 52185, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2086770118: reply ok 160 write
> PRE: sz 824045568 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824049664 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.312485 IP (tos 0x0, ttl 64, id 30460, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2103547334 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824049664 <filesync>
>
> 00:43:10.312507 IP (tos 0x0, ttl 64, id 30462, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.312517 IP (tos 0x0, ttl 64, id 52186, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0xf2de), seq 39032, ack 1005313, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651075], length 0
>
> 00:43:10.312775 IP (tos 0x0, ttl 64, id 52187, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2103547334: reply ok 160 write
> PRE: sz 824049664 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824053760 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.312861 IP (tos 0x0, ttl 64, id 30463, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2120324550 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824053760 <filesync>
>
> 00:43:10.312882 IP (tos 0x0, ttl 64, id 30465, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.312893 IP (tos 0x0, ttl 64, id 52188, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0xe1b3), seq 39196, ack 1009537, win 29124, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.313148 IP (tos 0x0, ttl 64, id 52189, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2120324550: reply ok 160 write
> PRE: sz 824053760 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824057856 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.313233 IP (tos 0x0, ttl 64, id 30466, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2137101766 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824057856 <filesync>
>
> 00:43:10.313259 IP (tos 0x0, ttl 64, id 30468, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.313280 IP (tos 0x0, ttl 64, id 52190, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0xd08f), seq 39360, ack 1013761, win 29124, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.313536 IP (tos 0x0, ttl 64, id 52191, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2137101766: reply ok 160 write
> PRE: sz 824057856 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824061952 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.313628 IP (tos 0x0, ttl 64, id 30469, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2153878982 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824061952 <filesync>
>
> 00:43:10.313650 IP (tos 0x0, ttl 64, id 30471, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.313661 IP (tos 0x0, ttl 64, id 52192, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0xbf71), seq 39524, ack 1017985, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.313915 IP (tos 0x0, ttl 64, id 52193, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2153878982: reply ok 160 write
> PRE: sz 824061952 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824066048 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.314000 IP (tos 0x0, ttl 64, id 30472, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2170656198 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824066048 <filesync>
>
> 00:43:10.314022 IP (tos 0x0, ttl 64, id 30474, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.314032 IP (tos 0x0, ttl 64, id 52194, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0xae4d), seq 39688, ack 1022209, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.314286 IP (tos 0x0, ttl 64, id 52195, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2170656198: reply ok 160 write
> PRE: sz 824066048 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824070144 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.314373 IP (tos 0x0, ttl 64, id 30475, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2187433414 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824070144 <filesync>
>
> 00:43:10.314395 IP (tos 0x0, ttl 64, id 30477, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.314406 IP (tos 0x0, ttl 64, id 52196, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x9d29), seq 39852, ack 1026433, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.314665 IP (tos 0x0, ttl 64, id 52197, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2187433414: reply ok 160 write
> PRE: sz 824070144 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824074240 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.314751 IP (tos 0x0, ttl 64, id 30478, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2204210630 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824074240 <filesync>
>
> 00:43:10.314772 IP (tos 0x0, ttl 64, id 30480, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.314783 IP (tos 0x0, ttl 64, id 52198, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x8c05), seq 40016, ack 1030657, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.315036 IP (tos 0x0, ttl 64, id 52199, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2204210630: reply ok 160 write
> PRE: sz 824074240 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824078336 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.315122 IP (tos 0x0, ttl 64, id 30481, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2220987846 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824078336 <filesync>
>
> 00:43:10.315144 IP (tos 0x0, ttl 64, id 30483, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.315154 IP (tos 0x0, ttl 64, id 52200, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x7ae1), seq 40180, ack 1034881, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.315407 IP (tos 0x0, ttl 64, id 52201, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2220987846: reply ok 160 write
> PRE: sz 824078336 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824082432 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.315510 IP (tos 0x0, ttl 64, id 30484, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2237765062 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824082432 <filesync>
>
> 00:43:10.315532 IP (tos 0x0, ttl 64, id 30486, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.315543 IP (tos 0x0, ttl 64, id 52202, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x69bd), seq 40344, ack 1039105, win 29118, options
> [nop,nop,TS val 3637794932 ecr 78651076], length 0
>
> 00:43:10.315781 IP (tos 0x0, ttl 64, id 52203, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2237765062: reply ok 160 write
> PRE: sz 824082432 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824086528 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.315904 IP (tos 0x0, ttl 64, id 30487, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2254542278 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824086528 <filesync>
>
> 00:43:10.315927 IP (tos 0x0, ttl 64, id 30489, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.315937 IP (tos 0x0, ttl 64, id 52204, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x5889), seq 40508, ack 1043329, win 29124, options
> [nop,nop,TS val 3637794942 ecr 78651076], length 0
>
> 00:43:10.316191 IP (tos 0x0, ttl 64, id 52205, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2254542278: reply ok 160 write
> PRE: sz 824086528 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824090624 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
> 00:43:10.316274 IP (tos 0x0, ttl 64, id 30490, offset 0, flags [DF],
> proto TCP (6), length 2948)
>
> 172.20.20.166.2271319494 > 172.20.20.162.2049: 2892 write fh
> 1325,752613/4 4096 (4096) bytes @ 824090624 <filesync>
>
> 00:43:10.316296 IP (tos 0x0, ttl 64, id 30492, offset 0, flags [DF],
> proto TCP (6), length 1380)
>
> 172.20.20.166.0 > 172.20.20.162.2049: 0 null
>
> 00:43:10.316307 IP (tos 0x0, ttl 64, id 52206, offset 0, flags [DF],
> proto TCP (6), length 52)
>
> 172.20.20.162.2049 > 172.20.20.166.997: Flags [.], cksum 0x8197
> (incorrect -> 0x476b), seq 40672, ack 1047553, win 29118, options
> [nop,nop,TS val 3637794942 ecr 78651076], length 0
>
> 00:43:10.316552 IP (tos 0x0, ttl 64, id 52207, offset 0, flags [DF],
> proto TCP (6), length 216)
>
> 172.20.20.162.2049 > 172.20.20.166.2271319494: reply ok 160 write
> PRE: sz 824090624 mtime 1390437790.000000 ctime 1390437790.000000
> POST: REG 640 ids 0/0 sz 824094720 nlink 1 rdev 3/130 fsid 59 fileid
> 4
> a/m/ctime 1390437723.000000 1390437790.000000 1390437790.000000 4096
> bytes <filesync>
>
Well, it seems Debian is doing 4096 byte writes, which won't have anywhere
near the effect on the network driver/virtual hardware that a 64K (about
45 IP datagrams) in one NFS RPC will.
>
> This seems quite different.
>
> But the 1500 byte fallback with the FreeBSD 64k case seems like the
> smoking gun.
>
Yea, looking at this case in wireshark might make what is going on
apparent. At least it would build up the actual 64K writes and would
flag retransmits, etc. (It also lists timestamps, so you can scan
down the screen and see where there are large time delays.)
Have fun with it, rick
> So far I have not been able to test whether the 1500 bytes case
> correlates to the 10 pps case, but I will attempt to do so.
>
> Thanks!
> _______________________________________________
> freebsd-net@freebsd.org mailing list
> http://lists.freebsd.org/mailman/listinfo/freebsd-net
> To unsubscribe, send any mail to
> "freebsd-net-unsubscribe@freebsd.org"
>
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?1891524918.14888294.1390450374695.JavaMail.root>