LinuxLists.cc - [PATCH v1] driver core: Extend deferred probe timeout on driver registration

2022-04-30 13:00:23

Subject: [PATCH v1] driver core: Extend deferred probe timeout on driver registration

The deferred probe timer that's used for this currently starts at
late_initcall and runs for driver_deferred_probe_timeout seconds. The
assumption being that all available drivers would be loaded and
registered before the timer expires. This means, the
driver_deferred_probe_timeout has to be pretty large for it to cover the
worst case. But if we set the default value for it to cover the worst
case, it would significantly slow down the average case. For this
reason, the default value is set to 0.

Also, with CONFIG_MODULES=y and the current default values of
driver_deferred_probe_timeout=0 and fw_devlink=on, devices with missing
drivers will cause their consumer devices to always defer their probes.
This is because device links created by fw_devlink defer the probe even
before the consumer driver's probe() is called.

Instead of a fixed timeout, if we extend an unexpired deferred probe
timer on every successful driver registration, with the expectation more
modules would be loaded in the near future, then the default value of
driver_deferred_probe_timeout only needs to be as long as the worst case
time difference between two consecutive module loads.

So let's implement that and set the default value to 10 seconds when
CONFIG_MODULES=y.

Cc: Greg Kroah-Hartman <[email protected]>
Cc: "Rafael J. Wysocki" <[email protected]>
Cc: Rob Herring <[email protected]>
Cc: Linus Walleij <[email protected]>
Cc: Will Deacon <[email protected]>
Cc: Ulf Hansson <[email protected]>
Cc: Kevin Hilman <[email protected]>
Cc: Thierry Reding <[email protected]>
Cc: Mark Brown <[email protected]>
Cc: Pavel Machek <[email protected]>
Cc: Geert Uytterhoeven <[email protected]>
Cc: Yoshihiro Shimoda <[email protected]>
Cc: Paul Kocialkowski <[email protected]>
Cc: [email protected]
Cc: [email protected]
Cc: [email protected]
Signed-off-by: Saravana Kannan <[email protected]>
---
.../admin-guide/kernel-parameters.txt | 6 ++++--
drivers/base/base.h | 1 +
drivers/base/dd.c | 19 +++++++++++++++++++
drivers/base/driver.c | 1 +
4 files changed, 25 insertions(+), 2 deletions(-)

diff --git a/Documentation/admin-guide/kernel-parameters.txt b/Documentation/admin-guide/kernel-parameters.txt
index 7123524a86b8..fcc1dfc877a9 100644
--- a/Documentation/admin-guide/kernel-parameters.txt
+++ b/Documentation/admin-guide/kernel-parameters.txt
@@ -939,8 +939,10 @@
[KNL] Debugging option to set a timeout in seconds for
deferred probe to give up waiting on dependencies to
probe. Only specific dependencies (subsystems or
- drivers) that have opted in will be ignored. A timeout of 0
- will timeout at the end of initcalls. This option will also
+ drivers) that have opted in will be ignored. A timeout
+ of 0 will timeout at the end of initcalls. If the time
+ out hasn't expired, it'll be restarted by each
+ successful driver registration. This option will also
dump out devices still on the deferred probe list after
retrying.

diff --git a/drivers/base/base.h b/drivers/base/base.h
index 2882af26392a..ab71403d102f 100644
--- a/drivers/base/base.h
+++ b/drivers/base/base.h
@@ -159,6 +159,7 @@ extern char *make_class_name(const char *name, struct kobject *kobj);
extern int devres_release_all(struct device *dev);
extern void device_block_probing(void);
extern void device_unblock_probing(void);
+extern void deferred_probe_extend_timeout(void);

/* /sys/devices directory */
extern struct kset *devices_kset;
diff --git a/drivers/base/dd.c b/drivers/base/dd.c
index f47cab21430f..603379b5f9dd 100644
--- a/drivers/base/dd.c
+++ b/drivers/base/dd.c
@@ -255,7 +255,12 @@ static int deferred_devs_show(struct seq_file *s, void *data)
}
DEFINE_SHOW_ATTRIBUTE(deferred_devs);

+#ifdef CONFIG_MODULES
+int driver_deferred_probe_timeout = 10;
+#else
int driver_deferred_probe_timeout;
+#endif
+
EXPORT_SYMBOL_GPL(driver_deferred_probe_timeout);
static DECLARE_WAIT_QUEUE_HEAD(probe_timeout_waitqueue);

