Re: [3.8-rc3 -> 3.8-rc4 regression] Re: [PATCH] module, async: async_synchronize_full() on module init iff async is used

From: Josh Hunt <joshhunt00@gmail.com>
To: Tejun Heo <tj@kernel.org>
Cc: Jonathan Nieder <jrnieder@gmail.com>,
	Linus Torvalds <torvalds@linux-foundation.org>,
	Ming Lei <ming.lei@canonical.com>,
	Alex Riesen <raa.lkml@gmail.com>,
	Alan Stern <stern@rowland.harvard.edu>,
	Jens Axboe <axboe@kernel.dk>,
	USB list <linux-usb@vger.kernel.org>,
	Linux Kernel Mailing List <linux-kernel@vger.kernel.org>,
	Arjan van de Ven <arjan@linux.intel.com>,
	Rusty Russell <rusty@rustcorp.com.au>
Subject: Re: [3.8-rc3 -> 3.8-rc4 regression] Re: [PATCH] module, async: async_synchronize_full() on module init iff async is used
Date: Tue, 26 Nov 2013 15:29:30 -0600	[thread overview]
Message-ID: <CAKA=qzY5NBZSv8r9sHqX-3fY-yrSXq26zPM1AvjoANaZkqJavQ@mail.gmail.com> (raw)
In-Reply-To: <20130812150900.GJ15892@htj.dyndns.org>

