Re: [PATCH v2 2/4] driver core: enable drivers to use deferred probe from init

[Takashi Iwai <tiwai@suse.de>]

At Sun, 10 Aug 2014 16:58:02 +0200,
Luis R. Rodriguez wrote:
> 
> On Sun, Aug 10, 2014 at 08:43:31PM +0800, Greg KH wrote:
> > On Sat, Aug 09, 2014 at 06:41:19PM +0200, Luis R. Rodriguez wrote:
> > > On Wed, Jul 30, 2014 at 03:11:07PM -0700, David Miller wrote:
> > > > From: "Luis R. Rodriguez" <mcgrof@do-not-panic.com>
> > > > Date: Mon, 28 Jul 2014 11:28:28 -0700
> > > > 
> > > > > Tetsuo bisected and found that commit 786235ee "kthread: make
> > > > > kthread_create() killable" modified kthread_create() to bail as
> > > > > soon as SIGKILL is received. This is causing some issues with
> > > > > some drivers and at times boot. Joseph then found that failures
> > > > > occur as the systemd-udevd process sends SIGKILL to modprobe if
> > > > > probe on a driver takes over 30 seconds. When this happens probe
> > > > > will fail on any driver, its why booting on some system will fail
> > > > > if the driver happens to be a storage related driver. Some folks
> > > > > have suggested fixing this by modifying kthread_create() to not
> > > > > leave upon SIGKILL [3], upon review Oleg rejected this change and
> > > > > the discussion was punted out to systemd to see if the default
> > > > > timeout could be increased from 30 seconds to 120. The opinion of
> > > > > the systemd maintainers is that the driver's behavior should
> > > > > be fixed [4]. Linus seems to agree [5], however more recently even
> > > > > networking drivers have been reported to fail on probe since just
> > > > > writing the firmware to a device and kicking it can take easy over
> > > > > 60 seconds [6]. Benjamim was able to trace the issues recently
> > > > > reported on cxgb4 down to the same systemd-udevd 30 second timeout [6].
> > > > > 
> > > > > This is an alternative solution which enables drivers that are
> > > > > known to take long to use deferred probe workqueue. This avoids
> > > > > the 30 second timeout and lets us annotate drivers with long
> > > > > init sequences.
> > > > > 
> > > > > As drivers determine a component is not yet available and needs
> > > > > to defer probe you'll be notified this happen upon init for each
> > > > > device but now with a message such as:
> > > > > 
> > > > > pci 0000:03:00.0: Driver cxgb4 requests probe deferral on init
> > > > > 
> > > > > You should see one of these per struct device probed.
> > > > 
> > > > It seems we're still discussing this.
> > > > 
> > > > I think I understand all of the underlying issues, and what I'll say
> > > > is that perhaps we should use what Greg KH requested but via a helper
> > > > that is easy to grep for.
> > > > 
> > > > I don't care if it's something like "module_long_probe_init()" and
> > > > "module_long_probe_exit()", but it just needs to be some properly
> > > > named interface which does the whole kthread or whatever bit.
> > > 
> > > I've tested the alternative kthread_run() proposal but unfortunately it
> > > does not help resolve the issue, the timeout is still hit and a SIGKILL
> > > still kills the driver probe. Please let me know how you'd all like us
> > > to proceed, these defer probe patches do help cure the issue though.
> > 
> > Why doesn't it work?  Doesn't modprobe come right back and the init
> > sequence still takes a while to run?  What exactly fails?
> 
> systemd uses kmod kmod_module_probe_insert_module(), what I see is that using
> kthread_run() as a work around still causes probe to fail on a driver that
> otherwise would work fine if all you do is sprinkle ssleep(33) (seconds) on the
> init sequence. To see the issue you can test this on any of your network
> drivers that get loaded automatically, I did my testing with iwlwifi by
> purposely breaking it and then using the work around. It seems the probe
> somehow still gets killed as before, I haven't debugged this further.
> 
> For example by breaking and fixing iwlwifi this yields:
> 
> ergon:~ # journalctl -b -0 -u systemd-udevd 
> 
> -- Logs begin at Mon 2014-08-04 21:55:28 EDT, end at Sun 2014-08-10 10:50:14 EDT. --
> Aug 10 10:48:49 ergon systemd-udevd[257]: specified group 'input' unknown
> Aug 10 10:48:55 ergon mtp-probe[493]: checking bus 3, device 2: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-7"
> Aug 10 10:48:55 ergon mtp-probe[492]: checking bus 3, device 4: "/sys/devices/pci0000:00/0000:00:14.0/usb3/3-12"
> Aug 10 10:49:24 ergon systemd-udevd[465]: seq 1755 '/devices/pci0000:00/0000:00:1c.1/0000:03:00.0' killed
> 
> ergon:~ # dmesg | grep iwlwifi
> [   10.315538] iwlwifi Going to sleep for 33 seconds
> [   43.323958] iwlwifi Done sleeping
> [   43.324400] iwlwifi 0000:03:00.0: irq 50 for MSI/MSI-X
> [   43.324534] iwlwifi 0000:03:00.0: Error allocating IRQ 50
> [   43.326951] iwlwifi: probe of 0000:03:00.0 failed with error -4
> 
> The patch used:
> 
> diff --git a/drivers/net/wireless/iwlwifi/mvm/ops.c b/drivers/net/wireless/iwlwifi/mvm/ops.c
> index 610dbcb..65e0ab2 100644
> --- a/drivers/net/wireless/iwlwifi/mvm/ops.c
> +++ b/drivers/net/wireless/iwlwifi/mvm/ops.c
> @@ -63,6 +63,7 @@
>  #include <linux/module.h>
>  #include <linux/vmalloc.h>
>  #include <net/mac80211.h>
> +#include <linux/kthread.h>
>  
>  #include "iwl-notif-wait.h"
>  #include "iwl-trans.h"
> @@ -111,7 +112,7 @@ MODULE_PARM_DESC(power_scheme,
>  /*
>   * module init and exit functions
>   */
> -static int __init iwl_mvm_init(void)
> +static int iwl_mvm_init_real(void *arg)
>  {
>  	int ret;
>  
> @@ -130,12 +131,21 @@ static int __init iwl_mvm_init(void)
>  
>  	return ret;
>  }
> +
> +static struct task_struct *init_thread;
> +
> +static int __init iwl_mvm_init(void)
> +{
> +	init_thread = kthread_run(iwl_mvm_init_real, NULL, "iwl_mvm_init");
> +	return 0;
> +}
>  module_init(iwl_mvm_init);
>  
>  static void __exit iwl_mvm_exit(void)
>  {
>  	iwl_opmode_deregister("iwlmvm");
>  	iwl_mvm_rate_control_unregister();
> +	kthread_stop(init_thread);
>  }
>  module_exit(iwl_mvm_exit);
>  
> diff --git a/drivers/net/wireless/iwlwifi/pcie/drv.c b/drivers/net/wireless/iwlwifi/pcie/drv.c
> index 98950e4..c1f2823 100644
> --- a/drivers/net/wireless/iwlwifi/pcie/drv.c
> +++ b/drivers/net/wireless/iwlwifi/pcie/drv.c
> @@ -489,6 +489,10 @@ static int iwl_pci_probe(struct pci_dev *pdev, const struct pci_device_id *ent)
>  	struct iwl_trans_pcie *trans_pcie;
>  	int ret;
>  
> +	printk("iwlwifi Going to sleep for 33 seconds\n");
> +	ssleep(33);
> +	printk("iwlwifi Done sleeping\n");
> +
>  	iwl_trans = iwl_trans_pcie_alloc(pdev, ent, cfg);
>  	if (IS_ERR(iwl_trans))
>  		return PTR_ERR(iwl_trans);
> 

I guess that the problem is that you moved the init stuff into kthread
for iwlmvm module, but the stall happens in a different module,
iwlwifi.  So iwlwifi is killed as expected.  You had to put the
kthread hack into pcie/drv.c instead.

(Actually, it's interesting how the SIGKILL error is reported back;
 it failed at request_threaded_irq().  If this were the normal irq
 handler, it might have worked :)


Takashi