@@ -315,6 +320,20 @@ static void deferred_probe_timeout_work_func(struct work_struct *work)
}
static DECLARE_DELAYED_WORK(deferred_probe_timeout_work, deferred_probe_timeout_work_func);

+void deferred_probe_extend_timeout(void)
+{
+ /*
+ * If the work hasn't been queued yet or if the work expired, don't
+ * start a new one.
+ */
+ if (cancel_delayed_work(&deferred_probe_timeout_work)) {
+ schedule_delayed_work(&deferred_probe_timeout_work,
+ driver_deferred_probe_timeout * HZ);
+ pr_debug("Extended deferred probe timeout by %d secs\n",
+ driver_deferred_probe_timeout);
+ }
+}
+
/**
* deferred_probe_initcall() - Enable probing of deferred devices
*
diff --git a/drivers/base/driver.c b/drivers/base/driver.c
index 8c0d33e182fd..77a77b2095cd 100644
--- a/drivers/base/driver.c
+++ b/drivers/base/driver.c
@@ -177,6 +177,7 @@ int driver_register(struct device_driver *drv)
return ret;
}
kobject_uevent(&drv->p->kobj, KOBJ_ADD);
+ deferred_probe_extend_timeout();

return ret;
}
--
2.36.0.464.gb9c8b46e94-goog

2022-05-14 00:08:37

by Rob Herring (Arm)

[permalink] [raw]

Subject: Re: [PATCH v1] driver core: Extend deferred probe timeout on driver registration

On Fri, Apr 29, 2022 at 5:09 PM Saravana Kannan <[email protected]> wrote:
>
> The deferred probe timer that's used for this currently starts at
> late_initcall and runs for driver_deferred_probe_timeout seconds. The
> assumption being that all available drivers would be loaded and
> registered before the timer expires. This means, the
> driver_deferred_probe_timeout has to be pretty large for it to cover the
> worst case. But if we set the default value for it to cover the worst
> case, it would significantly slow down the average case. For this
> reason, the default value is set to 0.
>
> Also, with CONFIG_MODULES=y and the current default values of
> driver_deferred_probe_timeout=0 and fw_devlink=on, devices with missing
> drivers will cause their consumer devices to always defer their probes.
> This is because device links created by fw_devlink defer the probe even
> before the consumer driver's probe() is called.
>
> Instead of a fixed timeout, if we extend an unexpired deferred probe
> timer on every successful driver registration, with the expectation more
> modules would be loaded in the near future, then the default value of
> driver_deferred_probe_timeout only needs to be as long as the worst case
> time difference between two consecutive module loads.
>
> So let's implement that and set the default value to 10 seconds when
> CONFIG_MODULES=y.

We had to revert a non-zero timeout before (issue with NFS root IIRC).
Does fw_devlink=on somehow fix that?

Rob

2022-05-14 03:20:23

by Saravana Kannan

[permalink] [raw]

Subject: Re: [PATCH v1] driver core: Extend deferred probe timeout on driver registration

On Fri, May 13, 2022 at 6:58 AM Rob Herring <[email protected]> wrote:
>
> On Fri, Apr 29, 2022 at 5:09 PM Saravana Kannan <[email protected]> wrote:
> >
> > The deferred probe timer that's used for this currently starts at
> > late_initcall and runs for driver_deferred_probe_timeout seconds. The
> > assumption being that all available drivers would be loaded and
> > registered before the timer expires. This means, the
> > driver_deferred_probe_timeout has to be pretty large for it to cover the
> > worst case. But if we set the default value for it to cover the worst
> > case, it would significantly slow down the average case. For this
> > reason, the default value is set to 0.
> >
> > Also, with CONFIG_MODULES=y and the current default values of
> > driver_deferred_probe_timeout=0 and fw_devlink=on, devices with missing
> > drivers will cause their consumer devices to always defer their probes.
> > This is because device links created by fw_devlink defer the probe even
> > before the consumer driver's probe() is called.
> >
> > Instead of a fixed timeout, if we extend an unexpired deferred probe
> > timer on every successful driver registration, with the expectation more
> > modules would be loaded in the near future, then the default value of
> > driver_deferred_probe_timeout only needs to be as long as the worst case
> > time difference between two consecutive module loads.
> >
> > So let's implement that and set the default value to 10 seconds when
> > CONFIG_MODULES=y.
>
> We had to revert a non-zero timeout before (issue with NFS root IIRC).
> Does fw_devlink=on somehow fix that?

If it's the one where ip autoconfig was timing out, then John Stultz
fixed it by fixing wait_for_device_probe().
https://lore.kernel.org/all/[email protected]/

If you are referring to some other issue, then I'd need more details.

-Saravana

2022-05-14 04:07:26

On Sun, May 29, 2022 at 1:34 AM 'Niklas Cassel' via kernel-team
<[email protected]> wrote:
>
> On Wed, May 25, 2022 at 12:49:00PM -0700, Saravana Kannan wrote:
> > On Wed, May 25, 2022 at 12:12 AM Sebastian Andrzej Siewior
> > <[email protected]> wrote:
> > >
> > > On 2022-05-24 10:46:49 [-0700], Saravana Kannan wrote:
> > > > > Removing probe_timeout_waitqueue (as suggested) or setting the timeout
> > > > > to 0 avoids the delay.
> > > >
> > > > In your case, I think it might be working as intended? Curious, what
> > > > was the call stack in your case where it was blocked?
> > >
> > > Why is then there 10sec delay during boot? The backtrace is
> > > |------------[ cut here ]------------
> > > |WARNING: CPU: 4 PID: 1 at drivers/base/dd.c:742 wait_for_device_probe+0x30/0x110
> > > |Modules linked in:
> > > |CPU: 4 PID: 1 Comm: swapper/0 Not tainted 5.18.0-rc5+ #154
> > > |RIP: 0010:wait_for_device_probe+0x30/0x110
> > > |Call Trace:
> > > | <TASK>
> > > | prepare_namespace+0x2b/0x160
> > > | kernel_init_freeable+0x2b3/0x2dd
> > > | kernel_init+0x11/0x110
> > > | ret_from_fork+0x22/0x30
> > > | </TASK>
> > >
> > > Looking closer, it can't access init. This in particular box boots
> > > directly the kernel without an initramfs so the kernel later mounts
> > > /dev/sda1 and everything is good. So that seems to be the reason…
> >
>
> Hello there,
>
> My (QEMU) boot times were recently extended by 10 seconds.
> Looking at the timestamps, it looks like nothing is being done for 10 whole
> seconds.
>
> A git bisect landed me at the patch in $subject:
> 2b28a1a84a0e ("driver core: Extend deferred probe timeout on driver registration")
>
> Adding a WARN_ON(1) in wait_for_device_probe(), as requested by the patch
> author from the others seeing a regression with this patch, gives two different
> stacktraces during boot:

Thanks for the report. My patch was exposing an existing issue. I
already sent a fix for that a few days ago. Waiting for it to get
picked up.

-Saravana

>
> [ 0.459633] printk: console [netcon0] enabled
> [ 0.459636] printk: console [netcon0] printing thread started
> [ 0.459637] netconsole: network logging started
> [ 0.459896] cfg80211: Loading compiled-in X.509 certificates for regulatory database
> [ 0.460230] kworker/u8:6 (105) used greatest stack depth: 14744 bytes left
> [ 0.461031] cfg80211: Loaded X.509 cert 'sforshee: 00b28ddf47aef9cea7'
> [ 0.461077] platform regulatory.0: Direct firmware load for regulatory.db failed with error -2
> [ 0.461085] cfg80211: failed to load regulatory.db
> [ 0.461113] ALSA device list:
> [ 0.461116] No soundcards found.
> [ 0.461614] ------------[ cut here ]------------
> [ 0.461615] WARNING: CPU: 2 PID: 1 at drivers/base/dd.c:741 wait_for_device_probe+0x1a/0x160
> [ 0.485809] Modules linked in:
> [ 0.486089] CPU: 2 PID: 1 Comm: swapper/0 Not tainted 5.18.0-next-20220526-00004-g74f936013b08-dirty #20
> [ 0.486842] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
> [ 0.487707] RIP: 0010:wait_for_device_probe+0x1a/0x160
> [ 0.488103] Code: 00 e8 fa e4 b5 ff 8b 44 24 04 48 83 c4 08 5b c3 0f 1f 44 00 00 53 48 83 ec 30 65 48 8b 04 25 28 00 00 00 48 89 44 24 28 31 c0 <0f> 0b e8 1f ac 57 00 8b 15 f1 b3 24 01 85 d2 75 3d 48 c7 c7 60 2f
> [ 0.489539] RSP: 0000:ffff9c7900013ed8 EFLAGS: 00010246
> [ 0.489965] RAX: 0000000000000000 RBX: 0000000000000008 RCX: 0000000000000d02
> [ 0.490597] RDX: 0000000000000cc2 RSI: 0000000000000000 RDI: 000000000002e990
> [ 0.491181] RBP: 0000000000000214 R08: 000000000000000f R09: 0000000000000064
> [ 0.491788] R10: ffff9c7900013c6c R11: 0000000000000000 R12: ffff8964c0343640
> [ 0.492384] R13: ffffffff9e51791c R14: 0000000000000000 R15: 0000000000000000
> [ 0.492960] FS: 0000000000000000(0000) GS:ffff896637d00000(0000) knlGS:0000000000000000
> [ 0.493658] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 0.494501] CR2: 0000000000000000 CR3: 00000001ed20c001 CR4: 0000000000370ee0
> [ 0.495621] Call Trace:
> [ 0.496059] <TASK>
> [ 0.496266] ? init_eaccess+0x3b/0x76
> [ 0.496657] prepare_namespace+0x30/0x16a
> [ 0.497016] kernel_init_freeable+0x207/0x212
> [ 0.497407] ? rest_init+0xc0/0xc0
> [ 0.497714] kernel_init+0x16/0x120
> [ 0.498250] ret_from_fork+0x1f/0x30
> [ 0.498898] </TASK>
> [ 0.499307] ---[ end trace 0000000000000000 ]---
> [ 0.748413] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ 0.749053] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ 0.749461] ata2.00: ATA-7: QEMU HARDDISK, version, max UDMA/100
> [ 0.749470] ata2.00: 732 sectors, multi 16: LBA48 NCQ (depth 32)
> [ 0.749479] ata2.00: applying bridge limits
> [ 0.750915] ata4: SATA link down (SStatus 0 SControl 300)
> [ 0.752110] ata5: SATA link down (SStatus 0 SControl 300)
> [ 0.753424] ata6: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
> [ 0.754877] ata3: SATA link down (SStatus 0 SControl 300)
> [ 0.755342] ata1.00: ATA-7: QEMU HARDDISK, version, max UDMA/100
> [ 0.755377] ata1.00: 268435456 sectors, multi 16: LBA48 NCQ (depth 32)
> [ 0.755387] ata1.00: applying bridge limits
> [ 0.755486] ata6.00: ATA-7: QEMU HARDDISK, version, max UDMA/100
> [ 0.755492] ata6.00: 8388608 sectors, multi 16: LBA48 NCQ (depth 32)
> [ 0.755500] ata6.00: applying bridge limits
> [ 0.757330] ata1.00: configured for UDMA/100
> [ 0.757441] ata6.00: configured for UDMA/100
> [ 0.757505] ata2.00: configured for UDMA/100
> [ 0.758015] scsi 0:0:0:0: Direct-Access ATA QEMU HARDDISK ion PQ: 0 ANSI: 5
> [ 0.760542] sd 0:0:0:0: Attached scsi generic sg0 type 0
> [ 0.760669] sd 0:0:0:0: [sda] 268435456 512-byte logical blocks: (137 GB/128 GiB)
> [ 0.760778] sd 0:0:0:0: [sda] Write Protect is off
> [ 0.760787] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
> [ 0.760847] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> [ 0.760981] sd 0:0:0:0: [sda] Preferred minimum I/O size 512 bytes
> [ 0.761319] scsi 1:0:0:0: Direct-Access ATA QEMU HARDDISK ion PQ: 0 ANSI: 5
> [ 0.762808] sd 1:0:0:0: Attached scsi generic sg1 type 0
> [ 0.763004] sd 1:0:0:0: [sdb] 732 512-byte logical blocks: (375 kB/366 KiB)
> [ 0.763649] sd 1:0:0:0: [sdb] Write Protect is off
> [ 0.763661] sd 1:0:0:0: [sdb] Mode Sense: 00 3a 00 00
> [ 0.763965] sd 1:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> [ 0.764026] sd 1:0:0:0: [sdb] Preferred minimum I/O size 512 bytes
> [ 0.765923] scsi 5:0:0:0: Direct-Access ATA QEMU HARDDISK ion PQ: 0 ANSI: 5
> [ 0.767987] sd 5:0:0:0: Attached scsi generic sg2 type 0
> [ 0.768626] sd 5:0:0:0: [sdc] 8388608 512-byte logical blocks: (4.29 GB/4.00 GiB)
> [ 0.769909] sd 5:0:0:0: [sdc] Write Protect is off
> [ 0.769920] sd 5:0:0:0: [sdc] Mode Sense: 00 3a 00 00
> [ 0.770515] sd 1:0:0:0: [sdb] Attached SCSI disk
> [ 0.770900] sd 5:0:0:0: [sdc] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
> [ 0.771782] sd 5:0:0:0: [sdc] Preferred minimum I/O size 512 bytes
> [ 0.773900] sda: sda1 sda14 sda15
> [ 0.774499] sd 5:0:0:0: [sdc] Attached SCSI disk
> [ 0.774907] sd 0:0:0:0: [sda] Attached SCSI disk
> [ 1.084011] input: ImExPS/2 Generic Explorer Mouse as /devices/platform/i8042/serio1/input/input3
> [ 10.887350] md: Waiting for all devices to be available before autodetect
> [ 10.887395] md: If you don't use raid, use raid=noautodetect
> [ 10.887445] ------------[ cut here ]------------
> [ 10.887448] WARNING: CPU: 1 PID: 1 at drivers/base/dd.c:741 wait_for_device_probe+0x1a/0x160
> [ 10.893987] Modules linked in:
> [ 10.894314] CPU: 1 PID: 1 Comm: swapper/0 Tainted: G W 5.18.0-next-20220526-00004-g74f936013b08-dirty #20
> [ 10.895389] Hardware name: QEMU Standard PC (Q35 + ICH9, 2009), BIOS rel-1.16.0-0-gd239552ce722-prebuilt.qemu.org 04/01/2014
> [ 10.896590] RIP: 0010:wait_for_device_probe+0x1a/0x160
> [ 10.897215] Code: 00 e8 fa e4 b5 ff 8b 44 24 04 48 83 c4 08 5b c3 0f 1f 44 00 00 53 48 83 ec 30 65 48 8b 04 25 28 00 00 00 48 89 44 24 28 31 c0 <0f> 0b e8 1f ac 57 00 8b 15 f1 b3 24 01 85 d2 75 3d 48 c7 c7 60 2f
> [ 10.899269] RSP: 0000:ffff9c7900013ec8 EFLAGS: 00010246
> [ 10.899762] RAX: 0000000000000000 RBX: 0000000000000008 RCX: 0000000000000000
> [ 10.900424] RDX: 0000000000000000 RSI: ffffffff9d998089 RDI: 00000000ffffffff
> [ 10.901060] RBP: 0000000000000214 R08: 80000000ffffe1ca R09: ffff9c7900013ea8
> [ 10.901839] R10: 3fffffffffffffff R11: 0000000000000000 R12: ffff8964c0343640
> [ 10.902615] R13: ffffffff9e51791c R14: 0000000000000000 R15: 0000000000000000
> [ 10.903371] FS: 0000000000000000(0000) GS:ffff896637c80000(0000) knlGS:0000000000000000
> [ 10.904188] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 10.904721] CR2: 0000000000000000 CR3: 00000001ed20c001 CR4: 0000000000370ee0
> [ 10.905340] Call Trace:
> [ 10.905558] <TASK>
> [ 10.905739] md_run_setup+0x3c/0x6a
> [ 10.906036] prepare_namespace+0x35/0x16a
> [ 10.906391] kernel_init_freeable+0x207/0x212
> [ 10.906748] ? rest_init+0xc0/0xc0
> [ 10.907021] kernel_init+0x16/0x120
> [ 10.907312] ret_from_fork+0x1f/0x30
> [ 10.907617] </TASK>
> [ 10.907796] ---[ end trace 0000000000000000 ]---
> [ 10.908159] md: Autodetecting RAID arrays.
> [ 10.908160] md: autorun ...
> [ 10.908160] md: ... autorun DONE.
> [ 10.911301] EXT4-fs (sda1): INFO: recovery required on readonly filesystem
> [ 10.911303] EXT4-fs (sda1): write access will be enabled during recovery
> [ 11.038001] EXT4-fs (sda1): orphan cleanup on readonly fs
> [ 11.038466] EXT4-fs (sda1): 2 orphan inodes deleted
> [ 11.038475] EXT4-fs (sda1): recovery complete
> [ 11.053033] EXT4-fs (sda1): mounted filesystem with ordered data mode. Quota mode: none.
> [ 11.053074] VFS: Mounted root (ext4 filesystem) readonly on device 8:1.
> [ 11.053175] devtmpfs: mounted
> [ 11.061921] Freeing unused kernel image (initmem) memory: 1680K
> [ 11.061930] Write protecting the kernel read-only data: 24576k
> [ 11.071108] Freeing unused kernel image (text/rodata gap) memory: 2032K
> [ 11.073596] Freeing unused kernel image (rodata/data gap) memory: 924K
> [ 11.073609] Run /sbin/init as init process
>
>
> Kind regards,
> Niklas
>
> --
> To unsubscribe from this group and stop receiving emails from it, send an email to [email protected].
>