Periodic huge slowdown on large file read, always to same speed with 2x oscillation

bonox · August 28, 2024, 11:56pm

Hi All

I have a curiosity only about a periodic slowdown on large file reads that i’m wondering if anyone else has come across.

The pool is half full and consists of 16TB exos x16 drives in four 7 drive z2 vdevs and will happily ingest or read 800MB/s+ for an hour at a time, but about once an hour, on a large file read (tens of GB) will drop speed to a crawl.

And it’s always the same (network) speed - 5.54MB/s that will oscillate up to 11.1MB/s and back down for a few minutes, then it’ll pick up again back to normal speeds. The factor of two is interesting and this behaviour is quite repeatable.

The CX3 10Gb NIC is cool, as is the HBA and the drives are all about 33 Celsius with no pool errors and no single drive obvious bottleneck visible from solnet runs.

Any thoughts please?

DL380 Gen 8, 2x 2697v2
384GB ECC
9201-16E
Mlx CX-3
KTN-STL3 shelves
28x 16TB x16 Exos
8x 16TB HC550
76x 6TB ES.5
Core 13u6.1

NickF1227 · August 29, 2024, 12:59am

This sounds like a TCP windowing thing maybe. What’s your MTU?

bonox · August 29, 2024, 1:35am

I get the same issue with 1500 though. There’s no switch on this NAS - it’s direct connect to a workstation with the same MTU as the NAS. It does sound very much like a network issue rather than a pool/disk one though doesn’t it!

NickF1227 · August 29, 2024, 2:57am

Can you paste the output of ifconfig and netstat -p protocol -s

bonox · August 29, 2024, 4:11am

root@truenas[~]# netstat -p protocol -s
netstat: protocol: unknown or uninstrumented protocol
root@truenas[~]# ifconfig
bge0: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=c019b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,TSO4,VLAN_HWTSO,LINKSTATE>
        ether 28:80:23:9e:f9
        media: Ethernet autoselect
        nd6 options=9<PERFORMNUD,IFDISABLED>
bge1: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=c019b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,TSO4,VLAN_HWTSO,LINKSTATE>
        ether 28:80:23:9e:f9
        media: Ethernet autoselect (none)
        status: no carrier
        nd6 options=9<PERFORMNUD,IFDISABLED>
bge2: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=c019b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,TSO4,VLAN_HWTSO,LINKSTATE>
        ether 28:80:23:9e:f9
        media: Ethernet autoselect
        nd6 options=9<PERFORMNUD,IFDISABLED>
bge3: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=c019b<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,VLAN_HWCSUM,TSO4,VLAN_HWTSO,LINKSTATE>
        ether 28:80:23:9e:f9
        media: Ethernet autoselect
        nd6 options=9<PERFORMNUD,IFDISABLED>
lo0: flags=8049<UP,LOOPBACK,RUNNING,MULTICAST> metric 0 mtu 16384
        options=680003<RXCSUM,TXCSUM,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        inet6 ::1 prefixlen 128
        inet6 fe80::1%lo0 prefixlen 64 scopeid 0x5
        inet 127.0.0.1 netmask 0xff000000
        groups: lo
        nd6 options=21<PERFORMNUD,AUTO_LINKLOCAL>
pflog0: flags=0<> metric 0 mtu 33160
        groups: pflog
mlxen0: flags=8843<UP,BROADCAST,RUNNING,SIMPLEX,MULTICAST> metric 0 mtu 1500
        description: mlxen0
        options=ed07bb<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,TSO4,TSO6,LRO,VLAN_HWFILTER,VLAN_HWTSO,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        ether 00:02:c9:ec
        inet 192.168.0.50 netmask 0xffffff00 broadcast 192.168.0.255
        media: Ethernet autoselect (10Gbase-CX4 <full-duplex,rxpause,txpause>)
        status: active
        nd6 options=9<PERFORMNUD,IFDISABLED>
mlxen1: flags=8802<BROADCAST,SIMPLEX,MULTICAST> metric 0 mtu 1500
        options=ed07bb<RXCSUM,TXCSUM,VLAN_MTU,VLAN_HWTAGGING,JUMBO_MTU,VLAN_HWCSUM,TSO4,TSO6,LRO,VLAN_HWFILTER,VLAN_HWTSO,LINKSTATE,RXCSUM_IPV6,TXCSUM_IPV6>
        ether 00:02:c9:ec:c9:01
        media: Ethernet autoselect
        status: no carrier
        nd6 options=9<PERFORMNUD,IFDISABLED>
root@truenas[~]#


