<div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr">Hi!</div><div dir="ltr"><br></div><div dir="ltr">I'm way out in the deep end of the pool here poking at things i shouldn't to see what happens and if i can learn something, or find a bit more info where things go wrong.. So I patched drivers/bus/mhi/pci_generic.c to give some more debug info:</div><div dir="ltr"><div><div><br></div><div>oskar@oskar-ThinkPad-X1-Nano-Gen-1:~/src/linux-kernel/linux-upstream-5.12.0+$ git diff</div><div>diff --git a/drivers/bus/mhi/pci_generic.c b/drivers/bus/mhi/pci_generic.c</div><div>index 7c810f02a2ef..819c0f17993d 100644</div><div>--- a/drivers/bus/mhi/pci_generic.c</div><div>+++ b/drivers/bus/mhi/pci_generic.c</div><div>@@ -492,9 +492,13 @@ static int mhi_pci_get_irqs(struct mhi_controller *mhi_cntrl,</div><div> * Alloc one MSI vector for BHI + one vector per event ring, ideally...</div><div> * No explicit pci_free_irq_vectors required, done by pcim_release.</div><div> */</div><div>+ dev_warn(&pdev->dev, "mhi_cntrl_config->num_events: %d\n", mhi_cntrl_config->num_events);</div><div> mhi_cntrl->nr_irqs = 1 + mhi_cntrl_config->num_events;</div><div>+ dev_warn(&pdev->dev, "mhi_cntrl->nr_irqs: %d\n", mhi_cntrl->nr_irqs);</div><div>+ dev_warn(&pdev->dev, "PCI_IRQ_MSI: %d\n", PCI_IRQ_MSI);</div><div><br></div><div> nr_vectors = pci_alloc_irq_vectors(pdev, 1, mhi_cntrl->nr_irqs, PCI_IRQ_MSI);</div><div>+ dev_warn(&pdev->dev, "nr_vectors: %d\n", nr_vectors);</div><div> if (nr_vectors < 0) {</div><div> dev_err(&pdev->dev, "Error allocating MSI vectors %d\n",</div><div> nr_vectors);</div></div><div><br></div><div>Compiling and loading that module prints the following in dmesg:</div><div><div>[ 5553.096754] mhi-pci-generic 0000:08:00.0: BAR 0: assigned [mem 0xbc200000-0xbc200fff 64bit]</div><div>[ 5553.097033] mhi-pci-generic 0000:08:00.0: mhi_cntrl_config->num_events: 4</div><div>[ 5553.097036] mhi-pci-generic 0000:08:00.0: mhi_cntrl->nr_irqs: 5</div><div>[ 5553.097038] mhi-pci-generic 0000:08:00.0: PCI_IRQ_MSI: 2</div><div>[ 5553.097314] mhi-pci-generic 0000:08:00.0: nr_vectors: 1 <- requested 5, got 1..</div><div>[ 5553.097316] mhi-pci-generic 0000:08:00.0: using shared MSI</div></div><div><br></div><div>requesting 5 nr_vectors, getting one which then seems to trigger another codepath..</div><div><br></div><div>Whlie researching pci_alloc_irq_vectors I then found this semi-related thread <a href="https://stackoverflow.com/questions/49821599/multiple-msi-vectors-linux-pci-alloc-irq-vectors-return-one-while-the-devi" target="_blank">https://stackoverflow.com/questions/49821599/multiple-msi-vectors-linux-pci-alloc-irq-vectors-return-one-while-the-devi</a> where Riton38 mentions that enabling intel vt-d "solved the problem" (default from factory on this Thinkpad X1 Nano it has all virtualization disabled).</div><div><br></div><div>Since i can't figure out what's wrong with the actual irq-setup as it's possibly bug in modem firmware (throwing interrupts over some channel when it shouldn't), or maybe a bug in how irq's are allocated in mhi_pci_generic i just tried enabling Intel VT-D in bios (security -> virtualization) and what would you know, <b>it works!!</b></div><div><br></div><div><div>[ 81.291874] mhi_pci_generic: loading out-of-tree module taints kernel.</div><div>[ 81.291970] mhi_pci_generic: module verification failed: signature and/or required key missing - tainting kernel</div><div>[ 81.292527] mhi-pci-generic 0000:08:00.0: BAR 0: assigned [mem 0xbc200000-0xbc200fff 64bit]</div><div>[ 81.292560] mhi-pci-generic 0000:08:00.0: enabling device (0000 -> 0002)</div><div>[ 81.292603] mhi-pci-generic 0000:08:00.0: mhi_cntrl_config->num_events: 4</div><div>[ 81.292605] mhi-pci-generic 0000:08:00.0: mhi_cntrl->nr_irqs: 5</div><div>[ 81.292606] mhi-pci-generic 0000:08:00.0: PCI_IRQ_MSI: 2</div><div>[ 81.292713] mhi-pci-generic 0000:08:00.0: nr_vectors: 5 <- <b>We got 5 vectors now!</b></div><div>[ 81.292955] mhi mhi0: Requested to power ON</div><div>[ 81.293180] mhi mhi0: Power on setup success</div><div>[ 81.325854] mhi mhi0: Wait for device to enter SBL or Mission mode</div></div><div><br></div><div>After running qmicli and connecting, no more errors in kernel log.</div><div><br></div><div><div><div>oskar@oskar-ThinkPad-X1-Nano-Gen-1:~/src/linux-kernel/linux-upstream-5.12.0+/drivers/bus/mhi$ ping <a href="http://ftp.sunet.se" target="_blank">ftp.sunet.se</a></div><div>PING <a href="http://ftp.sunet.se" target="_blank">ftp.sunet.se</a>(<a href="http://tutankhamon.ftp.acc.umu.se" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163)) 56 data bytes</div><div>64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=1 ttl=51 time=46.1 ms</div><div>64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=2 ttl=51 time=43.9 ms</div><div>64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=3 ttl=51 time=42.7 ms</div><div>64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=4 ttl=51 time=49.0 ms</div><div>^C</div><div>--- <a href="http://ftp.sunet.se" target="_blank">ftp.sunet.se</a> ping statistics ---</div><div>4 packets transmitted, 4 received, 0% packet loss, time 3005ms</div><div>rtt min/avg/max/mdev = 42.708/45.419/49.019/2.404 ms</div></div></div><div><br></div><div>Speedtest now gives decent speed, 50Mbit/s down and 13.4Mbit/ up where i before only got +1000ms latency and 7Mbit/s down where I am (just outside of central stockholm)</div><div><a href="https://www.speedtest.net/result/11435773983" target="_blank">https://www.speedtest.net/result/11435773983</a><br></div><div><br></div><div>Anything i can do to test / debug interrupts without intel vt-d enabled while I have this fresh in memory?</div><div><br></div><div>/Oskar Stenman</div></div></div></div></div></div></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, 17 May 2021 at 12:53, Oskar Stenman <<a href="mailto:oskar@cetex.se" target="_blank">oskar@cetex.se</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div dir="ltr"><div>Hi!</div><div><br></div><div><div> CPU0 CPU1 CPU2 CPU3 CPU4 CPU5 CPU6 CPU7</div></div><div> 143: 0 0 0 0 0 6 0 192 PCI-MSI 4194304-edge bhi, mhi, mhi, mhi, mhi<br></div><div><br></div><div>Attaching files with full /proc/interrupts and made a small script with timestamps / logging to see what happens in chronological order.</div><div><br></div><div>/Oskar</div><div><br></div><br><div class="gmail_quote"><div dir="ltr" class="gmail_attr">On Mon, 17 May 2021 at 11:27, Loic Poulain <<a href="mailto:loic.poulain@linaro.org" target="_blank">loic.poulain@linaro.org</a>> wrote:<br></div><blockquote class="gmail_quote" style="margin:0px 0px 0px 0.8ex;border-left:1px solid rgb(204,204,204);padding-left:1ex">Hi Oskar,<br>
<br>
On Wed, 12 May 2021 at 11:10, Oskar Stenman <<a href="mailto:oskar@cetex.se" target="_blank">oskar@cetex.se</a>> wrote:<br>
><br>
> On Wed, 12 May 2021 at 09:35, Aleksander Morgado <<a href="mailto:aleksander@aleksander.es" target="_blank">aleksander@aleksander.es</a>> wrote:<br>
>><br>
>> Or even easier; just completely skip the name of the port and create a<br>
>> generic "gsm" connection setting not bound to any specific device.<br>
>><br>
>> $ nmcli conn add type gsm con-name wwan gsm.apn <a href="http://data.tre.se" rel="noreferrer" target="_blank">data.tre.se</a> gsm.pin 7470<br>
><br>
><br>
> I found the issue now. When everything was segfaulting due to garbage in files i saw (strace) that network-manager was dying after loading libnm-wwan.so, I thought it was installed by ModemManager so I deleted the module to get NM to start (and wifi to work again..), this of course broke wwan support in nm.<br>
> Reinstalled Network-Manager and it put the file back and it detects the interface.<br>
><br>
> oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ nmcli conn up wwan<br>
> Connection successfully activated (D-Bus active path: /org/freedesktop/NetworkManager/ActiveConnection/399)<br>
><br>
> (As you can see on connection counter "399", once ModemManager started NM tried to connect "a few times" before i stopped it and ran the qmicli command)<br>
><br>
> As a sidenote I switched operators today, Tele2. When i replaced the simcard the modem got stuck "unavailable" according to NetworkManager, After a reboot i have to run that qmicli cuskit command again to enable the card. (so not just a do-once kinda thing, more a "do every boot" kinda thing)<br>
><br>
> Alright, reboot. Clean slate, try again. (There are at least a couple seconds between runnig each of these commands, often more than a few, i realize now that I should've put timestamps in there..)<br>
> oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ sudo qmicli -p -d /dev/wwan0p2MBIM --device-open-mbim --dms-dell-cuskit-unlock=00<br>
> [sudo] password for oskar:<br>
> [12 maj 2021, 10:15:43] -Warning ** [/dev/wwan0p2MBIM] couldn't detect transport type of port: couldn't detect device driver<br>
> [12 maj 2021, 10:15:43] -Warning ** [/dev/wwan0p2MBIM] requested MBIM mode but unexpected transport type found<br>
> [/dev/wwan0p2MBIM] Successfully run Dell cuskit unlock<br>
> oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ sudo service ModemManager start<br>
> oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ nmcli conn up wwan<br>
> Connection successfully activated (D-Bus active path: /org/freedesktop/NetworkManager/ActiveConnection/2)<br>
> oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ ping <a href="http://ftp.sunet.se" rel="noreferrer" target="_blank">ftp.sunet.se</a><br>
> PING <a href="http://ftp.sunet.se" rel="noreferrer" target="_blank">ftp.sunet.se</a>(<a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163)) 56 data bytes<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=1 ttl=51 time=57.6 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=2 ttl=51 time=1055 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=3 ttl=51 time=1053 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=4 ttl=51 time=1051 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=5 ttl=51 time=1049 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=6 ttl=51 time=1048 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=7 ttl=51 time=1046 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=8 ttl=51 time=1045 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=9 ttl=51 time=1042 ms<br>
> 64 bytes from <a href="http://tutankhamon.ftp.acc.umu.se" rel="noreferrer" target="_blank">tutankhamon.ftp.acc.umu.se</a> (2001:6b0:19::163): icmp_seq=10 ttl=51 time=1041 ms<br>
> ^C<br>
> --- <a href="http://ftp.sunet.se" rel="noreferrer" target="_blank">ftp.sunet.se</a> ping statistics ---<br>
> 11 packets transmitted, 10 received, 9.09091% packet loss, time 10016ms<br>
> rtt min/avg/max/mdev = 57.648/948.772/1055.277/297.071 ms, pipe 2<br>
><br>
> So we have data!<br>
> But i see messages like this in dmesg:<br>
> [ 254.970231] __common_interrupt: 3.34 No irq handler for vector<br>
> [ 255.098499] __common_interrupt: 3.34 No irq handler for vector<br>
><br>
> With that ~1s latency I'm guessing something resorts to polling instead of triggering on interrupts?<br>
<br>
Weird, can you share the output of `cat /proc/interrupts | grep mhi`.<br>
<br>
Regards,<br>
Loic<br>
</blockquote></div></div></div></div></div></div></div></div></div></div></div></div></div></div></div></div>
</blockquote></div>