Mt76 wireless driver debugging

In an effort to test this I've done my first full build of OpenWRT.

I followed the standard environment setup instructions, checked out the v23.03.3 tag and then cherry-picked the patch commit. From there I continued following the "quick" build instructions, using the build configuration from the relevant 23.03.3 target.

I've flashed the firmware and everything seems fine, but Is there any way to verify that the firmware I built actually contains the patch that I cherry-picked?

I just installed current snapshot
OpenWrt SNAPSHOT r22392-e7c399bee6 / LuCI Master git-23.074.82619-6ad6a24
and one of my APs froze within an hour.
It was not just wifi, I was unable to log in and had to restart.
This matches your observation.
I've disabled WED for now.

Felix pushed a proposed fix for this regression:

I'm testing with it now and while my APs are not crashing in the same way as before, I am noticing decreased throughput at the moment. Curious if others are seeing the same as well.

FWIW, I still have WED enabled, but am also testing with /proc/sys/net/core/backlog_threaded enabled (set to 1) per this:

Update 1 Yeah, something odd is going on for me. I disabled /proc/sys/net/core/backlog_threaded for now to not have that new variable introduced. When I see flows offloaded, performance seems pretty good--on par with other testing I've been doing with WED thus far. But sometimes the same device, running the same test, will not have its flows offloaded and my RT3200 CPUs reflect that heavily. In those cases, I'm seeing lower throughput than before the commits I tested yesterday (07b5508, fbcfb7f, d0a0696, and aa27771). Back-to-back tests indicate inconsistencies with which flows are offloaded or not.

Unfortunately there were a lot of other changes between the bad commit (aa27771) and the fix he pushed for that commit, which is https://github.com/openwrt/openwrt/commit/95cae498b6ab4613a0b4915393c798c750dac396.

I feel like I'm probably going to have to bisect again and see if there was another regression in between. sigh. If anyone else is NOT seeing what I'm describing, it could be something else going on in my test environment and knowing that might save me some bisecting time. :slight_smile:

Update 2 To put some numbers behind my statements before...

I found the throughput "regression" I was noting is not necessarily new to this build. In fact, I went back and confirmed this same behavior was happening on d0a0690 (and maybe prior even to that) as well.

Testing with iperf3:

  • From a well-connected 1gb ethernet host (192.168.xx.5)
  • To the same wireless AX client (192.168.xx.109), located at the same location from test to test
  • Through the same AP

Test 1 - Offloaded flow appeared in ppe0:

