Bug 195477 - firmware_class: loading the same file multiple times in parallel finishes only one
Summary: firmware_class: loading the same file multiple times in parallel finishes onl...
Alias: None
Product: Other
Classification: Unclassified
Component: Other (show other bugs)
Hardware: Intel Linux
: P1 blocking
Assignee: Luis Chamberlain
Depends on:
Reported: 2017-04-20 23:43 UTC by Nicolas
Modified: 2019-05-23 05:31 UTC (History)
7 users (show)

See Also:
Kernel Version: Linux 4.4.0-72-generic ( Ubuntu 16 ), 4.11
Tree: Mainline
Regression: No

A tgz of 3 png that show log output (405.03 KB, application/gzip)
2017-04-20 23:43 UTC, Nicolas
Dmesg (147.01 KB, text/plain)
2017-04-26 15:22 UTC, Nicolas
ifconfig -a (2.45 KB, text/plain)
2017-04-26 15:23 UTC, Nicolas
Patch to print a log in iwlwifi's probe (963 bytes, application/mbox)
2017-04-27 09:15 UTC, Luca Coelho
LSPCI Logs after Patch (2.57 KB, text/plain)
2017-05-09 14:44 UTC, Nicolas
DMESG After Patch (57.26 KB, text/plain)
2017-05-09 14:44 UTC, Nicolas
After Patch custom Logs (59.36 KB, text/plain)
2017-05-09 16:27 UTC, Nicolas
patch to delay request_fw (1.36 KB, application/mbox)
2017-05-10 09:45 UTC, Luca Coelho
DMSG with 500ms delay (70.39 KB, text/plain)
2017-05-10 15:07 UTC, Nicolas
possible patch for firmware_class.c (1.06 KB, patch)
2017-05-12 20:35 UTC, John Ewalt
Details | Diff

Description Nicolas 2017-04-20 23:43:36 UTC
Created attachment 255941 [details]
A tgz of 3 png that show log output

With multiple wifi cards plugged in the system will only enumerate the correct capabilities 50% of the time. If you boot the system and run ifconfig it is not guaranteed that all wifi devices show up. 

1.) Step One Plug 2+ 6260 Wifi cards into a system. ( Directly onto system motherboard)
2.) Boot the device
3.) Run Ifconfig ( You will either see 1 wireless interface or all of them) It is random
4.) If all wifi cards are there the reboot and check again

The attachments show the output of commands with 4 wifi cards plugged in. 
ifconfig only shows 1 wifi card
lspci shows all 4
lshw -C network shows 4 wifi cards. 1 has the correct capabilities and 3 have incorrect capabilities.
Comment 1 Luca Coelho 2017-04-26 06:33:42 UTC
Can you please provide dmesg?
Comment 2 Luca Coelho 2017-04-26 06:39:35 UTC
Also, can you please paste the results of the following commands?

ifconfig -a

iw dev
Comment 3 Nicolas 2017-04-26 15:22:52 UTC
Created attachment 256073 [details]
Comment 4 Nicolas 2017-04-26 15:23:13 UTC
Created attachment 256075 [details]
ifconfig -a
Comment 5 Nicolas 2017-04-26 15:23:59 UTC
I added dmesg and ifconfig -a attachments. Note that there is also a intel ln930 on the system. That accounts for the wwp0s20u2 device.
Comment 6 Nicolas 2017-04-26 16:06:28 UTC
One more update. We tried the same configuration with the 7260. Everything works fine. This seems to only be an issue with the 8260.
Comment 7 Nicolas 2017-04-26 23:26:10 UTC
Correction on the original bug posting. The problem is with the 8260 not 6260
Comment 8 Luca Coelho 2017-04-27 06:39:03 UTC
(In reply to Nicolas from comment #7)
> Correction on the original bug posting. The problem is with the 8260 not 6260

Yes, I noticed. :) That's why I used "8260" in the title.
Comment 9 Luca Coelho 2017-04-27 07:02:21 UTC
This is a very strange issue... I can clearly see the devices being found at the PCI level:

[    0.160229] pci 0000:03:00.0: [8086:24f3] type 00 class 0x028000
[    0.167352] pci 0000:05:00.0: [8086:24f3] type 00 class 0x028000
[    0.175391] pci 0000:08:00.0: [8086:24f3] type 00 class 0x028000
[    0.167352] pci 0000:05:00.0: [8086:24f3] type 00 class 0x028000

But later on I just see the iwlwifi driver reacting to one of them:

[    2.659223] iwlwifi 0000:03:00.0: loaded firmware version 16.242414.0 op_mode iwlmvm

Unfortunately we don't have any traces at the probe level in iwlwifi.  I'll provide you with a patch to add some traces there to check whether it's getting that far.
Comment 10 Luca Coelho 2017-04-27 07:20:44 UTC
Can you try to "remove" one of the devices that didn't show up and then rescan the PCI devices, like this:

echo 1 > /sys/bus/pci/devices/0000\:05\:00.0/remove

...wait a while then:

echo 1 > /sys/bus/pci/rescan

