frdm_k64f: Sometimes, there may be 1000+ms roundtrip for pings and other Ethernet packets (instead of sub-ms)

[zephyrbot]

Reported by Paul Sokolovsky:

I never saw this issue with QEMU, so theorize that it's frdm_k64t Ethernet driver issue.

Sometimes, instead of usual sub-millisecond pings:

64 bytes from 192.0.2.1: icmp_seq=1 ttl=64 time=0.788 ms
64 bytes from 192.0.2.1: icmp_seq=2 ttl=64 time=0.476 ms
64 bytes from 192.0.2.1: icmp_seq=3 ttl=64 time=0.295 ms
64 bytes from 192.0.2.1: icmp_seq=4 ttl=64 time=0.475 ms

you're starting to get:

64 bytes from 192.0.2.1: icmp_seq=88 ttl=64 time=1008 ms
64 bytes from 192.0.2.1: icmp_seq=89 ttl=64 time=1008 ms
64 bytes from 192.0.2.1: icmp_seq=90 ttl=64 time=493 ms
64 bytes from 192.0.2.1: icmp_seq=91 ttl=64 time=1007 ms

So far, I wasn't able to find an exact way to reproduce, but it happens often. Say, I see it in every testing session (5-6 board resets/Ethernet cable reconnects).

When this happens, all other packets seem to be delayed too, not just pings. For example, using netcat UDP with echo_server shows the similar effect of 1s delay.

(Imported from Jira ZEP-1678)

[zephyrbot]

by Paul Sokolovsky:

As a bit of more info, I saw this before https://gerrit.zephyrproject.org/r/10902 (dynamic PHY config on cable connect/disconnect), and saw with it too.

[zephyrbot]

by Paul Sokolovsky:

A case walkthru:

1. Flashed freshly built echo_server.
2. ping 192.0.2.1 - ok
3. ping6 2001:db8::1 - ok
4. nc -u6 2001:db8::1 4242 - ok
5. nc -u 192.0.2.1 4242 - problem begins. How it look like is that when type in 1st packet, no response is generated. Typing 2nd line and sending it, I get response to previous packet, etc. Sometimes, after wait, a last expected response does arrive on its own, by after more than 1s subjectively, maybe 2-3s.

[zephyrbot]

by Paul Sokolovsky:

Ok, a response always arrives actually, but perhaps after 4-5s. Typing a next one quickly makes previous response arrive immediately.

All that, I never saw with QEMU.

[zephyrbot]

by Paul Sokolovsky:

Ok, in such state, TCP echo doesn't work at all, so it's definitely another manifestation of ZEP-1724.

[zephyrbot]

by Paul Sokolovsky:

Now I'm torturing it for the whole 3 minutes, and it still works.

[zephyrbot]

by Paul Sokolovsky:

The same session now underwent 1000 pings (standard pings), and all 6 comm channels ((ICMP + UDP + TCP) * (IPv4 + IPv6)) work well, w/o any delays. (I pay special attention to pings, because I usually start testing with them, and in most cases, the issue manifests soon with them).

This proves that this is not inherent systematic issue, but a race condition. And we can't even be sure it's race in eth_mcux, because Z IP stack surely has its own share of races and weird things yet. And likely, it's eth_mcux race attenuated by Z stack race.

That was "good" news, bad news is that we can't reproduce it in at our will (though natural reoccurrence is quite high definitely).

[pfalcon]

This have been occurring for me regularly all this time. No specific pattern for triggering, except that it tends to occur with high probability after sufficient network load.

Another hypothesis, away from frdm_k64f/eth issue, is that it triggers some bug in the IP stack. Why it doesn't happen with QEMU is because of the low speed of it. With Ethernet, everything is "real time", which makes it easier to trigger e.g. some concurrency issue, after which the IP stack is stuck in this weird state.

[mike-scott]

Adding @therealprof in that he's been testing ethernet on a Nucleo STM32 board. It might be interesting to compare notes to see if the bug lies in the Z IP stack or something specific to MCUX shims.