Hi!
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:
oskar@oskar-ThinkPad-X1-Nano-Gen-1:~/src/linux-kernel/linux-upstream-5.12.0+$
git diff
diff --git a/drivers/bus/mhi/pci_generic.c b/drivers/bus/mhi/pci_generic.c
index 7c810f02a2ef..819c0f17993d 100644
--- a/drivers/bus/mhi/pci_generic.c
+++ b/drivers/bus/mhi/pci_generic.c
@@ -492,9 +492,13 @@ static int mhi_pci_get_irqs(struct mhi_controller
*mhi_cntrl,
* Alloc one MSI vector for BHI + one vector per event ring,
ideally...
* No explicit pci_free_irq_vectors required, done by pcim_release.
*/
+ dev_warn(&pdev->dev, "mhi_cntrl_config->num_events: %d\n",
mhi_cntrl_config->num_events);
mhi_cntrl->nr_irqs = 1 + mhi_cntrl_config->num_events;
+ dev_warn(&pdev->dev, "mhi_cntrl->nr_irqs: %d\n",
mhi_cntrl->nr_irqs);
+ dev_warn(&pdev->dev, "PCI_IRQ_MSI: %d\n", PCI_IRQ_MSI);
nr_vectors = pci_alloc_irq_vectors(pdev, 1, mhi_cntrl->nr_irqs,
PCI_IRQ_MSI);
+ dev_warn(&pdev->dev, "nr_vectors: %d\n", nr_vectors);
if (nr_vectors < 0) {
dev_err(&pdev->dev, "Error allocating MSI vectors %d\n",
nr_vectors);
Compiling and loading that module prints the following in dmesg:
[ 5553.096754] mhi-pci-generic 0000:08:00.0: BAR 0: assigned [mem
0xbc200000-0xbc200fff 64bit]
[ 5553.097033] mhi-pci-generic 0000:08:00.0: mhi_cntrl_config->num_events: 4
[ 5553.097036] mhi-pci-generic 0000:08:00.0: mhi_cntrl->nr_irqs: 5
[ 5553.097038] mhi-pci-generic 0000:08:00.0: PCI_IRQ_MSI: 2
[ 5553.097314] mhi-pci-generic 0000:08:00.0: nr_vectors: 1 <- requested 5,
got 1..
[ 5553.097316] mhi-pci-generic 0000:08:00.0: using shared MSI
requesting 5 nr_vectors, getting one which then seems to trigger another
codepath..
Whlie researching pci_alloc_irq_vectors I then found this semi-related
thread
https://stackoverflow.com/questions/49821599/multiple-msi-vectors-linux-pci-alloc-irq-vectors-return-one-while-the-devi
where Riton38 mentions that enabling intel vt-d "solved the problem"
(default from factory on this Thinkpad X1 Nano it has all virtualization
disabled).
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, *it works!!*
[ 81.291874] mhi_pci_generic: loading out-of-tree module taints kernel.
[ 81.291970] mhi_pci_generic: module verification failed: signature
and/or required key missing - tainting kernel
[ 81.292527] mhi-pci-generic 0000:08:00.0: BAR 0: assigned [mem
0xbc200000-0xbc200fff 64bit]
[ 81.292560] mhi-pci-generic 0000:08:00.0: enabling device (0000 -> 0002)
[ 81.292603] mhi-pci-generic 0000:08:00.0: mhi_cntrl_config->num_events: 4
[ 81.292605] mhi-pci-generic 0000:08:00.0: mhi_cntrl->nr_irqs: 5
[ 81.292606] mhi-pci-generic 0000:08:00.0: PCI_IRQ_MSI: 2
[ 81.292713] mhi-pci-generic 0000:08:00.0: nr_vectors: 5 <- *We got 5
vectors now!*
[ 81.292955] mhi mhi0: Requested to power ON
[ 81.293180] mhi mhi0: Power on setup success
[ 81.325854] mhi mhi0: Wait for device to enter SBL or Mission mode
After running qmicli and connecting, no more errors in kernel log.
oskar@oskar-ThinkPad-X1-Nano-Gen-1:~/src/linux-kernel/linux-upstream-5.12.0+/drivers/bus/mhi$
ping ftp.sunet.se
PING ftp.sunet.se(tutankhamon.ftp.acc.umu.se (2001:6b0:19::163)) 56 data
bytes
64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163): icmp_seq=1
ttl=51 time=46.1 ms
64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163): icmp_seq=2
ttl=51 time=43.9 ms
64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163): icmp_seq=3
ttl=51 time=42.7 ms
64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163): icmp_seq=4
ttl=51 time=49.0 ms
^C
--- ftp.sunet.se ping statistics ---
4 packets transmitted, 4 received, 0% packet loss, time 3005ms
rtt min/avg/max/mdev = 42.708/45.419/49.019/2.404 ms
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)
https://www.speedtest.net/result/11435773983
Anything i can do to test / debug interrupts without intel vt-d enabled
while I have this fresh in memory?
/Oskar Stenman
On Mon, 17 May 2021 at 12:53, Oskar Stenman <os...@cetex.se> wrote:
> Hi!
>
> CPU0 CPU1 CPU2 CPU3 CPU4 CPU5
> CPU6 CPU7
> 143: 0 0 0 0 0 6
> 0 192 PCI-MSI 4194304-edge bhi, mhi, mhi, mhi, mhi
>
> Attaching files with full /proc/interrupts and made a small script with
> timestamps / logging to see what happens in chronological order.
>
> /Oskar
>
>
> On Mon, 17 May 2021 at 11:27, Loic Poulain <loic.poul...@linaro.org>
> wrote:
>
>> Hi Oskar,
>>
>> On Wed, 12 May 2021 at 11:10, Oskar Stenman <os...@cetex.se> wrote:
>> >
>> > On Wed, 12 May 2021 at 09:35, Aleksander Morgado <
>> aleksan...@aleksander.es> wrote:
>> >>
>> >> Or even easier; just completely skip the name of the port and create a
>> >> generic "gsm" connection setting not bound to any specific device.
>> >>
>> >> $ nmcli conn add type gsm con-name wwan gsm.apn data.tre.se gsm.pin
>> 7470
>> >
>> >
>> > 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.
>> > Reinstalled Network-Manager and it put the file back and it detects the
>> interface.
>> >
>> > oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ nmcli conn up wwan
>> > Connection successfully activated (D-Bus active path:
>> /org/freedesktop/NetworkManager/ActiveConnection/399)
>> >
>> > (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)
>> >
>> > 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)
>> >
>> > 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..)
>> > oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ sudo qmicli -p -d
>> /dev/wwan0p2MBIM --device-open-mbim --dms-dell-cuskit-unlock=00
>> > [sudo] password for oskar:
>> > [12 maj 2021, 10:15:43] -Warning ** [/dev/wwan0p2MBIM] couldn't detect
>> transport type of port: couldn't detect device driver
>> > [12 maj 2021, 10:15:43] -Warning ** [/dev/wwan0p2MBIM] requested MBIM
>> mode but unexpected transport type found
>> > [/dev/wwan0p2MBIM] Successfully run Dell cuskit unlock
>> > oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ sudo service ModemManager start
>> > oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ nmcli conn up wwan
>> > Connection successfully activated (D-Bus active path:
>> /org/freedesktop/NetworkManager/ActiveConnection/2)
>> > oskar@oskar-ThinkPad-X1-Nano-Gen-1:~$ ping ftp.sunet.se
>> > PING ftp.sunet.se(tutankhamon.ftp.acc.umu.se (2001:6b0:19::163)) 56
>> data bytes
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=1 ttl=51 time=57.6 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=2 ttl=51 time=1055 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=3 ttl=51 time=1053 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=4 ttl=51 time=1051 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=5 ttl=51 time=1049 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=6 ttl=51 time=1048 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=7 ttl=51 time=1046 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=8 ttl=51 time=1045 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=9 ttl=51 time=1042 ms
>> > 64 bytes from tutankhamon.ftp.acc.umu.se (2001:6b0:19::163):
>> icmp_seq=10 ttl=51 time=1041 ms
>> > ^C
>> > --- ftp.sunet.se ping statistics ---
>> > 11 packets transmitted, 10 received, 9.09091% packet loss, time 10016ms
>> > rtt min/avg/max/mdev = 57.648/948.772/1055.277/297.071 ms, pipe 2
>> >
>> > So we have data!
>> > But i see messages like this in dmesg:
>> > [ 254.970231] __common_interrupt: 3.34 No irq handler for vector
>> > [ 255.098499] __common_interrupt: 3.34 No irq handler for vector
>> >
>> > With that ~1s latency I'm guessing something resorts to polling instead
>> of triggering on interrupts?
>>
>> Weird, can you share the output of `cat /proc/interrupts | grep mhi`.
>>
>> Regards,
>> Loic
>>
>
_______________________________________________
ModemManager-devel mailing list
ModemManager-devel@lists.freedesktop.org
https://lists.freedesktop.org/mailman/listinfo/modemmanager-devel