...and post dmesg again?
Comment 11 Luca Coelho 2017-04-27 09:15:15 UTC
Created attachment 256091 [details]
Patch to print a log in iwlwifi's probe

Can you apply this patch and run this scenario again so we can check whether the probe is getting to the iwlwifi driver?
Comment 12 Nicolas 2017-05-09 14:44:25 UTC
Created attachment 256325 [details]
LSPCI Logs after Patch
Comment 13 Nicolas 2017-05-09 14:44:44 UTC
Created attachment 256327 [details]
DMESG After Patch
Comment 14 Nicolas 2017-05-09 14:45:56 UTC
I am sorry for the delay in getting this done. We applied the patch and uploaded the logs. The driver is definitely getting through the probe. We started adding other logs to see if we can help narrow down the issue.
Comment 15 Luca Coelho 2017-05-09 15:49:35 UTC
Thanks for the logs!

Indeed we're getting probed but then not handling those other devices... I'll try to reproduce it locally to see if I can figure something out.
Comment 16 Nicolas 2017-05-09 16:27:51 UTC
Created attachment 256331 [details]
After Patch custom Logs
Comment 17 Nicolas 2017-05-09 16:29:04 UTC
Thank you and one more log for you.

We see it trying the multiple firmware versions for each of the cards. However, once it finds one that works for one of the cards, it stops trying for the remaining cards.
Comment 18 Luca Coelho 2017-05-09 17:04:51 UTC
Interesting.  But this didn't happen in the previous logs, did anything change?

Maybe this time it stopped working for the other NICs a bit later, so it still requests the first FW version and then stops.

OTOH, it's quite possible that the firmware loading code is what is causing this issue.  I'll look into that.
Comment 19 Luca Coelho 2017-05-10 09:19:01 UTC
Looked a bit further and tried to reproduce here, without success.

This definitely seems to be some sort of race condition with the request_firmware_nowait() API... Our driver is calling it for all the 4 NICs (as you mentioned), but only the callback for the first one is getting called.

BTW, in the first log (and with my tests), the iwlwifi driver gets probed very early withing seconds of booting, but in your latest logs it gets probed only ~16 seconds later... Did you change something in your system to cause this?
Comment 20 Luca Coelho 2017-05-10 09:45:09 UTC
Created attachment 256347 [details]
patch to delay request_fw

Can you try this patch? It's a very ugly hack to add 500 msecs delay multiplied by the request number.  This should give plenty of distance in time for each device being probed, so we can see if it's a race.
Comment 21 Luca Coelho 2017-05-10 10:51:12 UTC
Another way to check what is going on without having to recompile the modules is to check if there are any pending firmware requests by checking sysfs:

ls -l /sys/class/firmware

This should have a list of devices that have pending firmware requests.

Also, you could check if the iwlwifi driver still has those devices instantiated:

ls -l /sys/modules/iwlwifi/devices

Please run these commands after booting and post the results.
Comment 22 Nicolas 2017-05-10 15:06:43 UTC
We applied the patch. We changed it to be 500ms between each and it worked. All 4 wifi cards appear every time. The logs are attached. 

/sys/class/firmware doesn’t exist.
Neither does /sys/module/iwlwifi/devices
/sys/module/iwlwifi/refcnt is 4
/sys/module/iwlwifi/driver/pci:iwlwifi has links to all 4 devices

ls -l /sys/modules/iwlwifi/devices
Comment 23 Nicolas 2017-05-10 15:07:16 UTC
Created attachment 256363 [details]
DMSG with 500ms delay
Comment 24 Luca Coelho 2017-05-10 15:32:20 UTC
Cool! Yeah, I guess any delay there would work... I probably exaggerated in multiplying it.  Maybe even less, like 100 msecs works, dunno.

Strange that the /sys/class/firmware/ directory doesn't exist! It should be there since that's where the userspace pushes the files for the kernel to get.

Can you run those ls commands again *without* the delay? Just to be sure that the requests are indeed pending at that point.

So this indeed seems to be a race somewhere... Maybe systemd-udev (which I assume you are using) loses some of the events the kernel sends? It may be a good idea to get some udev logs...
Comment 25 John Ewalt 2017-05-10 17:21:45 UTC
Hi Luca,  I'm working with Nic on this issue.  I have tried looking for /sys/class/firmware on the original kernel and the modified one and it does not exist for either.

The timing difference (16 seconds into dmesg instead of a few seconds) is due to a change in using TPM.  I now have to manually enter the WDE passphrase so it takes a few more seconds to boot.

Can you give me some pointers on enabling systemd-udevd debug?
Comment 26 Luca Coelho 2017-05-10 18:39:48 UTC
Odd, I'll try to see if the /sys/class/firmware/ thing can be in a different place.

You can use this: 

udevadm control -l 7

To increase the loglevel in udev.  It will then print a bunch of stuff to your /var/log/syslog.  I'm definitely not an expert in udev, though, so I'm not sure I will be able to help read it.
Comment 27 John Ewalt 2017-05-10 19:02:22 UTC
With udev debugging enabled, I don't see any udev messaging between the probe and the firmware loading.  

