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

[Niklas Cassel <Niklas.Cassel@xxxxxxx>]

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
> <bigeasy@xxxxxxxxxxxxx> 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:

[    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