root@truenas[~]# netstat -p TCP -s
tcp:
        16988070 packets sent
                15216405 data packets (324153123433 bytes)
                18 data packets (2674 bytes) retransmitted
                0 data packets unnecessarily retransmitted
                0 resends initiated by MTU discovery
                1771285 ack-only packets (1268 delayed)
                0 URG only packets
                0 window probe packets
                285 window update packets
                77 control packets
        19047640 packets received
                19051506 acks (for 324153008550 bytes)
                988 duplicate acks
                0 UDP tunneled pkts
                0 UDP tunneled pkt cnt with errors
                0 acks for unsent data
                40448233 packets (59943982973 bytes) received in-sequence
                992 completely duplicate packets (19617846 bytes)
                0 old duplicate packets
                28 packets with some dup. data (649254 bytes duped)
                3818 out-of-order packets (129656314 bytes)
                0 packets (0 bytes) of data after window
                0 window probes
                0 window update packets
                1 packet received after close
                0 discarded for bad checksums
                0 discarded for bad header offset fields
                0 discarded because packet too short
                0 discarded due to full reassembly queue
        20 connection requests
        42 connection accepts
        0 bad connection attempts
        0 listen queue overflows
        0 ignored RSTs in the windows
        62 connections established (including accepts)
                52 times used RTT from hostcache
                52 times used RTT variance from hostcache
                0 times used slow-start threshold from hostcache
        73 connections closed (including 0 drops)
                57 connections updated cached RTT on close
                57 connections updated cached RTT variance on close
                0 connections updated cached ssthresh on close
        0 embryonic connections dropped
        1676537 segments updated rtt (of 1676531 attempts)
        0 retransmit timeouts
                0 connections dropped by rexmit timeout
        0 persist timeouts
                0 connections dropped by persist timeout
        0 Connections (fin_wait_2) dropped because of timeout
        0 keepalive timeouts
                0 keepalive probes sent
                0 connections dropped by keepalive
        16448956 correct ACK header predictions
        2151838 correct data packet header predictions
        42 syncache entries added
                0 retransmitted
                0 dupsyn
                0 dropped
                42 completed
                0 bucket overflow
                0 cache overflow
                0 reset
                0 stale
                0 aborted
                0 badack
                0 unreach
                0 zone failures
        42 cookies sent
        0 cookies received
        2 hostcache entries added
                0 bucket overflow
        0 SACK recovery episodes
        0 segment rexmits in SACK recovery episodes
        0 byte rexmits in SACK recovery episodes
        18 SACK options (SACK blocks) received
        4850 SACK options (SACK blocks) sent
        0 SACK scoreboard overflow
        0 packets with ECN CE bit set
        0 packets with ECN ECT(0) bit set
        0 packets with ECN ECT(1) bit set
        0 successful ECN handshakes
        0 times ECN reduced the congestion window
        0 packets with matching signature received
        0 packets with bad signature received
        0 times failed to make signature due to no SA
        0 times unexpected signature received
        0 times no signature provided by segment
        0 Path MTU discovery black hole detection activations
        0 Path MTU discovery black hole detection min MSS activations
        0 Path MTU discovery black hole detection failures
        0 times connection in TIME-WAIT responded with ACK
        0 times connection in TIME-WAIT was actively recycled
        0 times connection in TIME-WAIT responded with RST
TCP connection count by state:
        0 connections in CLOSED state
        20 connections in LISTEN state
        0 connections in SYN_SENT state
        0 connections in SYN_RCVD state
        5 connections in ESTABLISHED state
        0 connections in CLOSE_WAIT state
        0 connections in FIN_WAIT_1 state
        0 connections in CLOSING state
        0 connections in LAST_ACK state
        0 connections in FIN_WAIT_2 state
        4 connections in TIME_WAIT state
root@truenas[~]#

NickF1227 · August 29, 2024, 4:26am

Hmmm

Everything looks normal since your last reboot. The counters for things like duplicate packets/acks, retransmissions are all good, window update packets at 285 are low, nothins dropped.

What does ARC look like in the GUI when it drops? Is this over SMB?

bonox · August 29, 2024, 4:50am

Yes, only SMB. I’ll need a peak at the ARC reporting sometime later but in general ARC doesn’t get hit much if at all for the files in question. They’re read infrequently enough that they’re never captured and the total throughput far exceeds the ARC capacity so they’d be flushed quickly anyway.

bonox · August 30, 2024, 9:23pm

there’s a slow down a third of the way into these. At the same point iostat shows pool activity falling to basically nothing - a total that adds up to the 5.54MB/s.

Not sure this is a network problem any more as it happens via SMB on a server side copy as well as external traffic.