[-- Attachment #1: Type: text/plain, Size: 2143 bytes --]

On Mon, Aug 12, 2013 at 10:09 AM, Tejun Heo <tj@kernel.org> wrote:
> Hello, Jonathan.
>
> On Mon, Aug 12, 2013 at 12:04:11AM -0700, Jonathan Nieder wrote:
>> My laptop fails to boot[1] with the message 'Volume group "data" not
>> found'.  Bisects to v3.8-rc4~17 (the above commit).  Reverting that
>> commit on top of current "master" (d92581fcad18, 2013-08-10) produces
>> a working kernel.  dmesg output from that working kernel attached.
>> More details, including .config, at [2].
>>
>> Any ideas for tracking this down?
>
> Which initrd / boot script are you using?  It looks like lvm assemble
> scripts are running before sdX are detected leading to volume assembly
> failure.  Before the patch, any module loading would end up
> synchronizing async probes but after the patch modprobe invocations
> which don't schedule them won't be.  Does your boot script happen to
> run multiple modprobes in parallel and proceed to configure lvm
> without waiting for modprobes of libata drivers to finish?
>
> Thanks.
>
> --
> tejun
> --
> To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html
> Please read the FAQ at  http://www.tux.org/lkml/

I'm also hitting a regression b/c of this patch. Booting 3.10.20 on a
number of older machines with onboard sata controllers are unable to
find their root device quickly enough. I bisected the issue down to
774a1221e862b343388347bac9b318767336b20b. Reverting it allows my
systems to boot fine. I'm seeing this with both sata_svw and ahci. I'm
using ubuntu precise userspace which is using initramfs-tools
0.99ubuntu13.1. From what I can tell the modprobes in this initrd are
done in serial, but the port probing is async. This allows init to
continue on to try and mount root, but it's not there yet.

I'm attaching some serial log output with initcall_debug enabled.

Both ahci and sata_svw call ata_host_activate(), which call
ata_host_register() and async_schedule(async_port_probe, ap).

Let me know what other information you may need.
Thanks

-- 
Josh

[-- Attachment #2: seriallog --]
[-- Type: application/octet-stream, Size: 5990 bytes --]

[    8.206940] async_waiting @ 1
[    8.210057] async_continuing @ 1 after 1 usec
[    8.215144] Freeing unused kerel memory: 1124k freed
[    8.281234] calling  ata_init+0x0/0x3de [libata] @ 1264
[    8.286615] ACPI: bus type ATA registered
[    8.298160] libata version 3.00 loaded.
[    8.302162] initcall ata_init+0x0/0x3de [libata] returned 0 after 15170 usecs
[    8.364665] calling  ahci_pci_driver_init+0x0/0x20 [ahci] @ 1264
[    8.370858] ahci 0000:00:11.0: version 3.0
[    8.375342] ahci 0000:00:11.0: AHCI 0001.0100 32 slots 6 ports 3 Gbps 0x3f impl SATA mode
[    8.383757] ahci 0000:00:11.0: flags: 64bit ncq sntf ilck pm led clo pmp pio slum part ccc 
[    8.426199] scsi0 : ahci
[    8.428983] scsi1 : ahci
[    8.431799] scsi2 : ahci
[    8.434544] scsi3 : ahci
[    8.437513] scsi4 : ahci
[    8.440247] scsi5 : ahci
[    8.442957] ata1: SATA max UDMA/133 abar m1024@0xfdff9800 port 0xfdff9900 irq 22
[    8.450598] ata2: SATA max UDMA/133 abar m1024@0xfdff9800 port 0xfdff9980 irq 22
[    8.458234] ata3: SATA max UDMA/133 abar m1024@0xfdff9800 port 0xfdff9a00 irq 22
[    8.465861] ata4: SATA max UDMA/133 abar m1024@0xfdff9800 port 0xfdff9a80 irq 22
[    8.473498] ata5: SATA max UDMA/133 abar m1024@0xfdff9800 port 0xfdff9b00 irq 22
[    8.481126] ata6: SATA max UDMA/133 abar m1024@0xfdff9800 port 0xfdff9b80 irq 22
[    8.530027] initcall ahci_pci_driver_init+0x0/0x20 [ahci] returned 0 after 155459 usecs
[    8.624448] calling  dm_init+0x0/0x48 [dm_mod] @ 1462
[    .629697] device-mapper: ioctl: 4.24.0-ioctl (2013-01-15) initialised: dm-devel@redhat.com
[    8.638380] initcall dm_init+0x0/0x48 [dm_mod] returned 0 after 8514 usecs
[    8.672187] calling  md_init+0x0/0x16f [md_mod] @ 1468
[    8.677547] initcall md_init+0x0/0x16f [md_mod] returned 0 after 69 usecs
[    8.698175] calling  linear_init+0x0/0x12 [linear] @ 1468
[    8.703729] md: linear personality registered for level -1
[    8.709371] initcall linear_init+0x0/0x12 [linear] returned 0 after 5509 usecs
[    8.738262] calling  raid0_init+0x0/0x12 [raid0] @ 1473
[    8.743638] md: raid0 personality registered for level 0
[    8.749100] initcall raid0_init+0x0/0x12 [raid0] returned 0 after 5333 usecs
[    8.773966] calling  raid_init+0x0/0x12 [raid1] @ 1475
[    8.779261] md: raid1 personality registered for level 1
[    8.784721] initcall raid_init+0x0/0x12 [raid1] returned 0 after 5330 usecs
[    8.809389] calling  async_tx_init+0x0/0x1b [async_tx] @ 1477
[    8.815301] async_tx: api initialized (async)
[    8.819812] initcall async_tx_init+0x0/0x1b [async_tx] returned 0 after 4404 usecs
[    8.828137] ata4: SATA link down (SStatus 0 SControl 300)
[    8.841069] ata6: SATA link down (SStatus 0 SControl 300)
[    8.841118] ata5: SATA link down (SStatus 0 SControl 300)
[    8.872159] calling  calibrate_xor_blocks+0x0/0x144 [xor] @ 1477
[    8.878321] xor: meauring software checksum speed
[    8.893012]    prefetch64-sse: 11240.000 MB/sec
[    8.907013]    generic_sse: 10640.000 MB/sec
[    8.911435] xor: using function: prefetch64-sse (11240.000 MB/sec)
[    8.917765] initcall calibrate_xor_blocks+0x0/0x144 [xor] returned 0 after 38518 usecs
[    8.954420] calling  init_module+0x0/0x229 [raid6_pq] @ 1477
[    8.970052] ata1: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    8.976737] ata1.00: ATAPI: ATAPI   iHDS118   5, RL08, max UDMA/100
[    8.977014] raid6: sse2x1    3863 MB/s
[    8.988099] ata1.00: configured for UDMA/100
[    8.994025] raid6: sse2x2    5917 MB/s
[    8.994481] scsi 0:0:0:0: CD-ROM            ATAPI    iHDS118   5      RL08 PQ: 0 ANSI: 5
[    8.994566] scsi 0:0:0:0: Attached scsi generic sg0 type 5
[    9.012065] ata2: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    9.018420] ata3: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    9.026256] ata3.00: ATA-8: WDC WD2502ABYS-02B7A0, 02.03B03, max UDMA/133
[    9.028023] raid6: sse2x4    7160 MB/s
[    9.028024] raid6: using algorithm sse2x4 (7160 MB/s)
[    9.028025] raid6: using intx1 recovery algorithm
[    9.028031] initcall init_module+0x0/0x229 [raid6_pq] returned 0 after 66206 usecs
[    9.028337] calling  async_pq_init+0x0/0x3b [async_pq] @ 1477
[    9.028343] initcall async_pq_init+0x0/0x3b [async_pq] returned 0 after 2 usecs
[    9.029728] calling  raid5_init+0x0/0x2c [raid456] @ 1477
[    9.029731] md: raid6 personality registered for level 6
[    9.029732] md: raid5 personalit registered for level 5
[    9.029732] md: raid4 personality registered for level 4
[    9.029736] initcall raid5_init+0x0/0x2c [raid456] returned 0 after 3 usecs
[    9.146757] ata3.00: 490350672 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
[    9154167] ata2.00: ATA-8: WDC WD2502ABYS-02B7A0, 02.03B03, max UDMA/133
[    9.154169] ata2.00: 490350672 sectors, multi 0: LBA48 NCQ (depth 31/32), AA
[    9.168459] ata3.00: configured for UDMA/133
[    9.172920] ata2.00: configured for UDMA/133
[    9.173079] scsi 1:0:0:0: Direct-Access     ATA      WDC WD2502ABYS-0 02.0 PQ: 0 ANSI: 5
[    9.173173] sd 1:0:0:0: Attached scsi generic sg1 type 0
[    9.173494] scsi 2:0:0:0: Direct-Access     ATA      WDC WD2502ABYS0 02.0 PQ: 0 ANSI: 5
[   9.173553] sd 2:0:0:0: Attached scsi generic sg2 type 0
[    9.173917] sd 2:0:0:0: [sdb] 490350672 512-byte logical blocks: (251 GB/233 GiB)
[    9.173965] sd 2:0:0:0: [sdb] Write Protect is off
[    9.173966] sd 2:0:0:0: [sdb] Mode Sense: 00 3a 00 00
[    9.174172] sd 2:0:0:0: sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    9.174368] sd 1:0:0:0: [sda] 490350672 512-byte logical blocks: (251 GB/233 GiB)
[    9.174443] sd 1:0:0:0: [sda] Write Protect is off
[    9.174444] sd 1:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    9.174482] sd 1:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    9.179247]  sda: sda1 sda2 sda3 sda4
[    9.179977] sd 1:0:0:0: [sda] Attached SCSI disk
[    9.184193]  sdb: sdb1 sdb2 sdb3 sdb4
[    9.184905] sd 2:0:0:0: [sdb] Attached SCSI disk