❯ iperf3 -c 192.168.xx.5 -i1 -t30 -R
Connecting to host 192.168.xx.5, port 5201
Reverse mode, remote host 192.168.xx.5 is sending
[  5] local 192.168.xx.109 port 53371 connected to 192.168.xx.5 port 5201
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-1.01   sec  45.3 MBytes   378 Mbits/sec
[  5]   1.01-2.01   sec  55.5 MBytes   465 Mbits/sec
[  5]   2.01-3.00   sec  41.7 MBytes   352 Mbits/sec
[  5]   3.00-4.00   sec  34.3 MBytes   288 Mbits/sec
[  5]   4.00-5.00   sec  54.6 MBytes   458 Mbits/sec
[  5]   5.00-6.00   sec  57.6 MBytes   483 Mbits/sec
[  5]   6.00-7.00   sec  58.5 MBytes   492 Mbits/sec
[  5]   7.00-8.00   sec  57.6 MBytes   483 Mbits/sec
[  5]   8.00-9.01   sec  58.6 MBytes   489 Mbits/sec
[  5]   9.01-10.00  sec  61.1 MBytes   513 Mbits/sec
[  5]  10.00-11.01  sec  43.2 MBytes   362 Mbits/sec
[  5]  11.01-12.00  sec  38.4 MBytes   324 Mbits/sec
[  5]  12.00-13.00  sec  38.2 MBytes   321 Mbits/sec
[  5]  13.00-14.00  sec  55.3 MBytes   464 Mbits/sec
[  5]  14.00-15.00  sec  53.4 MBytes   448 Mbits/sec
[  5]  15.00-16.00  sec  57.0 MBytes   478 Mbits/sec
[  5]  16.00-17.00  sec  54.1 MBytes   452 Mbits/sec
[  5]  17.00-18.00  sec  55.0 MBytes   462 Mbits/sec
[  5]  18.00-19.00  sec  58.5 MBytes   490 Mbits/sec
[  5]  19.00-20.01  sec  52.7 MBytes   440 Mbits/sec
[  5]  20.01-21.00  sec  42.2 MBytes   354 Mbits/sec
[  5]  21.00-22.00  sec   546 KBytes  4.47 Mbits/sec
[  5]  22.00-23.00  sec  29.1 MBytes   245 Mbits/sec
[  5]  23.00-24.00  sec  58.8 MBytes   493 Mbits/sec
[  5]  24.00-25.00  sec  54.7 MBytes   460 Mbits/sec
[  5]  25.00-26.00  sec  54.8 MBytes   459 Mbits/sec
[  5]  26.00-27.00  sec  53.1 MBytes   446 Mbits/sec
[  5]  27.00-28.00  sec  58.4 MBytes   490 Mbits/sec
[  5]  28.00-29.00  sec  51.3 MBytes   430 Mbits/sec
[  5]  29.00-30.01  sec  35.4 MBytes   296 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-30.18  sec  1.44 GBytes   409 Mbits/sec  59354             sender
[  5]   0.00-30.01  sec  1.43 GBytes   411 Mbits/sec                  receiver

iperf Done.

Test 2 - Offloaded flow did not appear in ppe0:

❯ iperf3 -c 192.168.xx.5 -i1 -t30 -R
Connecting to host 192.168.xx.5, port 5201
Reverse mode, remote host 192.168.xx.5 is sending
[  5] local 192.168.xx.109 port 53377 connected to 192.168.xx.5 port 5201
[ ID] Interval           Transfer     Bitrate
[  5]   0.00-1.00   sec  44.5 MBytes   373 Mbits/sec
[  5]   1.00-2.00   sec  57.8 MBytes   485 Mbits/sec
[  5]   2.00-3.00   sec  57.4 MBytes   481 Mbits/sec
[  5]   3.00-4.01   sec  63.4 MBytes   529 Mbits/sec
[  5]   4.01-5.00   sec  61.6 MBytes   519 Mbits/sec
[  5]   5.00-6.00   sec  61.5 MBytes   514 Mbits/sec
[  5]   6.00-7.01   sec  63.9 MBytes   535 Mbits/sec
[  5]   7.01-8.00   sec  55.3 MBytes   466 Mbits/sec
[  5]   8.00-9.00   sec  14.8 MBytes   124 Mbits/sec
[  5]   9.00-10.00  sec  60.1 MBytes   503 Mbits/sec
[  5]  10.00-11.00  sec  43.6 MBytes   366 Mbits/sec
[  5]  11.00-12.00  sec  61.8 MBytes   519 Mbits/sec
[  5]  12.00-13.00  sec  57.3 MBytes   481 Mbits/sec
[  5]  13.00-14.00  sec  58.2 MBytes   488 Mbits/sec
[  5]  14.00-15.00  sec  60.8 MBytes   508 Mbits/sec
[  5]  15.00-16.00  sec  60.3 MBytes   506 Mbits/sec
[  5]  16.00-17.00  sec  63.2 MBytes   531 Mbits/sec
[  5]  17.00-18.00  sec  18.8 MBytes   158 Mbits/sec
[  5]  18.00-19.00  sec  54.1 MBytes   454 Mbits/sec
[  5]  19.00-20.00  sec  58.3 MBytes   489 Mbits/sec
[  5]  20.00-21.00  sec  38.0 MBytes   319 Mbits/sec
[  5]  21.00-22.00  sec  61.0 MBytes   512 Mbits/sec
[  5]  22.00-23.00  sec  60.0 MBytes   503 Mbits/sec
[  5]  23.00-24.00  sec  55.0 MBytes   461 Mbits/sec
[  5]  24.00-25.01  sec  57.2 MBytes   477 Mbits/sec
[  5]  25.01-26.00  sec  58.3 MBytes   490 Mbits/sec
[  5]  26.00-27.00  sec  33.1 MBytes   278 Mbits/sec
[  5]  27.00-28.00  sec  53.8 MBytes   450 Mbits/sec
[  5]  28.00-29.00  sec  48.9 MBytes   410 Mbits/sec
[  5]  29.00-30.00  sec  49.1 MBytes   413 Mbits/sec
- - - - - - - - - - - - - - - - - - - - - - - - -
[ ID] Interval           Transfer     Bitrate         Retr
[  5]   0.00-30.00  sec  1.56 GBytes   446 Mbits/sec    3             sender
[  5]   0.00-30.00  sec  1.55 GBytes   445 Mbits/sec                  receiver

