hm2_eth read timeout

[rene-dev]

during the stuttgart meeting, we tested master on real hardware with hm2_eth, and got a lot of hm2 read timeouts.
we bisected it to this commit, and specifically this line in the commit:
dd68759#diff-a2fc5c48f24c0bb77a64ce221b7cbcfa4494cdc8ccc69f4011282c82aa6f4a6eR179

needs investigating.

[rene-dev]

while the hm2_eth works fine before that commit, the smartserial now stops working after a while. It is ok on 2.9.

[grandixximo]

@rene-dev shouldn't the smart serial be its own issue then?

[BsAtHome]

@hdiethelm could you shed some light on this?

[hdiethelm]

Hmm, hard to say what the issue is due to it works on my system.

• Do you have a log?
• OS/Kernel?
• Any details on the system config?

Just guessing:

• It could be that if the timing is at the limit, it could have barly not reached a timeout while after this change, it times out.
• Possibly, ppoll does not work well on certain systems.

Worst case, I could go back to polling instead of interrupt driven while keeping the rest of the change as it is.

[hdiethelm]

I have no way of testing with smartserial: I don't have such a device.

A log would help a lot, without it's mostly guessing. I can only test timeouts by powering of the mesa board. When I do this, I see:

hm2_eth: receive_queued_reads: error (Resource temporarily unavailable) after 805451ns timeout=800000ns
hm2_eth: receive_queued_reads: error (Resource temporarily unavailable) after 805287ns timeout=800000ns
hm2_eth: receive_queued_reads: error (Resource temporarily unavailable) after 804663ns timeout=800000ns
hm2_eth: receive_queued_reads: error (Resource temporarily unavailable) after 804025ns timeout=800000ns
hm2_eth: receive_queued_reads: error (Resource temporarily unavailable) after 805403ns timeout=800000ns
hm2/hm2_7i96s.0: error finishing read! iter=173506

So exactly what is expected.

Also, the values of:
hm2_7i96s.0.read.time
hm2_7i96s.0.read.tmax
hm2_7i96s.0.packet-read-timeout
would be good to know. Ideally before and after the offending commit.

Meanwhile, I created 3 branches to test. Do you have a way to test if one or multiple solve the issue?

Read always with MSG_DONTWAIT, even if poll says there is no data:
https://github.com/hdiethelm/linuxcnc-fork/tree/hm2_eth_timeout_read

Change to select instead of ppoll:
https://github.com/hdiethelm/linuxcnc-fork/tree/hm2_eth_timeout_select

Back to polling loop as it was before but implemented inside the read function instead of copy-paste:
https://github.com/hdiethelm/linuxcnc-fork/tree/hm2_eth_timeout_poll

[rene-dev]

yes, that is exactly the message we got. I dont have those values currently, as it was @gmoccapy s machine. But I will test at home on my machine as well.

[rene-dev]

just in case it was unclear: the problem is not that the error appears, the machine actually becomes unusable when this happens, and the sserial slave timeouts. so it is not just a measuring error, something actually takes longer. will make some measurements.

[hdiethelm]

After going trough dd68759 and the bug report again, there is also an other possible reason: In hm2_eth.c:1032, I added the warning hm2_eth: receive_queued_reads: error (Resource temporarily unavailable) after 805451ns timeout=800000ns when a timeout occurs. There was no such warning on master before. However, there is the pin hm2_7i96s.0.packet-error-total which should increase on each timeout.

If you see this pin value increase on master before the above commit and smart serial stops working, this commit is most probably not the reason for the issue but just makes a timeout better visible.

Now after reading it, probably warning: would have been a better text. Depending on the configuration of hm2_eth, the board is disabled after default 5 timeouts in a row, but it can be adjusted with packet_error_limit.

When the board is disabled, the message hm2/hm2_7i96s.0: error finishing read! iter=173506 appears and the io-error pin is set to true.