Page MenuHomeFreeBSD

ena: Fix false 'missing TX completions' warnings due to timestamp race
ClosedPublic

Authored by akiyano_amazon.com on Tue, Jul 14, 9:46 PM.
Tags
None
Referenced Files
F163199735: D58241.diff
Tue, Jul 21, 12:03 AM
Unknown Object (File)
Sun, Jul 19, 4:13 PM
Unknown Object (File)
Sun, Jul 19, 9:39 AM
Unknown Object (File)
Sat, Jul 18, 6:35 PM
Unknown Object (File)
Sat, Jul 18, 3:08 AM
Unknown Object (File)
Thu, Jul 16, 7:43 PM
Unknown Object (File)
Thu, Jul 16, 5:32 PM
Unknown Object (File)
Thu, Jul 16, 5:09 PM
Subscribers

Details

Summary

Sporadic 'Found a Tx that wasn't completed on time' warnings appear
under sustained TX load, always reporting '1 msecs since last cleanup'
despite the 5-second timeout threshold.

The per-packet TX timestamp uses struct bintime (128 bits: two 64-bit
fields sec and frac) which is read and written non-atomically. A race
exists between the missing TX completion check
(check_missing_comp_in_tx_queue reading the timestamp) and the TX
submit path or cleanup path writing it on another CPU. Since the two
fields are not updated atomically, the check can observe a partially
written timestamp — one field from the old value and one from the new.
This can produce a timestamp with {sec=0, frac=valid}, causing the
check to compute a time offset equal to system uptime and falsely
exceeding the 5-second timeout.

Confirmed by instrumentation showing all occurrences had sec=0 with
valid frac/mbuf, cleanup_running=0, and ticks==last_cleanup_ticks.

Replace struct bintime with sbintime_t (a single 64-bit value) for
tx_buf->timestamp. An aligned 64-bit store/load cannot be torn on
64-bit architectures. Additionally, snapshot the timestamp into a
local variable in the check path to prevent a read-then-read race
where the timestamp could be zeroed between the zero-check and the
offset calculation.

Testing:
On m6i.large (FreeBSD 15.0-RELEASE-p6 amd64, 2 IO queues), two
instances with MTU 1500. Ran iperf -P 20 -u -b 320kpps (CPU
saturated at ~7 Gbps aggregate).

Without the fix: 8 warnings in 6 hours (first at ~72 min).
With the fix: 0 warnings after 20+ hours under identical conditions.

Fixes: 9b8d05b8ac78 ("Add support for Amazon Elastic Network Adapter (ENA) NIC")
Submitted by: Gilad Ben Yakov <giladben@amazon.com>
MFC after: 2 weeks
Sponsored by: Amazon, Inc.

Diff Detail

Repository
rG FreeBSD src repository
Lint
Lint Not Applicable
Unit
Tests Not Applicable

Event Timeline

akiyano_amazon.com planned changes to this revision.
akiyano_amazon.com created this revision.

I see these errors under low loads, and not always as "1 [mu]secs have passed":

ena0: Found a Tx that wasn't completed on time, qid 0, index 856. 10000 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 4, index 391. 1 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 2, index 124. 1 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 0, index 938. 1440 msecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 0, index 192. 20000 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 0, index 551. 370 msecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 2, index 425. 10000 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 1, index 297. 60 msecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 1, index 120. 1 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 4, index 353. 10000 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 0, index 104. 10000 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 4, index 68. 1 usecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.
ena0: Found a Tx that wasn't completed on time, qid 1, index 469. 100 msecs have passed since last cleanup. Missing Tx timeout value 5000 msecs.

I'm guessing the "always reporting '1 msecs since last cleanup'" you mention in the commit message is simply an artifact of having high network load -- if you're pushing enough packets, of course the cleanups always happen very frequently.

Good catch on the torn read though! The change looks correct even if the commit message potentially mis-claims about the symptom.

This revision is now accepted and ready to land.Wed, Jul 15, 3:08 AM