iperf Done.

Something odd happens around 21-22seconds. Look at the number of retries (!!!) when packets are traversing ppe0 vs not:
59354 vs 3

@nbd I suspect this is not the intended behavior for data traversing ppe0. Could you confirm this?

Also, this is still very true in my testing:

d0a0690

Please provide full commit key. Cannot find d0a0690, as seen here: https://github.com/openwrt/openwrt/search?q=d0a0690

commit d0a06965e8ab0a92a4813fddbb8e045407897310
Author: Felix Fietkau <nbd@nbd.name>
Date:   Mon Mar 20 18:51:06 2023 +0100

I found it too, but probably need to spend hours on the documentation to figure out how gdb works. There isn't just an example, instead there are hundreds of pages of technical documentation.

You can cd into the folder the gedit the file to see if the line is there:

osboxes@osboxes:/$ cd ~/openwrt/build_dir/target-aarch64_cortex-a53_musl/linux-mediatek_mt7622/backports-6.1-rc8/net/mac80211
osboxes@osboxes:~/openwrt/build_dir/target-aarch64_cortex-a53_musl/linux-mediatek_mt7622/backports-6.1-rc8/net/mac80211$ gedit sta_info.c

Although your backports might not be 6.1-rc8, so you'll have to find the folder.

Thank you - that was helpful. The answer is no, the patch didn't apply. I have no idea why not though. Do patches need to be listed somewhere in order to get applied to a particular target?

I haven't read OpenWRT documentation on how to apply a specific patch, so I can't answer that. But I'm well versed with git manipulation, so I just do my own patching.

If you run the patch again, you can check that file before you compile. If it's not there, then the patch maybe didn't run? If it did and you run "make world", check it again afterwards and the patch should still be there. If it downloads over it... well, it shouldn't, because each package has a git repo and SHA256 checksum, and packages do not re-download/unpack as long as they haven't changed, leaving source files as is.

Hoping this doesn’t take the thread off topic, but I also sent this to @timothyjward earlier via message: https://openwrt.org/docs/guide-developer/toolchain/use-patches-with-buildsystem

That is the “official” way to apply patches in the OpenWrt build system. Generally you would place patches in the appropriate package/ or target/ subdirectory so they’re not wiped out from build_dir/ during certain clean operations. @hnyman explains that in more detail on post #6 here.

This looks promising, though too “simple” compared to what I was finding last night. I’m going to give it a try tomorrow.

Awesome find on the gdb front! This looks like a remote debugging session.
I think the aarch64 gdb might be able to just point at the source code and show which line number is being referenced from a stack trace function/offset.
(I'm doing taxes this weekend so haven't had a chance yet to dig into gdb)

Agreed on the point about gdb being able to show a line number from source (given an offset), but I was thinking the remote ability of gdb might lend itself to attaching to running processes on the AP and view real-time backtrace info (among other things).

