Repository navigation
alpha.110: an FoE read of config.csv on an Integro answered 3852 of 4432 bytes with success, after the PC held a mailbox frame for 100 ms #138
Description
What happens
On our desk Integro with alpha.110, one read of config.csv, a file of 4432 bytes, answered with 3852 bytes and success. MM's log:
[17:33:59.169] [debug] FOEread slave 1 'config.csv'
[17:33:59.285] [info] Device 1: aborted the FoE transfer
[17:33:59.385] [warning] FOEread slave 1 'config.csv' failed (FoE error, wkc -1); attempt 1 of 3
[17:34:05.485] [info] Device 1: aborted the FoE transfer
[17:34:05.585] [warning] FOEread slave 1 'config.csv' failed (no response); attempt 2 of 3
[17:34:05.755] [debug] FOEread slave 1 'config.csv' ok (3852 bytes)
The third attempt returned a file 580 bytes short. That is item 3 of synapticon/somanet_software#5817: after a transfer ends early, the Integro serves the rest of the file as a whole file. Here it happened with no netem rule, on the PC of #113 as it is.
What started it: the PC held a return for 100 ms
The capture of that run (POST /api/captures, 30 s beside the rounds) has one frame later than 20 ms. It is the read of the drive's receive mailbox that carried an FoE packet:
17:33:59.184866 from PC FPRD idx 22 adp 0x1001 ado 0x1080 len 128
(no frame on the wire for 100 ms)
17:33:59.284969 from PC FPRD idx 23 adp 0x1001 ado 0x080D len 1
17:33:59.284993 returned FPRD idx 22 adp 0x1001 ado 0x1080 len 128
17:33:59.284993 returned FPRD idx 23 adp 0x1001 ado 0x080D len 1
- The return of idx 22 carries the same kernel timestamp as the return of the next frame, and comes 24 µs after that frame left the PC.
- A mailbox frame's round trip is 22 µs at the median and 39 µs at the 99th percentile in this capture. Of the other 119,418 mailbox frames of the run, 3 came back later than 2 ms and none later than 20 ms.
- So the drive answered at once, and the return sat in the PC's receive path until the next frame's return made the driver hand both up. It looks like a missed receive interrupt in r8169. Interrupt coalescing is off on the adapter (
ethtool -c: rx-usecs 0, rx-frames 1). - The 100 ms is MM's own wait for the frame. The held return comes up when MM, after that wait, sends its next frame.
- Run 3 shows the same, 100.139 ms after an FPRD of 0x1080, during an SDO read of 0x200E:00. alpha.99's second read rode through it: "got no answer (wkc -1); asked once more", then ok.
The #113 test on alpha.110
Same PC, drive and test as #113. A run is 10 rounds at PreOp of POST /api/devices/1/parameters/read (577 parameters, so 577 SDO uploads) and GET /api/devices/1/files/config.csv. The drive runs a v5.6 build with open firmware PRs, v5.6.11+10.g9bcc5ff33.
| MM | Runs | Failed SDO reads per run | Writes without a frame back per run | Median parameter read | config.csv reads that differ |
|---|---|---|---|---|---|
| alpha.110 | 3 | 0, 0, 0 | 0, 0, 0 | 2.3, 2.3, 2.3 s | 0, 1, 0 |
| alpha.93 | 3 | 0, 0, 1 | 76, 70, 54 | 2.9, 2.8, 2.5 s | 0 |
| alpha.92 | 2 | 13, 7 | 74, 64 | 3.1, 2.4 s | 0 |
| alpha.91 | 1 | 0 | not logged | 2.3 s | 0 |
The parameter read is the time of the whole HTTP request, about 4 ms per SDO upload. The script then held the drive at OP for 30 s, not enabled, with a second capture:
| Run | Mailbox frames at PreOp | Sent again | Later than 2 / 20 / 100 ms | Cyclic frames at OP | Cyclic round trip, median / 99th percentile / max | Cycles skipped at OP | Short working counter |
|---|---|---|---|---|---|---|---|
| 1 | 100,716 | 0 | 3 / 0 / 0 | 30,000 | 32 / 81 / 326 µs | 0 | 0 |
| 2 | 119,419 | 1 | 4 / 1 / 1 | 30,000 | 31 / 88 / 224 µs | 0 | 0 |
| 3 | 101,185 | 0 | 2 / 1 / 1 | 29,999 | 32 / 83 / 345 µs | 1 | 0 |
The game loop held 1000 Hz with SCHED_FIFO, with a cycle time of 25 to 27 µs on average and 470 to 850 µs at most.
So alpha.110 is as fast as alpha.91, and what #113 reported is gone. What is left is the return the PC holds, about one in 100,000 mailbox frames here. When it falls into an FoE read, #5817 (3) turns it into a wrong file with status 200.
What should happen
A file read that answers with success returns the whole file.
Possible fixes
- Do not wait 100 ms for a return the PC holds. After a short wait with no return, send one harmless frame, for example the SyncManager 1 status read that MM sends after its 100 ms today. Both held returns came up within 25 µs of the next frame.
- After an FoE read on an Integro that ended early, answer the request with an error rather than trying again, or try again and answer only when two reads of the file agree. The tail #5817 (3) serves is shorter than the file.
Also seen
- The capture summary counts as lost the last frame sent before the capture ends. Each of our six captures has one such frame, sent in the last microseconds, with
lost: 1. A frame sent less than the longest wait, 100 ms, before the end could be counted apart. - The description of
POST /api/capturessays "A capture that shows late frames puts the delay on the wire or in the device." The kernel takes a return's timestamp when the driver hands it up, so a return the driver holds shows as late too, as here.
Environment
- PC: AMD Ryzen 7 PRO 8840HS, Ubuntu 26.04.1 LTS, kernel 7.0.0-38-generic, no real-time patch. The bus is on a Realtek NIC, driver r8169, with interrupt coalescing off.
- MM: 6.0.0-alpha.110 from the .deb.
- Drive: SOMANET Integro (ACTILINK-S), serial 9024-05-0000764-2550, firmware v5.6.11+10.g9bcc5ff33. One drive on the bus.
- The script: MMAF's dev/research/mailbox_ab.py with
--rounds 10 --capture 30 --op-sec 30.
Files
The six captures, MM's log of the three runs, the script, and the pairing of the late frames are in a zip in a comment below.
Activity
apremji commentedon Oct 22, 2026
The FoE trace of the short read
Rebuilt from the FoE messages in run 2's PreOp capture,
capture-20261022-173342-enp1s0f0.pcap. A master message is a write into SM0, and a drive message is a read of SM1 that came back with a working counter of 1.The 34 packets of the third read are exactly bytes 580 to 4432 of the file, which are packets 6 to 39 of a whole read, numbered 1 to 34. Every other read of config.csv in the capture is 39 packets and 4432 bytes. The first read of the three ended after 4 packets, 464 bytes, the head of the file.
Why the read answered with success
The third transfer is a valid FoE read as far as the protocol goes. It starts with an RRQ, its packet numbers count up from 1, every packet is acknowledged, and it ends with a packet shorter than the mailbox allows, which is how FoE marks the end of a file. FoE carries no file size or checksum, so nothing in the transfer itself shows that it starts at byte 580.
What we would ask of MM
The script that rebuilt the trace,
foe_trace.py, is in the zip below.feat(hil): add held_frame to test a held return and the NOP that free…
markosankovic commentedon Oct 23, 2026
A test for the held return
held_frametests the reading of the capture above, and it tests a remedy for it. Its source ishil/held_frame/main.ccon the branch of this issue.The binary: held_frame-portable.zip (attached below)
held_frame-portable.zip
The program reads
config.csvover FoE again and again, with the frames MM sends for a file read: a mailbox write for the request and for each acknowledgement, a read of the SyncManager 1 status every 200 µs until the mailbox is full, and a read of the mailbox. The mailbox writes and mailbox reads go out once, as MM sends them. Two modes take turns, one file read each. They differ only in how they wait for the return of a mailbox write or a mailbox read:plainwaits up to 100 ms, as MM does today. When no return comes, it sends the SyncManager 1 status read, the frame MM sends next, and looks for the missing return beside its return. That is the event of the capture above. MM ends the transfer at that point. The program uses the return when it came, so the drive is never left part-way through the file.nudgesends a NOP datagram after each 2 ms with no return, and looks for the return right after the NOP comes back. Every slave passes a NOP on and acts on nothing in it.Each read is compared with the first read of the run. The last line is one of these:
THE NOP RELEASES A HELD FRAME: inplainsome returns came only beside the status read, innudgea NOP released at least one return, and every return came within 20 ms.NO HELD FRAME SEEN: no held return inplain. The traffic did not cause a hold, or the run was too short.NOT CONFIRMED: anything else. The lines above it say what happened.How to run it
On the PC of this issue, with the Integro on the bus and no MM server using the adapter:
A read of
config.csvis about 320 frames. The held return came about once in 100,000 mailbox frames, so 6000 reads give each mode about ten chances. That takes about 8 minutes. The program puts the drive into INIT and then PRE-OP, and leaves it in PRE-OP.The binary links libstdc++ statically, so it needs glibc 2.38 or newer and nothing else. It was built on Fedora 44 and was not tested on Ubuntu.
What to send back
uname -randethtool -i <bus adapter>.What the program does not cover
NO HELD FRAME SEENsays nothing about the NOP.On our bench
Fedora 44, kernel 7.2.11-200.fc44.x86_64, the bus on a USB adapter with the r8152 driver (RTL8153B), and an Integro, product 0x401, 50 reads:
An earlier version of the program sent 2,000,000 register reads on the same adapter and saw no held return either. This adapter does not hold returns, so the runs show only that the program works. Only a PC that holds returns can show whether the NOP releases them.
feat(hil): read a file over FoE in held_frame
docs: explain how frames, repeats and timeouts work on the bus
feat(comm): report a mailbox read that came back after the wait
docs(changelog): add the report of a late mailbox read
feat(tools): print the adapter settings that can hold a frame
markosankovic commentedon Nov 1, 2026
Results of
held_frameThank you for the run. The log has two runs of 6000 reads each, on
enp1s0f0with an Integro, product 0x401.Run 1:
THE NOP RELEASES A HELD FRAMEplain, 185 returns came about 100.2 ms late, each one beside the return of the next frame. This is the event of the capture above.nudge, 207 NOPs were sent, and each one released a held return. These returns came about 2.2 ms late.plainsay "the read request was not written". The host held the return of the read request itself.Run 2:
NOT CONFIRMEDThe host held one return in 6000 reads. At the end, the script restored
napi_defer_hard_irqs 1andgro_flush_timeout 20000. So it changed these two settings for one of the runs.What we need
held_frame_ab.sh, to know which run used which settings.uname -r.ethtool -i enp1s0f0.If run 2 is the run with the settings changed, the settings cause the hold. In run 1 the NOP released every held return, so it can protect a host where nobody changes them.