I see udevd messages about 'inserting' iwlwifi and passing the device to netlink monitor followed by the probing of all 4 devices.  

The firmware is loaded for 4 all devices and then I see more unrelated udev stuff.
Comment 28 John Ewalt 2017-05-11 18:39:50 UTC
Ok, I have done a bit more debugging and udev does not come into play here.  I think what is happening is the request_firmware is put in a work queue and multiple requests for the same firmware are serialized.  Since we are looking for several files that don't exist (version 28-version 22) the first request loads but subsequent requests are put in a wait queue until the first request is either aborted or done.  

I have tried a few changes in this area of code (firmware_class.c) but I have not found the bug yet.  One change that seems to make sense is to move the fw_state_done() call in fw_get_filesystem_firmware() to just before the return.  Regardless of the reason, we are done with the file at this point.

I am going to keep playing with this.  If you need more information or want logs, please ask.
Comment 29 John Ewalt 2017-05-12 20:34:38 UTC
I think I may have a solution.  What I am seeing is in firmware_class.c, when multiple driver instances are waiting on the same firmware file they will all  be put in a swait queue.  When the file is loaded into the firmware cache, it is marked as done which should release the other waiting instances.  It does this but only for the first instance since the firmware will not be reloaded from the filesystem, it is never marked as "DONE" again so the rest of the instances stay in the swait queue.  

A small change to __fw_state_set() in firmware_class.c to swake_up_all() instead of just swake_up() will fix the problem and modifying the fw_get_filesystem_firmware() function to mark the firmware as done or aborted will ensure that swakup_all() gets called when it should.

A patch will be attached soon.
Comment 30 John Ewalt 2017-05-12 20:35:31 UTC
Created attachment 256493 [details]
possible patch for firmware_class.c
Comment 31 John Ewalt 2017-05-16 18:08:30 UTC
I see that the title of this has been changed.  Is there anything else I can provide to help move this along?  

Please let me know.
Comment 32 Luis Chamberlain 2017-05-24 19:14:01 UTC
I'm looking at this now.
Comment 33 Luis Chamberlain 2017-05-24 22:02:16 UTC
(In reply to John Ewalt from comment #30)
> Created attachment 256493 [details]
> possible patch for firmware_class.c

The changes you propose make sense!

However can you please split them apart, identify which commit caused each issue, draw up with easy language to explain the impact of the issue and what each patch fixes ?

As an example of types of enhancements to the commit needed which I'd like to see refer to a recent fix proposed also for firmware_class [0], after some good review of its impact this changed to be very descriptive [1] including references to the commits which the patch provides a fix for. For instance just the swake_up_all() change seems to one atomic change and you can supply a Fixes: 5b029624948d68 ("firmware: do not use fw_lock for fw_state protection") tag.

$ git describe --contains 5b029624948d6864053166da1263df74c0c443df

So this fix alone should be merged on >= 4.10. You can see how I referred to a fix applicable to a stable kernel on the 2nd iteration fix above [1].

The other changes should be split off as well and similar work should be done.

Once done please feel free to send these patches to me and Cc the others I Cc'd in the recent patch I Cc'd you on.

Bonus points if we are able to draw up test cases for these issues into the driver data API [2] on the lib/test_driver_data.c. As I noted recently to Yi Li, we *don't yet* have a way to flex the cache infrastructure but it should be fairly easy to add a debugfs interface to let test this [3].

As I also noted on that thread, this particular issue on this bug report however spans the cache infrastructure since as you very noted two pending requests for the same file can end up being serialized. Upon a glance it would seem we actually have *dozens* of other error cases which we do not wake up pending callers for on failure, and these issues have been lingering in the kernel for ages. You seem to have addressed a few, but upon a glance I think we have many more to address. For this reason interface for this would help a lot.

I can help you along the way. If this is too much I understand as well, at the very least try to post patches split up and I can take it from there.

Also in the commit logs please refer to this bug entry.

[0] https://lkml.kernel.org/r/20170523131607.28138.12306.stgit@localhost
[1] https://lkml.kernel.org/r/20170524214027.7775-1-mcgrof@kernel.org
[2] https://git.kernel.org/pub/scm/linux/kernel/git/mcgrof/linux-next.git/log/?h=20170524-driver-data-stable
[3[ https://lkml.kernel.org/r/20170524190357.GB8951@wotan.suse.de
[4] https://lkml.kernel.org/r/20170524203246.GD8951@wotan.suse.de
Comment 34 John Ewalt 2017-05-24 23:11:22 UTC
I can split the patches and describe what I think each is doing but I am not sure I an do all that you ask.  

I will give it a shot tomorrow.

Thank you for looking into this.
Comment 35 Luis Chamberlain 2017-06-15 18:59:51 UTC
Poke? I haven't seen patches yet..
Comment 36 Nicolas 2017-06-15 19:01:46 UTC
I am sorry. We have to drop the effort to fix this due to time constraints.
Comment 37 Nicolas 2017-06-15 19:02:06 UTC
We may be able to revist in the future.

Note You need to log in before you can comment on or make changes to this bug.