Perhaps that's not the right use-case for kernel/driver debugging. Just something that seemed interesting to potentially explore.

A few hopefully helpful items for you:

EDIT:
Old example of the the basic items in debugging "collectd":

  • on router: gdbserver :9000 collectd -f
  • on buildhost: ./scripts/remote-gdb 192.168.1.1:9000 ./staging_dir/target-mips_34kc_musl-1.1.11/root-ar71xx/usr/sbin/collectd

I found out last week how to use gdb properly to get the code where a crash occurs. Because openwrt uses -O2 optimization by default during the compile, it will inline a lot of functions, so the function names in the stack dump are often not the real function, especially if the offset is above 0x100.

Here's an example usage, run from the build server:

(gdb) add-symbol-file ~/openwrt/build_dir/target-aarch64_cortex-a53_musl/linux-mediatek_mt7622/backports-6.1-rc8/net/mac80211/mac80211.o
add symbol table from file "/home/osboxes/openwrt/build_dir/target-aarch64_cortex-a53_musl/linux-mediatek_mt7622/backports-6.1-rc8/net/mac80211/mac80211.o"
(y or n) y
Reading symbols from /home/osboxes/openwrt/build_dir/target-aarch64_cortex-a53_musl/linux-mediatek_mt7622/backports-6.1-rc8/net/mac80211/mac80211.o...

(gdb) l *ieee80211_sta_ps_transition+0x448
0x23a20 is in ieee80211_rx_8023 (/home/osboxes/openwrt/build_dir/target-aarch64_cortex-a53_musl/linux-mediatek_mt7622/backports-6.1-rc8/net/mac80211/rx.c:4771).
4766				 */
4767				xmit_skb->priority += 256;
4768				xmit_skb->protocol = htons(ETH_P_802_3);
4769				skb_reset_network_header(xmit_skb);
4770				skb_reset_mac_header(xmit_skb);
4771				dev_queue_xmit(xmit_skb);
4772			}
4773	
4774			if (!skb)
4775				return;

Unfortunately there is still two other crashes that have not been added by Felix that I submitted. One for three is just a start. My branch has all the found fixes so far. He does not like the spinlock I added, but if it doesn't crash, and the documentation calls for synchronization, then... well.. I don't know. I could very well be wrong and it could be something else, but noone has offered up an alternative, and my spinlocks follow what the ieee80211 documentation calls for. Though, Felix would probably know if that documentation is incorrect. He may have written most of it after all.

I've just found another issue, this one possibly affecting the WED stopping. There are tokens not being released over time, and I need to track down why.... Once I have this I believe the RT3200 will be stable.

Are you able to keep track of the patches as they are added/merged in master?

I think I have successfully backported the mac80211 fix to 22.03, but it would be nice to get as many of the patches as possible into stable.

Let's get back to this WED issue. First an update, I'm compiling with the latest OpenWRT build as of 4/3/2023. Using my branch for the mt76 portion, it no longer crashes, but it has a new issue. The speed gets slower, and slower, and slower, until I can't even connect. I added a debug file in the /sys/ folder so I can view internal counters real time.

The first thing I've found is the token_count gets stuck at some point above zero. This is probably when WED stops working. The question is... when and why? This is my next target. I have a feeling once this is fixed, the WED will be fixed as well.

I added the extra debug code to my branch if you want to pull the latest. You can then do this:

root@router:~# cd /sys/kernel/brain2000
root@router:/sys/kernel/brain2000# cat brain2000_mt76-\>token_count
token_count=0
sta_rc_list=0
sta_poll_list=0
twt_list=0

This monitoring will help us to see what doesn't get cleaned up when issues start happening.
I'm finding the token_count gets stuck above 0 after a while, even if I do a wifi down wifi up. The only way to get it back down to 0 is to run rmmod and modprobe to reload the mt7915e driver.

Let's see where this leads...

My patches will not get added until Felix deems them appropriate.