USB device cannot be reconnected and khubd "blocked for more than 120 seconds"

Hi,

the USB stick (an Cruzer Titanium 2GB) was not recognized at any of the USB ports of this system (an System76 lemu4 laptop, XHCI device) after it was removed. If I attempt to insert it again in any of the ports (one of the two USB3, or the USB2) the led on the stick lights up shortly and if off again. There is no media detection messages in the dmesg output, only that from the first time:

usb 1-1.2: new high-speed USB device number 3 using ehci-pci usb 1-1.2: New USB device found, idVendor=0781, idProduct=5408 usb 1-1.2: New USB device strings: Mfr=1, Product=2, SerialNumber=3 usb 1-1.2: Product: U3 Titanium
usb 1-1.2: Manufacturer: SanDisk Corporation
usb 1-1.2: SerialNumber: 0000187A3A60F1E9
scsi6 : usb-storage 1-1.2:1.0
io scheduler deadline registered (default)
usb 1-1.2: USB disconnect, device number 3

The kernel is v3.8-rc3. I never had this problem in 3.7. I could almost reproduce the problem later in a simplified setup (init=/bin/bash) on USB3 ports by inserting and removing the stick quickly. Almost - because the USB3 ports recovered after some time, while the USB2 port never experienced the problem.

Out of desperation, I tried to write "1\n" to
"/sys/bus/usb/devices/1-1.2/remove",
with interesting result:

 INFO: task khubd:512 blocked for more than 120 seconds.
 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
 khubd           D ffff880213918000     0   512      2 0x00000000
  ffff880213b7fa78 0000000000000046 ffff88020000006b 0000000000000000
  ffff880213918000 ffff880213b7ffd8 ffff880213b7ffd8 0000000000013440
  ffff880213eb5d90 ffff880213918000 ffff880213b7fa08 0000000000000046
 Call Trace:
  [<ffffffff8104d763>] ? flush_work+0x6d/0x1fe
  [<ffffffff8133deeb>] ? scsi_remove_host+0x24/0x10e
  [<ffffffff8104d6fb>] ? flush_work+0x5/0x1fe
  [<ffffffff815dcf9e>] schedule+0x65/0x67
  [<ffffffff815dd1e6>] schedule_preempt_disabled+0x18/0x24
  [<ffffffff815db9ac>] mutex_lock_nested+0x181/0x2c1
  [<ffffffff8133deeb>] ? scsi_remove_host+0x24/0x10e
  [<ffffffff8133deeb>] scsi_remove_host+0x24/0x10e
  [<ffffffff8138c2f5>] usb_stor_disconnect+0x77/0xbc
  [<ffffffff81376a4c>] usb_unbind_interface+0x6c/0x14d
  [<ffffffff813266ec>] __device_release_driver+0x88/0xdb
  [<ffffffff81326764>] device_release_driver+0x25/0x32
  [<ffffffff8132615f>] bus_remove_device+0xf5/0x10a
  [<ffffffff8132412f>] device_del+0x12e/0x189
  [<ffffffff81374bee>] usb_disable_device+0x77/0x197
  [<ffffffff8136e719>] usb_disconnect+0x93/0xfb
  [<ffffffff8136f8ed>] hub_port_connect_change+0x14f/0x792
  [<ffffffff81370382>] hub_thread+0x452/0x6c3
  [<ffffffff8105ac1a>] ? complete+0x1f/0x50
  [<ffffffff81052587>] ? wake_up_bit+0x2a/0x2a
  [<ffffffff8136ff30>] ? hub_port_connect_change+0x792/0x792
  [<ffffffff81051f2a>] kthread+0xd5/0xdd
  [<ffffffff8105d5f6>] ? finish_task_switch+0x3f/0xf7
  [<ffffffff81051e55>] ? __init_kthread_worker+0x5a/0x5a
  [<ffffffff815e481c>] ret_from_fork+0x7c/0xb0
  [<ffffffff81051e55>] ? __init_kthread_worker+0x5a/0x5a
 4 locks held by khubd/512:
  #0:  (&__lockdep_no_validate__){......}, at: [<ffffffff81370039>]
hub_thread+0x109/0x6c3
  #1:  (&__lockdep_no_validate__){......}, at: [<ffffffff8136e6e2>]
usb_disconnect+0x5c/0xfb
  #2:  (&__lockdep_no_validate__){......}, at: [<ffffffff8132675c>]
device_release_driver+0x1d/0x32
  #3:  (&shost->scan_mutex){......}, at: [<ffffffff8133deeb>]
scsi_remove_host+0x24/0x10e
 INFO: task modprobe:12163 blocked for more than 120 seconds.
 "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
 modprobe        D 0000000000000009     0 12163  12162 0x00000000
  ffff88020536dd68 0000000000000046 0000000000000000 ffff8801e66f86c8
  ffff8801e66f8000 ffff88020536dfd8 ffff88020536dfd8 0000000000013440
  ffff880213d33e60 ffff8801e66f8000 0000000000000000 ffff8801e66f86c8
 Call Trace:
  [<ffffffff810526f7>] ? prepare_to_wait+0x23/0x7d
  [<ffffffff81058775>] ? async_synchronize_cookie_domain+0xe0/0x167
  [<ffffffff815dcf9e>] schedule+0x65/0x67
  [<ffffffff8105879e>] async_synchronize_cookie_domain+0x109/0x167
  [<ffffffff81052587>] ? wake_up_bit+0x2a/0x2a
  [<ffffffff81058883>] async_synchronize_full+0x56/0x77
  [<ffffffff8108c837>] load_module+0x1002/0x11e8
  [<ffffffff810882e0>] ? sys_getegid16+0x4b/0x4b
  [<ffffffff815e13f2>] ? do_page_fault+0xe/0x10
  [<ffffffff8108cab6>] sys_init_module+0x99/0xa6
  [<ffffffff815e48c6>] system_call_fastpath+0x1a/0x1f
 1 lock held by modprobe/12163:
  #0:  (async_register_mutex){......}, at: [<ffffffff8105884a>]
async_synchronize_full+0x1d/0x77

When reproducing in the simplified setup, this operation just disconnected the device, as expected.

Additional information:
lspci:

00:00.0 Host bridge: Intel Corporation 3rd Gen Core processor DRAM Controller (rev 09)
00:02.0 VGA compatible controller: Intel Corporation 3rd Gen Core processor Graphics Controller (rev 09)
00:14.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB xHCI Host Controller (rev 04)
00:16.0 Communication controller: Intel Corporation 7 Series/C210 Series Chipset Family MEI Controller #1 (rev 04)
00:1a.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB Enhanced Host Controller #2 (rev 04)
00:1b.0 Audio device: Intel Corporation 7 Series/C210 Series Chipset Family High Definition Audio Controller (rev 04)
00:1c.0 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset Family PCI Express Root Port 1 (rev c4)
00:1c.2 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset Family PCI Express Root Port 3 (rev c4)
00:1c.3 PCI bridge: Intel Corporation 7 Series/C210 Series Chipset Family PCI Express Root Port 4 (rev c4)
00:1d.0 USB controller: Intel Corporation 7 Series/C210 Series Chipset Family USB Enhanced Host Controller #1 (rev 04)
00:1f.0 ISA bridge: Intel Corporation HM76 Express Chipset LPC Controller (rev 04)
00:1f.2 SATA controller: Intel Corporation 7 Series Chipset Family 6-port SATA Controller [AHCI mode] (rev 04)
00:1f.3 SMBus: Intel Corporation 7 Series/C210 Series Chipset Family SMBus Controller (rev 04)
02:00.0 Network controller: Intel Corporation Centrino Advanced-N 6235 (rev 24) 03:00.0 Unassigned class [ff00]: Realtek Semiconductor Co., Ltd. Device 5289 (rev 01)
03:00.2 Ethernet controller: Realtek Semiconductor Co., Ltd. RTL8111/8168B PCI Express Gigabit Ethernet controller (rev 0a)

.config and the kern.log at:

http://familie-riesen.de/~raa/public/v3.8-rc3-khubd-hang-config-dmesg.tar.bz2

The kern.log ends with a long trace of running tasks: I pressed alt-sysrq-t before reboot.

One more detail: I usually use the "noop" elevator. That time it was the "deadline". And I just reproduced it easily with "deadline".

Can you provide the output of dmesg with CONFIG_USB_DEBUG? This will be helpful.

--
Best regards
Tianyu Lan

To make testing simpler, use only the USB-2 ports. The xHCI driver is not as mature as the EHCI driver.

For testing, use a kernel with CONFIG_USB_DEBUG and CONFIG_PRINTK_TIME enabled. Do the following:

After a normal boot, run "dmesg -C" to clear the log buffer.

Then plug in the stick. After a couple of seconds, type Alt-SysRq-W.

Then unplug the stick. After a couple of seconds, type Alt-SysRq-W again.

Then collect the output from dmesg and post it.

I doubt the elevator has anything to do with this.

Alan Stern

But it looks like it does: just using the deadline elevator is a sure way to reproduce the bug. The system always recovers (sometimes after a while) with "noop".

And no, it does not. Not by itself, but the fact that deadline elevator was compiled as module certainly helped!

This explains the hanging modprobe in the dmesg output (the part after device connect). I still wonder, why didn't it froze at boot, mounting SATA devices (the root, /var, and /home are on an SSD connected by SATA)? And why hanging khubd at reboot?

Anyway, building the elevator in the kernel avoids the problem. Sorry for not spotting this earlier.

Now, who would be interested to handle this kind of misconfiguration ...

So the whole thing was a false alarm?

Maybe you should report to the block-layer maintainers that it's possible to mess up the system by building an elevator as a module. That sounds like the sort of thing they'd be interested to hear.

Alan Stern

Yes, almost. What about khubd hanging when machine is shutdown?

Hi Jens,

may I point you at this problem report:

http://thread.gmane.org/gmane.linux.kernel/1420814

It is surely a misconfiguration on my part (the used io scheduler configured as a module), but the behavior is somewhat problematic
anyway: at least in this case USB storage is essentially locked up.

Regards,
Alex

What about it? I have trouble understanding all the descriptions you have provided so far, because you talk about several different things and change your mind a lot. Can you provide a single, simple scenario that illustrates this problem?

Alan Stern

1. Compile a kernel with deadline elevator as module
2. Boot into it, make sure the elevator is selected
(I used "elevator=deadline" in the kernel command line)
3. Insert a FAT formatted mass storage device in an USB2 port Observe "io scheduler deadline registered"
4. Pull the stick out, wait a moment, and either shutdown or just and press alt-sysrq-W:

[  158.170585] usb 1-1.2: USB disconnect, device number 3
[  158.170590] usb 1-1.2: unregistering device
[  158.170595] usb 1-1.2: unregistering interface 1-1.2:1.0
[  166.959398] SysRq : Show Blocked State
[  166.959410]   task                        PC stack   pid father
[  166.959432] khubd           D ffff880213a68000     0   513      2 0x00000000
[  166.959440]  ffff880213affa18 0000000000000046 ffff88020000006b 0000000000000
[  166.959448]  ffff880213a68000 ffff880213afffd8 ffff880213afffd8 0000000000013
[  166.959454]  ffffffff81a14400 ffff880213a68000 ffff880213aff9a8 0000000000000
[  166.959461] Call Trace:
[  166.959475]  [<ffffffff8104d763>] ? flush_work+0x6d/0x1fe
[  166.959485]  [<ffffffff8133defb>] ? scsi_remove_host+0x24/0x10e
[  166.959490]  [<ffffffff8104d6fb>] ? flush_work+0x5/0x1fe
[  166.959499]  [<ffffffff815e1dd6>] schedule+0x65/0x67
[  166.959506]  [<ffffffff815e201e>] schedule_preempt_disabled+0x18/0x24
[  166.959513]  [<ffffffff815e07e4>] mutex_lock_nested+0x181/0x2c1
[  166.959518]  [<ffffffff8133defb>] ? scsi_remove_host+0x24/0x10e
[  166.959524]  [<ffffffff8133defb>] scsi_remove_host+0x24/0x10e
[  166.959531]  [<ffffffff813910d5>] usb_stor_disconnect+0x77/0xbc
[  166.959539]  [<ffffffff81377ca3>] usb_unbind_interface+0x6c/0x14d
[  166.959548]  [<ffffffff813266fc>] __device_release_driver+0x88/0xdb
[  166.959554]  [<ffffffff81326774>] device_release_driver+0x25/0x32
[  166.959561]  [<ffffffff8132616f>] bus_remove_device+0xf5/0x10a
[  166.959567]  [<ffffffff8132413f>] device_del+0x12e/0x189
[  166.959574]  [<ffffffff81375d3a>] usb_disable_device+0xb1/0x20e
[  166.959582]  [<ffffffff8136ed8b>] usb_disconnect+0xab/0x113
[  166.959589]  [<ffffffff81370218>] hub_port_connect_change+0x1b0/0x879
[  166.959597]  [<ffffffff81370e3a>] hub_events+0x559/0x69d
[  166.959604]  [<ffffffff81370fb6>] hub_thread+0x38/0x19b
[  166.959612]  [<ffffffff81052587>] ? wake_up_bit+0x2a/0x2a
[  166.959618]  [<ffffffff81370f7e>] ? hub_events+0x69d/0x69d
[  166.959625]  [<ffffffff81051f2a>] kthread+0xd5/0xdd
[  166.959632]  [<ffffffff8105d5f6>] ? finish_task_switch+0x3f/0xf7
[  166.959641]  [<ffffffff81051e55>] ? __init_kthread_worker+0x5a/0x5a
[  166.959648]  [<ffffffff815e965c>] ret_from_fork+0x7c/0xb0
[  166.959655]  [<ffffffff81051e55>] ? __init_kthread_worker+0x5a/0x5a

This trace if from alt-sysrq-W. I can attach an image from the shutdown case, the traces from that case are hard to save: the main storage is usually already stopped. I believe it was the same, though.

That makes it clear. The elevator probably has scheduled work which cannot finish waiting on a lock and scsi_remove_host() wants to flush work.

This is not a USB problem. You need to involve the SCSI people. khubd just stops working because disconnects are processed in its context and the removal deadlocks.

Regards
Oliver

Indeed. I just tried booting into a kernel that has the deadline elevator built-in, not a module. Even then, when I specified "elevator=deadline" on the boot command line, the system hung up partway through booting. Hard to tell exactly where, because it occurred shortly after the switching from VGA to the framebuffer driver, so the screen was completely blank.

When I get a chance, I'll try it on another machine where I can use a serial console.

What is the work and why can't it finish? Or rather, how can we figure these things out? According to what Alex wrote, the blocked task doesn't show up in the Alt-SysRq-W listing.

And don't forget that the listing shows scsi_remove_host() blocks waiting to acquire the host's scan_mutex. Not waiting for work to be flushed. This casts doubt on your explanation.

The why whould building the deadline elevator as a module make any difference? Or does it make a difference?

Alex, if the elevator is made static instead, do you still see the same behavior when the USB drive is removed?

Also, are there any mounted filesystems on the drive when you unplug it?

Alan Stern

Building elevator as module does make a difference: the system is broken.

How can I make the elevator static? Or did you mean "built-in"? Or did you mean to ask if khubd hangs if the deadline is built in? In that case - no. The behavior is normal. Nothing hangs.

No, no auto-mount. The whole of userspace init is attached, and I'm reasonably sure nothing of it mounts anything automatically. Nothing of udev, too.

I can reproduce the problem too on one ehci-only system(Pandaboard) with deadline elevator module case, and no such problem in the built-in case, and still on 3.8-rc3.

Follows the dmesg log:

[   85.665679] usb 1-1.2.2: new high-speed USB device number 5 using ehci-omap
[   85.784423] usb 1-1.2.2: default language 0x0409
[   85.790008] usb 1-1.2.2: udev 5, busnum 1, minor = 4
[   85.790039] usb 1-1.2.2: New USB device found, idVendor=0951, idProduct=1624
[   85.790039] usb 1-1.2.2: New USB device strings: Mfr=1, Product=2,
SerialNumber=3
[   85.790069] usb 1-1.2.2: Product: DataTraveler G2
[   85.790069] usb 1-1.2.2: Manufacturer: Kingston
[   85.790100] usb 1-1.2.2: SerialNumber: 0019E06C5346EA41D0000071
[   85.790100] device: '1-1.2.2': device_add
[   85.790344] bus: 'usb': add device 1-1.2.2
[   85.790405] PM: Adding info for usb:1-1.2.2
[   85.790740] bus: 'usb': driver_probe_device: matched device 1-1.2.2
with driver usb
[   85.790771] bus: 'usb': really_probe: probing driver usb with device 1-1.2.2
[   85.790802] usb 1-1.2.2: usb_probe_device
[   85.790832] usb 1-1.2.2: configuration #1 chosen from 1 choice
[   85.791076] usb 1-1.2.2: adding 1-1.2.2:1.0 (config #1, interface 0)
[   85.791076] device: '1-1.2.2:1.0': device_add
[   85.791137] bus: 'usb': add device 1-1.2.2:1.0
[   85.791168] PM: Adding info for usb:1-1.2.2:1.0
[   85.791442] device: 'ep_81': device_add
[   85.791564] PM: Adding info for No Bus:ep_81
[   85.791564] device: 'ep_02': device_add
[   85.791687] PM: Adding info for No Bus:ep_02
[   85.791687] driver: '1-1.2.2': driver_bound: bound to device 'usb'
[   85.791717] bus: 'usb': really_probe: bound device 1-1.2.2 to driver usb
[   85.791748] PM: Moving platform:musb-hdrc.0.auto to end of list
[   85.791748] device: 'ep_00': device_add
[   85.791778] platform musb-hdrc.0.auto: Retrying from deferred list
[   85.791839] PM: Adding info for No Bus:ep_00
[   85.791839] bus: 'platform': driver_probe_device: matched device
musb-hdrc.0.auto with driver musb-hdrc
[   85.791839] bus: 'platform': really_probe: probing driver musb-hdrc
with device musb-hdrc.0.auto
[   85.791870] hub 1-1.2:1.0: state 7 ports 4 chg 0000 evt 0004
[   85.791900] unable to find transceiver of type USB2 PHY
[   85.797454] HS USB OTG: no transceiver configured
[   85.802703] musb-hdrc musb-hdrc.0.auto: musb_init_controller failed
with status -517
[   85.811157] platform musb-hdrc.0.auto: Driver musb-hdrc requests
probe deferral
[   85.811187] platform musb-hdrc.0.auto: Added to deferred list
[   85.811218] PM: Moving platform:twl6030_usb to end of list
[   85.811218] platform twl6030_usb: Retrying from deferred list
[   85.811279] bus: 'platform': driver_probe_device: matched device
twl6030_usb with driver twl6030_usb
[   85.811279] bus: 'platform': really_probe: probing driver
twl6030_usb with device twl6030_usb
[   85.811309] twl6030_usb twl6030_usb: phy not ready, deferring probe
[   85.811462] platform twl6030_usb: Driver twl6030_usb requests probe deferral
[   85.811462] platform twl6030_usb: Added to deferred list
[   85.883331] Initializing USB Mass Storage driver...
[   85.883361] bus: 'usb': add driver usb-storage
[   85.883453] bus: 'usb': driver_probe_device: matched device
1-1.2.2:1.0 with driver usb-storage
[   85.883483] bus: 'usb': really_probe: probing driver usb-storage
with device 1-1.2.2:1.0
[   85.883514] usb-storage 1-1.2.2:1.0: usb_probe_interface
[   85.883544] usb-storage 1-1.2.2:1.0: usb_probe_interface - got id
[   85.884094] scsi0 : usb-storage 1-1.2.2:1.0
[   85.884155] device: 'host0': device_add
[   85.884185] bus: 'scsi': add device host0
[   85.884246] PM: Adding info for scsi:host0
[   85.884552] device: 'host0': device_add
[   85.884674] PM: Adding info for No Bus:host0
[   85.884948] driver: '1-1.2.2:1.0': driver_bound: bound to device
'usb-storage'
[   85.884979] bus: 'usb': really_probe: bound device 1-1.2.2:1.0 to
driver usb-storage
[   85.884979] PM: Moving platform:musb-hdrc.0.auto to end of list
[   85.885009] platform musb-hdrc.0.auto: Retrying from deferred list
[   85.885070] bus: 'platform': driver_probe_device: matched device
musb-hdrc.0.auto with driver musb-hdrc
[   85.885070] bus: 'platform': really_probe: probing driver musb-hdrc
with device musb-hdrc.0.auto
[   85.885131] unable to find transceiver of type USB2 PHY
[   85.886230] usbcore: registered new interface driver usb-storage
[   85.886230] USB Mass Storage support registered.
[   85.890655] HS USB OTG: no transceiver configured
[   85.895660] musb-hdrc musb-hdrc.0.auto: musb_init_controller failed
with status -517
[   85.903839] platform musb-hdrc.0.auto: Driver musb-hdrc requests
probe deferral
[   85.903869] platform musb-hdrc.0.auto: Added to deferred list
[   85.903869] PM: Moving platform:twl6030_usb to end of list
[   85.903900] platform twl6030_usb: Retrying from deferred list
[   85.903930] bus: 'platform': driver_probe_device: matched device
twl6030_usb with driver twl6030_usb
[   85.903961] bus: 'platform': really_probe: probing driver
twl6030_usb with device twl6030_usb
[   85.903991] twl6030_usb twl6030_usb: phy not ready, deferring probe
[   85.904022] platform twl6030_usb: Driver twl6030_usb requests probe deferral
[   85.904052] platform twl6030_usb: Added to deferred list
[   86.901367] io scheduler deadline registered (default)
[  181.168487] INFO: task modprobe:2462 blocked for more than 90 seconds.
[  181.175323] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  181.183624] modprobe        D c04f1920     0  2462   2461 0x00000000
[  181.183685] [<c04f1920>] (__schedule+0x5fc/0x6d4) from [<c005eba4>]
(async_synchronize_cookie_domain+0xdc/0x
168)
[  181.183715] [<c005eba4>]
(async_synchronize_cookie_domain+0xdc/0x168) from [<c005ed04>]
(async_synchronize_f
ull+0x3c/0x60)
[  181.183776] [<c005ed04>] (async_synchronize_full+0x3c/0x60) from
[<c0085610>] (load_module+0x1aac/0x1cdc)
[  181.183807] [<c0085610>] (load_module+0x1aac/0x1cdc) from
[<c0085944>] (sys_init_module+0x104/0x110)
[  181.183837] [<c0085944>] (sys_init_module+0x104/0x110) from
[<c000dfe0>] (ret_fast_syscall+0x0/0x48)
[  271.175506] INFO: task modprobe:2462 blocked for more than 90 seconds.
[  271.182373] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[  271.190826] modprobe        D c04f1920     0  2462   2461 0x00000000
[  271.190887] [<c04f1920>] (__schedule+0x5fc/0x6d4) from [<c005eba4>]
(async_synchronize_cookie_domain+0xdc/0x
168)
[  271.190917] [<c005eba4>]
(async_synchronize_cookie_domain+0xdc/0x168) from [<c005ed04>]
(async_synchronize_f
ull+0x3c/0x60)
[  271.190948] [<c005ed04>] (async_synchronize_full+0x3c/0x60) from
[<c0085610>] (load_module+0x1aac/0x1cdc)
[  271.190948] [<c0085610>] (load_module+0x1aac/0x1cdc) from
[<c0085944>] (sys_init_module+0x104/0x110)
[  271.190979] [<c0085944>] (sys_init_module+0x104/0x110) from
[<c000dfe0>] (ret_fast_syscall+0x0/0x48)

Thanks,
--
Ming Lei

The deadlock problem is caused by calling request_module() inside async function of do_scan_async(), and it was introduced by Linus's below commit:

commit d6de2c80e9d758d2e36c21699117db6178c0f517

Author: Linus Torvalds <[email protected]>
Date:   Fri Apr 10 12:17:41 2009 -0700

async: Fix module loading async-work regression

IMO, maybe the commit isn't a proper fix, considered the below fact:

- it isn't good to allow async function to be marked as __init

- any user mode shouldn't expect that the device is ready just after completing of 'insmod', and drivers should make the device ready for user mode just after its async probing or other kind of async initialization(done in work or kthread) completes.

- from view of driver, introducing async_synchronize_full() after do_one_initcall() inside do_init_module() is like a sync probe for drivers built as module, and cause this kind of deadlock easily.

So could we revert the commit and fix the previous problems just case by case? or other better fix?

Thanks,
--
Ming Lei

Immaterial. For modules, __init is a non-issue. For non-modules, the synchronization elsewhere is sufficient.

Bullshit. That expectation is just a fact. People insmod a device driver, and mount the device immediately in scripts.

We do not say "user mode shouldn't". Seriously. EVER. User mode *does*, and we deal with it. Learn it now, and stop ever saying that again.

This is really starting to annoy me. Kernel developers who say "user mode should be fixes to not do that" should go somewhere else. The whole and *only* point of a kernel is to hide these kinds of issues from user mode, and make things "just work" in user mode. User mode should not ever worry about "oh, doing X can trigger a module load, so now the device might not be available immediately, so I should delay and re-try until it is".

That's just f*cking crazy talk.

We have a very simple rule in the kernel: we don't break user space. EVER.

Learn that rule. I don't ever want to hear "any user mode shouldn't expect" again. User mode *does* expect. End of discussion.

There's no way in hell we take a "fix things one by one" approach. It's not going to work. And your suggestion seems to not do async discovery of devices in general, which is a *much* worse fix than anything else. It's just crazy.

But there are other approaches we might take. We might move the call to

    async_synchronize_full();

to other places. For example, maybe we're better off doing it at block/char device open instead?

Linus

How about skipping that call if the current thread is one of the async helpers? Is it possible to detect when that happens?

Or maybe such a check should go inside async_synchronize_full() itself.

Alan Stern

Do we have some idea of exactly what is waiting for what? Which async context is causing the module load to happen in the first place?

I think *that* is what we should avoid - it sounds like the block layer is loading the IO scheduler at the wrong point. I realize that people like (for testing purposes) to change the IO scheduler at random, but if that means that any IO can basically result in a request_module(), then that sounds like a problem.

It seems to be "elevator_get()", and I presume the chain is something like "load block driver async, the block driver does blk_init_allocated_queue, that does request_module() to find the elevator, the request_module() succeeds, but ends up waiting for async work, which is the block driver load, which is waiting for the request_module to finish".

And my gut feel is that blk_init_allocated_queue() probably shouldn't do that request_module() at all. We migth want to do it when we *open* the device, but not while loading the module for the device.

So my _feeling_ is that this is just a bug in the block layer, and that it shouldn't set up block device drivers for this kind of crazy "need to load the elevator module while in the middle of scanning devices". I think *that* is what we should aim to change.

Hmm?

That said, I think it might indeed be a good idea to make this problem much easier to see, and that "detect when it happens" would be a good thing (and then we should WARN_ON_ONCE() on people trying to do request_module() calls from async context).

Linus

Looks 5d38258ec026921a7b266f4047ebeaa75db358e5(ACPI battery:
fix async boot oops) addresses the issue of __init for modules.

I mean we can let the device node populated in probe() first, but let open() wait for completion of the async probe(). Maybe my expression is not accurate, here the 'device isn't ready' just means that the async probe() isn't completed, and doesn't mean the device node doesn't come.

No, I don't mean we should break user space, see above.

I will try to figure out one patch to address the scsi block async probe issue first, and see if it can fix the problem by moving add_disk() into sd_probe()
and calling async_synchronize_full_domain(&scsi_sd_probe_domain) in the entry of sd_open().

Looks it is similar with the above idea, but we have to remove the async_synchronize_full() in do_init_module() together.

Thanks,
--
Ming Lei

Looks it isn't doable because the block partition device can only be created inside the async things.

But I have another idea to address the problem, and let module code call async_synchronize_full() only if the module requires that explicitly, so how about the below draft patch?

index 7992635..c5106a0 100644
@@ -3143,6 +3143,8 @@ static int __init init_sd(void)
 	if (err)
 		goto err_out_driver;
 
+	mod_init_async_wait(THIS_MODULE);
+
 	return 0;
 
 err_out_driver:

index 7760c6d..09bd4c5 100644
@@ -300,6 +300,12 @@ struct module
 
 	unsigned int taints;	/* same bits as kernel:tainted */
 
+	/*
+	 * set if the module wants to call async_synchronize_full
+	 * after its init() is complted.
+	 */
+	unsigned int init_async_wait:1;
+
 #ifdef CONFIG_GENERIC_BUG
 	/* Support for BUG */
 	unsigned num_bugs;

@@ -656,4 +662,16 @@ static inline void module_bug_finalize(const Elf_Ehdr *hdr,
 static inline void module_bug_cleanup(struct module *mod) {}
 #endif	/* CONFIG_GENERIC_BUG */
 
+/*
+ * If one module wants to complete its all async code after
+ * its init() executed, the module can call this function in
+ * the entry of its init(), but the module's async function
+ * can't call request_module, otherwise deadlock will be caused.
+ */
+static inline void mod_init_async_wait(struct module *mod)
+{
+	if (mod)
+		mod->init_async_wait = 1;
+}
+
 #endif /* _LINUX_MODULE_H */

index 250092c..dc5d011 100644
@@ -3058,8 +3058,9 @@ static int do_init_module(struct module *mod)
 	blocking_notifier_call_chain(&module_notify_list,
 				     MODULE_STATE_LIVE, mod);
 
-	/* We need to finish all async code before the module init sequence is done */
-	async_synchronize_full();
+	/* Only complete all async code if the module requires that */
+	if (mod->init_async_wait)
+		async_synchronize_full();
 
 	mutex_lock(&module_mutex);
 	/* Drop initial reference. */

Thanks,
--
Ming Lei

[ Added Tejun to the discussion, since he's the async go-to-guy ]

No way.

This kind of "let's just let drivers tell us when they used async helpers" is basically *asking* for buggy code. In fact, just to prove how bad it is, YOU SCREWED IT UP YOURSELF.

Because it's not just sd.c that uses async_schedule(), and would need the async synchronize. It's floppy.c, it's generic scsi scanning (so scsi tapes etc), and it's libata-core.c.

This kind of "let's randomly encourage people to write subtly buggy code that has magical timing dependencies, so that the developer won't likely even see it because he has fast disks etc" code is totally unacceptable. And this code was *designed* to be that kind of buggy.

No, if we set a flag like this, then it needs to be set *automatically*, so that a module cannot screw this up by mistake.

It could be as simple as having a per-thread flag that gets set by the __async_schedule() function, and gets cleared by fork. Then the module code could do something like

   /* before calling the module ->init function */
   current->used_async = 0;
   ...
   if (current->used_async)
      async_synchronize_full();

or whatever.

Tejun, comments? You can see the whole thread on lkml, but the basic problem is that the module loading doing the unconditional async_synchronize_full() has caused problems, because we have

- load module A
- module A does per-controller async discovery of its devices (eg
scsi or ata probing)
- in the async thread, it initializes somethign that needs another
module B (in this case the default IO scheduler module)
- modprobe for B loads the IO scheduler module successfully at the end of the module load, it does
async_synchronize_full() to make sure load_module won't return before the module is ready
*DEADLOCK*, because the async_synchronize_full() thing
actually waits for not the module B async code (it didn't have any), but for the module *A* async code, which is waiting for module B to finish.

Now, I'll happily argue that we shouldn't have this kind of "load modules from random context" behavior in the kernel, and I think the block layer is to blame for doing the IO scheduler load at an insane time. So "don't do that then" would be the best solution. Sadly, we don't even have a good way to notice that we're doing it, so "hacky workaround that at least doesn't require driver authors to care" is likely the second-best workaround.

But the "hacky workaround" absolutely needs to be *automatic*. Because the "driver writers need to get this subtle untestable thing right" is *not* acceptable. That's the patch that Ming Lei did, and I refuse to have that kind of fragile crap in the kernel.

Linus

Btw, we could *possibly* do this the other way around. Wait for all async work by default, but then have a really hacky way to turn that off for modules that explicitly don't want it, because they know they can be loaded in async context, and they don't do any async work themselves. Then we could make the IO schedulers set that flag ("I know I'm loaded from async space, and I know I'm not myself doing any async init")

Quite frankly, I'd still much rather prefer the automated approach - or even better, just avoiding the "load modules in async context" entirely. But at least the "I can put a huge comment about why I don't want to be waited on" would be much more acceptable than the "I need to explicitly tell the world that it needs to wait on me".

So Ming Lei's patch was "easily subtly buggy by mistake" (showing that by the fact that it was indeed buggy), while the opposite model where you have to explicitly ask people not to wait for you could still be very buggy, but at least now it needs to explicitly do extra work in order to be buggy.

So if an interface is fragile, it should aim to be fragile in the right way - making the fragility explicit, so that people can grep for it, and people can add comments to the particular code that marks it fragile. The default behavior should be the robust one.

And if would be lovely to add a warning to the "people loaded a module from async context" case, so that we'd *see* this.

Tejun, is there a good way for code to see "I'm running in async context"? Then we could do something like

    WARN_ON_ONCE(wait && system_state == SYSTEM_RUNNING && in_async_thread());

in kernel/kmod.c (__request_module()). That should at least warn about this whole issue happening.

Linus

Hello, Linus

Will continue on another reply but this one is relevant so...

Almost. With a bit of modification we can ask whether current is a kworker, reach struct worker_struct via kthread_data() if so and then test worker->current_func against the async workfn.

Thanks.

tejun

It may not be so easy. When the SCSI async thread probes the new disk, it has to do I/O. So it needs to use a scheduler.

But maybe it could use a built-in trivial scheduler until the proper one is loaded. Then the loading could be asynchronous.

Alan Stern

Hello, Alan.

It can be done. Noop is always built-in and block IO can do IOs with noop. The problem here is that request_module() is done synchronously during evelator_init(). We can punt that to a work item so that the elevator is switched on load completion. There are some nastiness involved tho - if module probing returns before elevator switch happens, the userland can observe elevator being switched after some indetermined short period of time, which can, for example, break scripts adjusting elevator knobs and etc...

I *think* it'll be best to allow scoped synchronization of async ops. Looking into it.

Thanks.

tejun

Hello, Linus.

I think the root problem here, apart from request_module() from block
- which is a bit nasty but making that part completely async would too be quite nasty albeit in a different way - is that async_synchronize_full() is way too indescriminate. It's something only suitable for things like the end of system init.

I'm wondering whether what we need is a rudimentray nesting like the following.

finished_loading()

{
	blah blah;

	cookie = async_current_cookie();

	do init calls;

	async_synchronize_upto(cookie);

	blah blah;
}

The nesting here would be an approximation as the dependency recorded here is chronological. I *suspect* this should be safe unless the module is doing something weird. Need to think more about it. One way or the other, I think what we need is some form of scoping for flushing async ops.

BTW, the current synchronization is broken - cookie isn't transferred to running->domain in queueing order but __lowest_in_progress() assumes that. I think I broke that while converting it to workqueue.

Anyways, working on it.

Thanks.

tejun

I think that is a good solution if it works, but look out: we need to synchronize across *all* domains, not just the default one. The sd.c code, for example, uses its own "scsi_sd_probe_domain" for example, and we *do* want to synchronize with it.

Can you do that with your suggested interface (ie it would have to be a *global* sequence number).

Linus

cc'ing Arjan. Arjan, the original thread can be read from

http://thread.gmane.org/gmane.linux.kernel/1420814

Hello, again.

So, I've been thinking about it for a while now and it looks like async is cutting too many corners to implement any sane stackable flushing scheme on top. There simply isn't much information to determine who should wait for what.

I've thought of two workarounds. Both suck.

A. Try to detect deadlock conditions from synchronize(). If deadlock
condition involving other async jobs are detected, whine about it and then skip. Ignore deadlock condition on self (should solve this particular case).

Detecting deadlock condition isn't difficult if there are only global synchronizations; unfortunately, fragmented dependencies via domain-local synchronization makes this non-trivial.

We can still do ignore-self thing mostly trivially tho. This will at least work around the problem at hand.

B. The ranged synchronization I first suggested. The problem with
this is that it's a common practice for a given async job to try to flush anything which comes before it. This can introduce spurious synchronization dependencies which can then lead to deadlocks.

These conditions can be detected and ignored, at least only considering global synchronizations. The problem here is that those deadlock conditions will occur under normal usage and thus should be ignored silently, which basically makes synchronization silently ignore and finish successfully even if there are legitimate deadlocks which should be investigated.

For now, I'm gonna implement simple "I'm not gonna wait for myself" self-deadlock avoidance. If this needs any more sophistication, I think we better reimplement it so that we can explicitly match up and track who's gonna wait for what instead of throwing everything into a single cookie space and then try to work back from there.

Thanks.

tejun

async fundamentally had the concept of a monotonic increasing number, and that you could always wait for "everyone before me". then people (like me) wanted exceptions to what "everyone" means ;-( I'm ok with going back to a single space and simplify the world.

the case with (usb) module loading is "fun"...
people expect the device to be there (since frankly, it's hard to do otherwise).. ... but it's also really hard due to the nature of USB.. USB is async in nature, even independent of the kernel async stuff.
Example: Load ehci.ko ... the actual use devices don't show up for some time.

the module wait case is tricky, and I wonder if there's deadlocks lurking even without async. (btw there is a similar situation at the end of the normal kernel boot versus things like asynchronous driver initializing... but we "skip" that in the case of an initrd is used to bypass a very similar deadlock. this is even without "async" in use.. typical hard case is the PS/2 mouse probing)

at some point in the past we had the concept of "request a module but don't wait for it", and I wonder if that is what should have been used here.

Doing a "range wait", with the start of the range being taken at the start of module loading is a bit of a hack, but it'll work for the userspace expected semantics of all async stuff of the *loaded module* be done, independent of all other modules/async stuff. It's not as deadlocky as one might think, but it's not going to be efficient to implement.

not self-deadlocking likely solves most practical cases though

Hello, Arjan.

If we want (or need) finer grained operation, we'll probably have to head the other direction, so that we can definitively tell that an async operation belongs to domains system, module load A and B, so that each waiter knows what to wait for.

The current domain implementation is somewhere inbetween. It's not completely simplistic system and at the same time not developed enough to do properly stacked flushing.

I don't think so. It's really an async job waiting for itself. Working around just this case is mostly trivial (working on patches now) but it really is putting kludges on top of shaky foundation. Maybe this is the extent of complexity that we need to go given the rather limited use cases of async. Let's hope so. I think we'll have to reimplement synchronization scheme if we have to go further.

We actually want to wait for it as it creates a userland visible behavior difference otherwise. It's just that async's way of waiting is too ham-fisted to be used properly in more complex scenarios.

Thanks.

tejun

I like your idea of chronological synchronization: Insist that anybody who wants to flush async jobs must get a cookie, and then only allow them to wait for async jobs started after the cookie was issued.

I don't know if this is possible with the current implementation. It would require changing every call to async_synchronize_*(), and in a nontrivial way. But it might provide a proper solution to all these problems.

Can you think of any reasons why it wouldn't work in principle? It would prevent code from doing "wait until all currently-running async jobs have finished" -- but arguably, nobody should be allowed to do that anyway.

Alan Stern

Hello, Alan.

The problem here is that "flush everything which comes before me" is used to order async jobs. e.g. after async jobs probe the hardware they order themselves by flushing before registering them, so unless we build accurate flushing dependencies, those dependencies will reach beyond the time window we're interested in and bring in deadlocks.

And, as Linus pointed it out, tracking dependency through request_module() is tricky no matter what we do. I think it can be done by matching the ones calling request_module() and the ones actually loading modules but it's gonna be nasty.

There aren't too many which use async anyway so changing stuff shouldn't be too difficult but I think the simpicity or dumbness is one of major attractions of async, so it'd be nice to keep things that way and the PF_USED_ASYNC hack seems to be able to hold things together for now.

Thanks.

tejun

I don't fully understand this example. What is the point -- to make sure that asynchronously probed devices are registered in the order of their discovery?

If so, here's how to do it safely: Start up the async jobs in reverse order of discovery. Have each job acquire a cookie when it starts. Then each job needs to wait only for tasks that started after its cookie was issued.

The flushing-dependency principle can be very simple: No async task should ever have to wait for another async task that started before it. The "cookie" approach satisfies this requirement (unless an earlier task passes its cookie to a later task or subverts the mechanism in another way).

This shouldn't matter. Dependencies don't need to be tracked explicitly, because we know that any async work done by request_module() must start _after_ request_module() is called. Thus, if async task A calls request_module(), which starts up async task B, then we know that A can safely wait for B and B cannot safely wait for A.

Nesting won't matter for the chronological approach. I really think you should consider it more fully. It's not a hack, and it doesn't need to be complicated.

Alan Stern

Hello, Alan.

People still want devices to be numbered to their physical ports and so on, so we keep the registeration order the same as natural (whatever that means) hardware order.

It's a bit clumsy but yeah I guess it could work.

There is benefit to the current dumb implementation in that drivers can use it without thinking too much, but yeah it could be that the flushing range limit isn't too much of restriction on top. I don't know. At this point, I'd prefer to remove request_module() from elevator init path for the problem at hand. If we need something more involved, changing cookie usage rules definitely seems like an option.

Thanks.

tejun

A simpler approach might be to leave the existing synchronization mechanisms as they are, and use the chronological approach only for the case of loading a module (or wherever else someone wants to use it).

Alan Stern

You can't really do that. Or rather, it won't *help*.

The thing is, the module loading in particular is not necessarily happening in the same context as what *started* the module loading. A module loader will request the module from user space, and then later user space - through possibly a totally unrelated process - will finish it. So there is no "myself". There's not even necessarily any relationship that the kernel even knows about, because the module loading request can have gone from usermode_helper over something like dbus to systemd.

See?

There's a reason I asked for a warning for this. Or the "let's flag the current thread if it ever started anything asynchronous". Because it's complicated.

Linus

Btw, the sequence counter (that is *not* taking anything else into account) is good enough in practice, exactly because the common case for module loading is actually that nothing in the module init sequence is done asynchronously.

Yes, device discovery (particularly for block devices) is often asynchronous. But the modules it then asks to load usually wouldn't be. So if we just have the flag "did this thread ever even start async work" over the module init sequence, we can just avoid the async serialization entirely for that case, and it breaks the deadlock chain nicely in practice.

Only of a block device does async work and then wants to load another module that does more async work in its init routine would it then break. But at that point, I'll happily just put my foot down and tell people they are crazy, and "Let's not do that kind of crap".

Linus

If the default iosched is built as module, the kernel may deadlock while trying to load the iosched module on device probe if the probing was running off async. This is because async_synchronize_full() at the end of module init ends up waiting for the async job which initiated the module loading.

async A modprobe

1. finds a device
2. registers the block device
3. request_module(default iosched)
4. modprobe in userland
5. load and init module
6. async_synchronize_full()

Async A waits for modprobe to finish in request_module() and modprobe waits for async A to finish in async_synchronize_full().

Because there's no easy to track dependency once control goes out to userland, implementing properly nested flushing is difficult. For now, make module init perform async_synchronize_full() iff module init has queued async jobs as suggested by Linus.

This avoids the described deadlock because iosched module doesn't use async and thus wouldn't invoke async_synchronize_full(). This is hacky and incomplete. It will deadlock if async module loading nests; however, this works around the known problem case and seems to be the best of bad options.

For more details, please refer to the following thread.

http://thread.gmane.org/gmane.linux.kernel/1420814

---
It makes me feel dirty but makes the problem go away and I can't think of anything better, so here is the implementation of "used async" workaround.

Thanks.

 include/linux/sched.h |    1 +
 kernel/async.c        |    3 +++
 kernel/module.c       |   27 +++++++++++++++++++++++++--
 3 files changed, 29 insertions(+), 2 deletions(-)

@@ -1810,6 +1810,7 @@ extern void thread_group_cputime_adjuste
 #define PF_MEMALLOC	0x00000800	/* Allocating memory */
 #define PF_NPROC_EXCEEDED 0x00001000	/* set_user noticed that RLIMIT_NPROC was exceeded */
 #define PF_USED_MATH	0x00002000	/* if unset the fpu must be initialized before use */
+#define PF_USED_ASYNC	0x00004000	/* used async_schedule*(), used by module init */
 #define PF_NOFREEZE	0x00008000	/* this thread should not be frozen */
 #define PF_FROZEN	0x00010000	/* frozen for system suspend */
 #define PF_FSTRANS	0x00020000	/* inside a filesystem transaction */

@@ -196,6 +196,9 @@ static async_cookie_t __async_schedule(a
 	atomic_inc(&entry_count);
 	spin_unlock_irqrestore(&async_lock, flags);
 
+	/* mark that this task has queued an async job, used by module init */
+	current->flags |= PF_USED_ASYNC;
+
 	/* schedule for execution */
 	queue_work(system_unbound_wq, &entry->work);
 

@@ -3013,6 +3013,12 @@ static int do_init_module(struct module
 {
 	int ret = 0;
 
+	/*
+	 * We want to find out whether @mod uses async during init.  Clear
+	 * PF_USED_ASYNC.  async_schedule*() will set it.
+	 */
+	current->flags &= ~PF_USED_ASYNC;
+
 	blocking_notifier_call_chain(&module_notify_list,
 			MODULE_STATE_COMING, mod);
 

@@ -3058,8 +3064,25 @@ static int do_init_module(struct module
 	blocking_notifier_call_chain(&module_notify_list,
 				     MODULE_STATE_LIVE, mod);
 
-	/* We need to finish all async code before the module init sequence is done */
-	async_synchronize_full();
+	/*
+	 * We need to finish all async code before the module init sequence
+	 * is done.  This has potential to deadlock.  For example, a newly
+	 * detected block device can trigger request_module() of the
+	 * default iosched from async probing task.  Once userland helper
+	 * reaches here, async_synchronize_full() will wait on the async
+	 * task waiting on request_module() and deadlock.
+	 *
+	 * This deadlock is avoided by perfomring async_synchronize_full()
+	 * iff module init queued any async jobs.  This isn't a full
+	 * solution as it will deadlock the same if module loading from
+	 * async jobs nests more than once; however, due to the various
+	 * constraints, this hack seems to be the best option for now.
+	 * Please refer to the following thread for details.
+	 *
+	 * http://thread.gmane.org/gmane.linux.kernel/1420814
+	 */
+	if (current->flags & PF_USED_ASYNC)
+		async_synchronize_full();
 
 	mutex_lock(&module_mutex);
 	/* Drop initial reference. */

Ok, people, can we get a tested-by (or "Nope, doesn't work") from the people who saw this?

That said, maybe we could just make the rule be that you can't pick a default IO scheduler that is modular.

And I *would* like to see the warning we discussed. Maybe there are other situations that can trigger this?

Because something like that

    WARN_ON_ONCE(wait && i_am_async() && system_state == SYSTEM_RUNNING);

in kernel/kmod.c (__request_module()) still sounds like a good idea to verify that this is the only thing that triggers it (of course, we'd need to somehow avoid the warning for the known case with the known workaround).

Linus

Hello, Linus.

This is definitely much more preferable but it would affect use case where everything is built modular and the elevator is selected via kernel param. This is way outside the usual usage and we can warn about the new behavior but it still is an observable behavior change. Do you think this would be okay?

And then this warning can be added without introducing request_module_but_dont_warn_about_being_called_from_async().

Thanks.

tejun

I do want the same user-visible semantics, so it's not some one-liner.

The compiled-in elevator would be easy enough to handle in the Kconfig file (maybe we do already, I didn't even bother to check). The real problem is the "chosen_elevator" one, which is dynamic with the kernel command line. And we could handle that one by just trying to load the module early (but exactly _when_?) and then instead of looking things up by name, just keep a pointer to the default elevator around.

But no, it's not just some trivial one-liner. Especially the question about "when to try to load the module that is given on the kernel command line" is not trivial. Do we require that the module is in the initrd and loadable basically immediate at boot? Do we try again after switching the root filesystem? Things like that..

I do agree that it would be much nicer that way.

Linus

to load it from the root fs you tend to need... an elevator ;-)

I think it's pretty fair to users to say that if you want something by default at boot time, you need to build it in...
but for us to try a modprobe from the initrd is not too bad I suppose. probably need to do this around the time we initialize the block layer

Hey,

If the current user-visible semantics is defined as "the kernel shall try to load the default iosched if not already available on each block device discovery", nothing can be changed ever, but I'm not sure it needs to be pushed that far.

As Arjan suggested, trying to load the default modules right after the initial rootfs mount could be an acceptable compromise and it would be really nice (for both code sanity and avoiding future problems) to be able to declare module loading nested inside async unspported.

Thanks.

tejun

we can even try twice

the first time right after we mount the initramfs
the second time when the initramfs code exits, and before we exec init (the initramfs supposedly mounted the real root fs at this point)

if you want your elevator to apply to your root filesystem storage, the rule will then be "put the module in the initramfs"... but to be honest, that's not a restriction that is unreasonable or unexpected.

for doing a module loading from inside an async handler..we can then just make use of the normal "load this module async" way of requesting a module.

Yes. This, together with "don't try request_module for the default elevator", and the "warn if somebody does request_module from async context" would, I think, be the right thing to do.

In the meantime, I've applied Tejun's patch. It possibly speeds things up regardless of this particular deadlock thing, and while it's not pretty it certainly isn't horribly nasty or very invasive either, so I don't see any reason to delay it just because there might be a better solution some day.

Linus

This patch adds default module loading and uses it to load the default block elevator. During boot, it's called right after initramfs or initrd is made available and right before control is passed to userland. This ensures that as long as the modules are available in the usual places in initramfs, initrd or the root filesystem, the default modules are loaded as soon as possible.

This will replace the on-demand elevator module loading from elevator init path.

---
 block/elevator.c         |   16 ++++++++++++++++
 include/linux/elevator.h |    1 +
 include/linux/init.h     |    1 +
 init/do_mounts_initrd.c  |    3 +++
 init/initramfs.c         |    8 +++++++-
 init/main.c              |   16 ++++++++++++++++
 6 files changed, 44 insertions(+), 1 deletion(-)

@@ -136,6 +136,22 @@ static int __init elevator_setup(char *s
 
 __setup("elevator=", elevator_setup);
 
+/* called during boot to load the elevator chosen by the elevator param */
+void __init load_default_elevator_module(void)
+{
+	struct elevator_type *e;
+
+	if (!chosen_elevator[0])
+		return;
+
+	spin_lock(&elv_list_lock);
+	e = elevator_find(chosen_elevator);
+	spin_unlock(&elv_list_lock);
+
+	if (!e)
+		request_module("%s-iosched", chosen_elevator);
+}
+
 static struct kobj_type elv_ktype;
 
 static struct elevator_queue *elevator_alloc(struct request_queue *q,

@@ -138,6 +138,7 @@ extern void elv_drain_elevator(struct re
 /*
  * io scheduler registration
  */
+extern void __init load_default_elevator_module(void);
 extern int elv_register(struct elevator_type *);
 extern void elv_unregister(struct elevator_type *);
 

@@ -161,6 +161,7 @@ extern unsigned int reset_devices;
 /* used by init/main.c */
 void setup_arch(char **);
 void prepare_namespace(void);
+void __init load_default_modules(void);
 
 extern void (*late_time_init)(void);
 

@@ -57,6 +57,9 @@ static void __init handle_initrd(void)
 	sys_mkdir("/old", 0700);
 	sys_chdir("/old");
 
+	/* try loading default modules from initrd */
+	load_default_modules();
+
 	/*
 	 * In case that a resume from disk is carried out by linuxrc or one of
 	 * its children, we need to tell the freezer not to wait for us.

@@ -592,7 +592,7 @@ static int __init populate_rootfs(void)
 			initrd_end - initrd_start);
 		if (!err) {
 			free_initrd();
-			return 0;
+			goto done;
 		} else {
 			clean_rootfs();
 			unpack_to_rootfs(__initramfs_start, __initramfs_size);

@@ -607,6 +607,7 @@ static int __init populate_rootfs(void)
 			sys_close(fd);
 			free_initrd();
 		}
+	done:
 #else
 		printk(KERN_INFO "Unpacking initramfs...\n");
 		err = unpack_to_rootfs((char *)initrd_start,

@@ -615,6 +616,11 @@ static int __init populate_rootfs(void)
 			printk(KERN_EMERG "Initramfs unpacking failed: %s\n", err);
 		free_initrd();
 #endif
+		/*
+		 * Try loading default modules from initramfs.  This gives
+		 * us a chance to load before device_initcalls.
+		 */
+		load_default_modules();
 	}
 	return 0;
 }

@@ -70,6 +70,8 @@
 #include <linux/perf_event.h>
 #include <linux/file.h>
 #include <linux/ptrace.h>
+#include <linux/blkdev.h>
+#include <linux/elevator.h>
 
 #include <asm/io.h>
 #include <asm/bugs.h>

@@ -794,6 +796,17 @@ static void __init do_pre_smp_initcalls(
 		do_one_initcall(*fn);
 }
 
+/*
+ * This function requests modules which should be loaded by default and is
+ * called twice right after initrd is mounted and right before init is
+ * exec'd.  If such modules are on either initrd or rootfs, they will be
+ * loaded before control is passed to userland.
+ */
+void __init load_default_modules(void)
+{
+	load_default_elevator_module();
+}
+
 static int run_init_process(const char *init_filename)
 {
 	argv_init[0] = init_filename;

@@ -900,4 +913,7 @@ static void __init kernel_init_freeable(
 	 * we're essentially up and running. Get rid of the
 	 * initmem segments and start the user-mode stuff..
 	 */
+
+	/* rootfs is available now, try loading default modules */
+	load_default_modules();
 }

And here I was really hoping that there was a third patch in the series that added the warning...

We don't currently have a "am I an async worker" helper function for the warning to use, which is something very much up your alley.

Linus

Hello, Linus.

Oh yeah, it's coming. I just wanted to finish something else first and, as turning on PF_WQ_WORKER on a rescuer thread has some chance of developing into an obscure difficult-to-trigger and diagnose problem, don't want to hurry it too much.

Thanks.

tejun

Ok. I think I'll delay these things for 3.9 anyway, since the actual _problem_ people are seeing should be fixed with your other patch. So I guess it's not really all that critical any more.

Linus

If you're okay with it, I'll route these two and the patches to add warning through a wq branch. There's already a wq/for-3.9 patch which am_i_async() can make use of, so it's gonna be easier this way.

Thanks.

tejun

Sounds good to me. Thanks,

Linus

PF_WQ_WORKER is used to tell scheduler that the task is a workqueue worker and needs wq_worker_sleeping/waking_up() invoked on it for concurrency management. As rescuers never participate in concurrency management, PF_WQ_WORKER wasn't set on them.

There's a need for an interface which can query whether %current is executing a work item and if so which. Such interface requires a way to identify all tasks which may execute work items and PF_WQ_WORKER will be used for that. As all normal workers always have PF_WQ_WORKER set, we only need to add it to rescuers.

As rescuers start with WORKER_PREP but never clear it, it's always NOT_RUNNING and there's no need to worry about it interfering with concurrency management even if PF_WQ_WORKER is set; however, unlike normal workers, rescuers currently don't have its worker struct as kthread_data(). It uses the associated workqueue_struct instead. This is problematic as wq_worker_sleeping/waking_up() expect struct worker at kthread_data().

This patch adds worker->rescue_wq and start rescuer kthreads with worker struct as kthread_data and sets PF_WQ_WORKER on rescuers.

---
These three patches implement the warning on synchronous request_module() from async. The first two will go through wq/for-3.9 and the last one through wq/for-3.9-async-deadlock-fixes together with the block layer updates.

Thanks.

 kernel/workqueue.c | 35 ++++++++++++++++++++++++++++-------
 1 file changed, 28 insertions(+), 7 deletions(-)

index 7967f34..6b99ac7 100644
@@ -149,6 +149,9 @@ struct worker {
 
 	/* for rebinding worker to CPU */
 	struct work_struct	rebind_work;	/* L: for busy worker */
+
+	/* used only by rescuers to point to the target workqueue */
+	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
 };
 
 struct worker_pool {

@@ -763,12 +766,20 @@ struct task_struct *wq_worker_sleeping(struct task_struct *task,
 				       unsigned int cpu)
 {
 	struct worker *worker = kthread_data(task), *to_wakeup = NULL;
-	struct worker_pool *pool = worker->pool;
-	atomic_t *nr_running = get_pool_nr_running(pool);
+	struct worker_pool *pool;
+	atomic_t *nr_running;
 
+	/*
+	 * Rescuers, which may not have all the fields set up like normal
+	 * workers, also reach here, let's not access anything before
+	 * checking NOT_RUNNING.
+	 */
 	if (worker->flags & WORKER_NOT_RUNNING)
 		return NULL;
 
+	pool = worker->pool;
+	nr_running = get_pool_nr_running(pool);
+
 	/* this can only happen on the local cpu */
 	BUG_ON(cpu != raw_smp_processor_id());
 

@@ -2357,7 +2368,7 @@ sleep:
 
 /**
  * rescuer_thread - the rescuer thread function
- * @__wq: the associated workqueue
+ * @__rescuer: self
  *
  * Workqueue rescuer thread function.  There's one rescuer for each
  * workqueue which has WQ_RESCUER set.

@@ -2374,20 +2385,27 @@ sleep:
  *
  * This should happen rarely.
  */
-static int rescuer_thread(void *__wq)
+static int rescuer_thread(void *__rescuer)
 {
-	struct workqueue_struct *wq = __wq;
-	struct worker *rescuer = wq->rescuer;
+	struct worker *rescuer = __rescuer;
+	struct workqueue_struct *wq = rescuer->rescue_wq;
 	struct list_head *scheduled = &rescuer->scheduled;
 	bool is_unbound = wq->flags & WQ_UNBOUND;
 	unsigned int cpu;
 
 	set_user_nice(current, RESCUER_NICE_LEVEL);
+
+	/*
+	 * Mark rescuer as worker too.  As WORKER_PREP is never cleared, it
+	 * doesn't participate in concurrency management.
+	 */
+	rescuer->task->flags |= PF_WQ_WORKER;
 repeat:
 	set_current_state(TASK_INTERRUPTIBLE);
 
 	if (kthread_should_stop()) {
 		__set_current_state(TASK_RUNNING);
+		rescuer->task->flags &= ~PF_WQ_WORKER;
 		return 0;
 	}
 

@@ -2431,6 +2449,8 @@ repeat:
 		spin_unlock_irq(&gcwq->lock);
 	}
 
+	/* rescuers should never participate in concurrency management */
+	WARN_ON_ONCE(!(rescuer->flags & WORKER_NOT_RUNNING));
 	schedule();
 	goto repeat;
 }

@@ -3266,7 +3286,8 @@ struct workqueue_struct *__alloc_workqueue_key(const char *fmt,
 		if (!rescuer)
 			goto err;
 
-		rescuer->task = kthread_create(rescuer_thread, wq, "%s",
+		rescuer->rescue_wq = wq;
+		rescuer->task = kthread_create(rescuer_thread, rescuer, "%s",
 					       wq->name);
 		if (IS_ERR(rescuer->task))
 			goto err;

1.8.0.2

Implement work/async_current_func() which query whether the current task is a workqueue or async worker respectively and, if so, return the current function being executed along with work / async item related information.

This will be used to implement warning on synchronous request_module() from async workers.

---
 include/linux/async.h     |  2 ++
 include/linux/workqueue.h |  1 +
 kernel/async.c            | 25 +++++++++++++++++++++++++
 kernel/workqueue.c        | 22 ++++++++++++++++++++++
 4 files changed, 50 insertions(+)

index 7a24fe9..6c49157 100644
@@ -52,4 +52,6 @@ extern void async_synchronize_full_domain(struct async_domain *domain);
 extern void async_synchronize_cookie(async_cookie_t cookie);
 extern void async_synchronize_cookie_domain(async_cookie_t cookie,
 					    struct async_domain *domain);
+extern async_func_ptr *async_current_func(void **datap,
+					  async_cookie_t *cookiep);
 #endif

index 2b58905..984fbef 100644
@@ -428,6 +428,7 @@ extern void workqueue_set_max_active(struct workqueue_struct *wq,
 extern bool workqueue_congested(unsigned int cpu, struct workqueue_struct *wq);
 extern unsigned int work_cpu(struct work_struct *work);
 extern unsigned int work_busy(struct work_struct *work);
+extern work_func_t work_current_func(struct work_struct **workp);
 
 /*
  * Like above, but uses del_timer() instead of del_timer_sync(). This means,

index 9d31183..ed1eda0 100644
@@ -337,3 +337,28 @@ void async_synchronize_cookie(async_cookie_t cookie)
 	async_synchronize_cookie_domain(cookie, &async_running);
 }
 EXPORT_SYMBOL_GPL(async_synchronize_cookie);
+
+/**
+ * async_current_func - determine the async entry %current is executing
+ * @datap: optional out param for the data
+ * @cookiep: optional out param for the cookie
+ *
+ * Determine whether %current is an async worker executing an async_entry
+ * and if so return the async function and, if @cookiep is not %NULL, the
+ * cookie.  If %current isn't executing an async_entry, %NULL is returned.
+ */
+async_func_ptr *async_current_func(void **datap, async_cookie_t *cookiep)
+{
+	struct work_struct *work;
+	struct async_entry *entry;
+
+	if (work_current_func(&work) != async_run_entry_fn)
+		return NULL;
+
+	entry = container_of(work, struct async_entry, work);
+	if (datap)
+		*datap = entry->data;
+	if (cookiep)
+		*cookiep = entry->cookie;
+	return entry->func;
+}

index 6b99ac7..9fc1549 100644
@@ -3492,6 +3492,28 @@ unsigned int work_busy(struct work_struct *work)
 }
 EXPORT_SYMBOL_GPL(work_busy);
 
+/**
+ * work_current_func - determine the work fn and item %current is executing
+ * @workp: optional out param for the current work item
+ *
+ * Determine whether %current is a kworker executing a work item and if so
+ * return the work function and, if @workp is not %NULL, the work item.  If
+ * %current isn't executing a work item, %NULL is returned.
+ */
+work_func_t work_current_func(struct work_struct **workp)
+{
+	struct worker *worker;
+
+	/* am I a kworker? */
+	if (!(current->flags & PF_WQ_WORKER))
+		return NULL;
+
+	worker = kthread_data(current);
+	if (workp)
+		*workp = worker->current_work;
+	return worker->current_func;
+}
+
 /*
  * CPU hotplug.
  *

1.8.0.2

So why the odd interface? The only user of it calls it with a NULL/NULL pair of arguments, and in general it's just way too complex to be an exported function at all. I *suspect* you chose that complex interface because you feel you may have some use for it inside of the async code itself, but why isn't that then not totally private to there?

IOW, why isn't the interface just

   static struct worker *current_worker(void)
   {
      if (current->flags & PF_WQ_WORKER)
         return kthread_data(current);
      return NULL;
   }

   int current_is_async(void)
   {
      struct worker *worker = current_worker(void);
      return worker && worker->current_func == async_run_entry_fn;
   }

and that current_is_async() is enough for the exported interface.

Then, if you actually want to care about the work itself, you can use that same "current_worker()" helper function, and look at the different worker fields more. But why export that kind of logic?

Am I missing something?

Linus

Hello, Linus.

Yeah, I was doing something else in async and arguing between that and current_is_async() and ended up keeping it as it was consistent with the workqueue counterpart.

I'd prefer to keep struct worker inside workqueue.c, so how about keeping the workqueue part and make async part current_is_async()?

Thanks.

tejun

Another thing is that it seems like having introspection type interface often lead to abuses - work_pending(), work_busy() both ended up bringing more unnecessary dependencies and subtle bugginess on internal details than actual benefits. Querying %current is much less likely to be harmful in itself but I'm afraid it might encourage its users to develop something crazy on top. It might be a good idea to make it only available to async.

Thanks.

tejun

I'm not sure I understand what you mean? Do you mean trying to limit work_current_func() to only be accessible to the async code? You'd have to make some kind of private header file under kernel/ for that, but I guess that would work fine. We already do something similar inside filesystems etc, where they have their own local headers.

I still don't really see what other data the async code could possibly ever want than the "is this an async thread" I guess if you want to keep all these things private to their own C files with no leaving of the structure definitions (even within just a private kernel/worker.h file or something) you could make the interface be one like

- kernel/workqueue.c:

      int current_uses_workfn(work_func_t match)
      {
         if (current->flags & PF_WQ_WORKER) {
            struct worker *worker = kthread_data(current);
            return worker && match == worker->current_func;
         }
         return 0;
      }

- kernel/async.c:

      int current_is_async(void)
      {
         return current_uses_workfn(async_run_entry_fn);
      }

but quite frankly, we've generally tried to avoid those kinds of silly wrappers just because it's very wasteful to do two function calls just to hide some detail like this. The code generation is atrocious, jumping around for no good reason just increases cache pressure etc.

Yes, yes, some globally optimizing compiler could sort it all out, but I'd personally be inclined to just move all the structure definitions into kernel/worker.h, and make the code be inline functions. The only actual current *user* would also be in the kernel/ subdirectory, and we don't know if we'd ever want to really expand it past there.

Hmm?

Linus

Yeap, and I'm unsure whether it's worth introducing a new internal header file.

If we're gonna make it kernel/ internal thing with internal header, we definitely can go all the way. It's a bit meh because the code path involved is very cold. Hmm... I'll make it that way. I like how it keeps the thing apparently internal.

Thanks.

tejun

From: Tejun Heo <[email protected]>
Date: Thu, 17 Jan 2013 17:16:24 -0800

PF_WQ_WORKER is used to tell scheduler that the task is a workqueue worker and needs wq_worker_sleeping/waking_up() invoked on it for concurrency management. As rescuers never participate in concurrency management, PF_WQ_WORKER wasn't set on them.

There's a need for an interface which can query whether %current is executing a work item and if so which. Such interface requires a way to identify all tasks which may execute work items and PF_WQ_WORKER will be used for that. As all normal workers always have PF_WQ_WORKER set, we only need to add it to rescuers.

As rescuers start with WORKER_PREP but never clear it, it's always NOT_RUNNING and there's no need to worry about it interfering with concurrency management even if PF_WQ_WORKER is set; however, unlike normal workers, rescuers currently don't have its worker struct as kthread_data(). It uses the associated workqueue_struct instead. This is problematic as wq_worker_sleeping/waking_up() expect struct worker at kthread_data().

This patch adds worker->rescue_wq and start rescuer kthreads with worker struct as kthread_data and sets PF_WQ_WORKER on rescuers.

---
This one is the same as last time.

 kernel/workqueue.c | 35 ++++++++++++++++++++++++++++-------
 1 file changed, 28 insertions(+), 7 deletions(-)

index 7967f34..6b99ac7 100644
@@ -149,6 +149,9 @@ struct worker {
 
 	/* for rebinding worker to CPU */
 	struct work_struct	rebind_work;	/* L: for busy worker */
+
+	/* used only by rescuers to point to the target workqueue */
+	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
 };
 
 struct worker_pool {

@@ -763,12 +766,20 @@ struct task_struct *wq_worker_sleeping(struct task_struct *task,
 				       unsigned int cpu)
 {
 	struct worker *worker = kthread_data(task), *to_wakeup = NULL;
-	struct worker_pool *pool = worker->pool;
-	atomic_t *nr_running = get_pool_nr_running(pool);
+	struct worker_pool *pool;
+	atomic_t *nr_running;
 
+	/*
+	 * Rescuers, which may not have all the fields set up like normal
+	 * workers, also reach here, let's not access anything before
+	 * checking NOT_RUNNING.
+	 */
 	if (worker->flags & WORKER_NOT_RUNNING)
 		return NULL;
 
+	pool = worker->pool;
+	nr_running = get_pool_nr_running(pool);
+
 	/* this can only happen on the local cpu */
 	BUG_ON(cpu != raw_smp_processor_id());
 

@@ -2357,7 +2368,7 @@ sleep:
 
 /**
  * rescuer_thread - the rescuer thread function
- * @__wq: the associated workqueue
+ * @__rescuer: self
  *
  * Workqueue rescuer thread function.  There's one rescuer for each
  * workqueue which has WQ_RESCUER set.

@@ -2374,20 +2385,27 @@ sleep:
  *
  * This should happen rarely.
  */
-static int rescuer_thread(void *__wq)
+static int rescuer_thread(void *__rescuer)
 {
-	struct workqueue_struct *wq = __wq;
-	struct worker *rescuer = wq->rescuer;
+	struct worker *rescuer = __rescuer;
+	struct workqueue_struct *wq = rescuer->rescue_wq;
 	struct list_head *scheduled = &rescuer->scheduled;
 	bool is_unbound = wq->flags & WQ_UNBOUND;
 	unsigned int cpu;
 
 	set_user_nice(current, RESCUER_NICE_LEVEL);
+
+	/*
+	 * Mark rescuer as worker too.  As WORKER_PREP is never cleared, it
+	 * doesn't participate in concurrency management.
+	 */
+	rescuer->task->flags |= PF_WQ_WORKER;
 repeat:
 	set_current_state(TASK_INTERRUPTIBLE);
 
 	if (kthread_should_stop()) {
 		__set_current_state(TASK_RUNNING);
+		rescuer->task->flags &= ~PF_WQ_WORKER;
 		return 0;
 	}
 

@@ -2431,6 +2449,8 @@ repeat:
 		spin_unlock_irq(&gcwq->lock);
 	}
 
+	/* rescuers should never participate in concurrency management */
+	WARN_ON_ONCE(!(rescuer->flags & WORKER_NOT_RUNNING));
 	schedule();
 	goto repeat;
 }

@@ -3266,7 +3286,8 @@ struct workqueue_struct *__alloc_workqueue_key(const char *fmt,
 		if (!rescuer)
 			goto err;
 
-		rescuer->task = kthread_create(rescuer_thread, wq, "%s",
+		rescuer->rescue_wq = wq;
+		rescuer->task = kthread_create(rescuer_thread, rescuer, "%s",
 					       wq->name);
 		if (IS_ERR(rescuer->task))
 			goto err;

1.8.0.2

From: Tejun Heo <[email protected]>
Date: Fri, 18 Jan 2013 14:05:55 -0800

Workqueue wants to expose more interface internal to kernel/. Instead of adding a new header file, repurpose kernel/workqueue_sched.h. Rename it to workqueue_internal.h and add include protector.

This patch doesn't introduce any functional changes.

---
Ingo, Peter, changes to scheduler is trivial. If there's no objection, I'd like to route this with the rest of workqueue and async changes.

Thanks.

 kernel/sched/core.c         |  2 +-
 kernel/workqueue.c          |  2 +-
 kernel/workqueue_internal.h | 18 ++++++++++++++++++
 kernel/workqueue_sched.h    |  9 ---------
 4 files changed, 20 insertions(+), 11 deletions(-)
 create mode 100644 kernel/workqueue_internal.h
 delete mode 100644 kernel/workqueue_sched.h

index 257002c..c6737f4f 100644
@@ -83,7 +83,7 @@
 #endif
 
 #include "sched.h"
-#include "../workqueue_sched.h"
+#include "../workqueue_internal.h"
 #include "../smpboot.h"
 
 #define CREATE_TRACE_POINTS

index 6b99ac7..b4e9206 100644
@@ -43,7 +43,7 @@
 #include <linux/idr.h>
 #include <linux/hashtable.h>
 
-#include "workqueue_sched.h"
+#include "workqueue_internal.h"
 
 enum {
 	/*

new file mode 100644
index 0000000..b3ea6ad
@@ -0,0 +1,18 @@
+/*
+ * kernel/workqueue_internal.h
+ *
+ * Workqueue internal header file.  Only to be included by workqueue and
+ * core kernel subsystems.
+ */
+#ifndef _KERNEL_WORKQUEUE_INTERNAL_H
+#define _KERNEL_WORKQUEUE_INTERNAL_H
+
+/*
+ * Scheduler hooks for concurrency managed workqueue.  Only to be used from
+ * sched.c and workqueue.c.
+ */
+void wq_worker_waking_up(struct task_struct *task, unsigned int cpu);
+struct task_struct *wq_worker_sleeping(struct task_struct *task,
+				       unsigned int cpu);
+
+#endif /* _KERNEL_WORKQUEUE_INTERNAL_H */

deleted file mode 100644
index 2d10fc9..0000000
@@ -1,9 +0,0 @@
-/*
- * kernel/workqueue_sched.h
- *
- * Scheduler hooks for concurrency managed workqueue.  Only to be
- * included from sched.c and workqueue.c.
- */
-void wq_worker_waking_up(struct task_struct *task, unsigned int cpu);
-struct task_struct *wq_worker_sleeping(struct task_struct *task,
-				       unsigned int cpu);

1.8.0.2

From: Tejun Heo <[email protected]>
Date: Fri, 18 Jan 2013 14:05:55 -0800

This will be used to implement an inline function to query whether %current is a workqueue worker and, if so, allow determining which work item it's executing.

---
 kernel/workqueue.c          | 32 +-------------------------------
 kernel/workqueue_internal.h | 37 +++++++++++++++++++++++++++++++++++++
 2 files changed, 38 insertions(+), 31 deletions(-)

index b4e9206..2ffa240 100644
@@ -122,37 +122,7 @@ enum {
  * W: workqueue_lock protected.
  */
 
-struct global_cwq;
-struct worker_pool;
-
-/*
- * The poor guys doing the actual heavy lifting.  All on-duty workers
- * are either serving the manager role, on idle list or on busy hash.
- */
-struct worker {
-	/* on idle list while idle, on busy hash table while busy */
-	union {
-		struct list_head	entry;	/* L: while idle */
-		struct hlist_node	hentry;	/* L: while busy */
-	};
-
-	struct work_struct	*current_work;	/* L: work being processed */
-	work_func_t		current_func;	/* L: current_work's fn */
-	struct cpu_workqueue_struct *current_cwq; /* L: current_work's cwq */
-	struct list_head	scheduled;	/* L: scheduled works */
-	struct task_struct	*task;		/* I: worker task */
-	struct worker_pool	*pool;		/* I: the associated pool */
-	/* 64 bytes boundary on 64bit, 32 on 32bit */
-	unsigned long		last_active;	/* L: last active timestamp */
-	unsigned int		flags;		/* X: flags */
-	int			id;		/* I: worker id */
-
-	/* for rebinding worker to CPU */
-	struct work_struct	rebind_work;	/* L: for busy worker */
-
-	/* used only by rescuers to point to the target workqueue */
-	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
-};
+/* struct worker is defined in workqueue_internal.h */
 
 struct worker_pool {
 	struct global_cwq	*gcwq;		/* I: the owning gcwq */

index b3ea6ad..02549fa 100644
@@ -7,6 +7,43 @@
 #ifndef _KERNEL_WORKQUEUE_INTERNAL_H
 #define _KERNEL_WORKQUEUE_INTERNAL_H
 
+#include <linux/workqueue.h>
+
+struct global_cwq;
+struct worker_pool;
+
+/*
+ * The poor guys doing the actual heavy lifting.  All on-duty workers are
+ * either serving the manager role, on idle list or on busy hash.  For
+ * details on the locking annotation (L, I, X...), refer to workqueue.c.
+ *
+ * Only to be used in workqueue and async.
+ */
+struct worker {
+	/* on idle list while idle, on busy hash table while busy */
+	union {
+		struct list_head	entry;	/* L: while idle */
+		struct hlist_node	hentry;	/* L: while busy */
+	};
+
+	struct work_struct	*current_work;	/* L: work being processed */
+	work_func_t		current_func;	/* L: current_work's fn */
+	struct cpu_workqueue_struct *current_cwq; /* L: current_work's cwq */
+	struct list_head	scheduled;	/* L: scheduled works */
+	struct task_struct	*task;		/* I: worker task */
+	struct worker_pool	*pool;		/* I: the associated pool */
+	/* 64 bytes boundary on 64bit, 32 on 32bit */
+	unsigned long		last_active;	/* L: last active timestamp */
+	unsigned int		flags;		/* X: flags */
+	int			id;		/* I: worker id */
+
+	/* for rebinding worker to CPU */
+	struct work_struct	rebind_work;	/* L: for busy worker */
+
+	/* used only by rescuers to point to the target workqueue */
+	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
+};
+
 /*
  * Scheduler hooks for concurrency managed workqueue.  Only to be used from
  * sched.c and workqueue.c.

1.8.0.2

From: Tejun Heo <[email protected]>
Date: Fri, 18 Jan 2013 14:05:56 -0800

This function queries whether %current is an async worker executing an async item. This will be used to implement warning on synchronous request_module() from async workers.

---
 include/linux/async.h       |  1 +
 kernel/async.c              | 14 ++++++++++++++
 kernel/workqueue_internal.h | 11 +++++++++++
 3 files changed, 26 insertions(+)

index 7a24fe9..345169c 100644
@@ -52,4 +52,5 @@ extern void async_synchronize_full_domain(struct async_domain *domain);
 extern void async_synchronize_cookie(async_cookie_t cookie);
 extern void async_synchronize_cookie_domain(async_cookie_t cookie,
 					    struct async_domain *domain);
+extern bool current_is_async(void);
 #endif

index 9d31183..d9bf2a9 100644
@@ -57,6 +57,8 @@ asynchronous and synchronous parts of the kernel.
 #include <linux/slab.h>
 #include <linux/workqueue.h>
 
+#include "workqueue_internal.h"
+
 static async_cookie_t next_cookie = 1;
 
 #define MAX_WORK	32768

@@ -337,3 +339,15 @@ void async_synchronize_cookie(async_cookie_t cookie)
 	async_synchronize_cookie_domain(cookie, &async_running);
 }
 EXPORT_SYMBOL_GPL(async_synchronize_cookie);
+
+/**
+ * current_is_async - is %current an async worker task?
+ *
+ * Returns %true if %current is an async worker task.
+ */
+bool current_is_async(void)
+{
+	struct worker *worker = current_wq_worker();
+
+	return worker && worker->current_func == async_run_entry_fn;
+}

index 02549fa..cc35e7e 100644
@@ -8,6 +8,7 @@
 #define _KERNEL_WORKQUEUE_INTERNAL_H
 
 #include <linux/workqueue.h>
+#include <linux/kthread.h>
 
 struct global_cwq;
 struct worker_pool;

@@ -44,6 +45,16 @@ struct worker {
 	struct workqueue_struct	*rescue_wq;	/* I: the workqueue to rescue */
 };
 
+/**
+ * current_wq_worker - return struct worker if %current is a workqueue worker
+ */
+static inline struct worker *current_wq_worker(void)
+{
+	if (current->flags & PF_WQ_WORKER)
+		return kthread_data(current);
+	return NULL;
+}
+
 /*
  * Scheduler hooks for concurrency managed workqueue.  Only to be used from
  * sched.c and workqueue.c.

1.8.0.2

From: Tejun Heo <[email protected]>
Date: Fri, 18 Jan 2013 14:05:57 -0800

Synchronous requet_module() from an async worker can lead to deadlock because module init path may invoke async_synchronize_full(). The async worker waits for request_module() to complete and the module loading waits for the async task to finish. This bug happened in the block layer because of default elevator auto-loading.

Block layer has been updated not to do default elevator auto-loading and it has been decided to disallow synchronous request_module() from async workers.

Trigger WARN_ON_ONCE() on synchronous request_module() from async workers.

For more details, please refer to the following thread.

http://thread.gmane.org/gmane.linux.kernel/1420814

---
 kernel/kmod.c | 9 +++++++++
 1 file changed, 9 insertions(+)

index 1c317e3..ecd42b4 100644
@@ -38,6 +38,7 @@
 #include <linux/suspend.h>
 #include <linux/rwsem.h>
 #include <linux/ptrace.h>
+#include <linux/async.h>
 #include <asm/uaccess.h>
 
 #include <trace/events/module.h>

@@ -130,6 +131,14 @@ int __request_module(bool wait, const char *fmt, ...)
 #define MAX_KMOD_CONCURRENT 50	/* Completely arbitrary value - KAO */
 	static int kmod_loop_msg;
 
+	/*
+	 * We don't allow synchronous module loading from async.  Module
+	 * init may invoke async_synchronize_full() which will end up
+	 * waiting for this task which already is waiting for the module
+	 * loading to complete, leading to a deadlock.
+	 */
+	WARN_ON_ONCE(wait && current_is_async());
+
 	va_start(args, fmt);
 	ret = vsnprintf(module_name, MODULE_NAME_LEN, fmt, args);
 	va_end(args);

1.8.0.2

Synchronous requet_module() from an async worker can lead to deadlock because module init path may invoke async_synchronize_full(). The async worker waits for request_module() to complete and the module loading waits for the async task to finish. This bug happened in the block layer because of default elevator auto-loading.

Block layer has been updated not to do default elevator auto-loading and it has been decided to disallow synchronous request_module() from async workers.

Trigger WARN_ON_ONCE() on synchronous request_module() from async workers.

For more details, please refer to the following thread.

http://thread.gmane.org/gmane.linux.kernel/1420814

---
Linus, please note that I dropped system_state == SYSTEM_RUNNING condition from WARN_ON_ONCE() as the deadlock can happen during system init too - e.g. libata probing block device using async making block layer try to load default elevator from initramfs.

Thanks.

 kernel/kmod.c | 9 +++++++++
 1 file changed, 9 insertions(+)

index 1c317e3..028287e 100644
@@ -38,6 +38,7 @@
 #include <linux/suspend.h>
 #include <linux/rwsem.h>
 #include <linux/ptrace.h>
+#include <linux/async.h>
 #include <asm/uaccess.h>
 
 #include <trace/events/module.h>

@@ -130,6 +131,14 @@ int __request_module(bool wait, const char *fmt, ...)
 #define MAX_KMOD_CONCURRENT 50	/* Completely arbitrary value - KAO */
 	static int kmod_loop_msg;
 
+	/*
+	 * We don't allow synchronous module loading from async.  Module
+	 * init may invoke async_synchronize_full() which will end up
+	 * waiting for this task which already is waiting for the module
+	 * loading to complete, leading to a deadlock.
+	 */
+	WARN_ON_ONCE(wait && async_current_func(NULL, NULL));
+
 	va_start(args, fmt);
 	ret = vsnprintf(module_name, MODULE_NAME_LEN, fmt, args);
 	va_end(args);

1.8.0.2

From: Tejun Heo <[email protected]>
Date: Fri, 18 Jan 2013 14:05:56 -0800

This patch adds default module loading and uses it to load the default block elevator. During boot, it's called right after initramfs or initrd is made available and right before control is passed to userland. This ensures that as long as the modules are available in the usual places in initramfs, initrd or the root filesystem, the default modules are loaded as soon as possible.

This will replace the on-demand elevator module loading from elevator init path.

v2: Fixed build breakage when !CONFIG_BLOCK. Reported by kbuild test
robot.

---
Minor revision to fix build breakage on !CONFIG_BLOCK reported by Fengguang. The patch is queued to wq/for-3.9-async-deadlock-fixes.

Thanks.

 block/elevator.c         | 16 ++++++++++++++++
 include/linux/elevator.h |  5 +++++
 include/linux/init.h     |  1 +
 init/do_mounts_initrd.c  |  3 +++
 init/initramfs.c         |  8 +++++++-
 init/main.c              | 16 ++++++++++++++++
 6 files changed, 48 insertions(+), 1 deletion(-)

index 9edba1b..c2d61d5 100644
@@ -136,6 +136,22 @@ static int __init elevator_setup(char *str)
 
 __setup("elevator=", elevator_setup);
 
+/* called during boot to load the elevator chosen by the elevator param */
+void __init load_default_elevator_module(void)
+{
+	struct elevator_type *e;
+
+	if (!chosen_elevator[0])
+		return;
+
+	spin_lock(&elv_list_lock);
+	e = elevator_find(chosen_elevator);
+	spin_unlock(&elv_list_lock);
+
+	if (!e)
+		request_module("%s-iosched", chosen_elevator);
+}
+
 static struct kobj_type elv_ktype;
 
 static struct elevator_queue *elevator_alloc(struct request_queue *q,

index c03af76..1866206 100644
@@ -138,6 +138,7 @@ extern void elv_drain_elevator(struct request_queue *);
 /*
  * io scheduler registration
  */
+extern void __init load_default_elevator_module(void);
 extern int elv_register(struct elevator_type *);
 extern void elv_unregister(struct elevator_type *);
 

@@ -206,5 +207,9 @@ enum {
 	INIT_LIST_HEAD(&(rq)->csd.list);	\
 	} while (0)
 
+#else /* CONFIG_BLOCK */
+
+static inline void load_default_elevator_module(void) { }
+
 #endif /* CONFIG_BLOCK */
 #endif

index a799273..9230c94 100644
@@ -161,6 +161,7 @@ extern unsigned int reset_devices;
 /* used by init/main.c */
 void setup_arch(char **);
 void prepare_namespace(void);
+void __init load_default_modules(void);
 
 extern void (*late_time_init)(void);
 

index 5e4ded5..dfe606a 100644
@@ -57,6 +57,9 @@ static void __init handle_initrd(void)
 	sys_mkdir("/old", 0700);
 	sys_chdir("/old");
 
+	/* try loading default modules from initrd */
+	load_default_modules();
+
 	/*
 	 * In case that a resume from disk is carried out by linuxrc or one of
 	 * its children, we need to tell the freezer not to wait for us.

index 84c6bf1..a67ef9d 100644
@@ -592,7 +592,7 @@ static int __init populate_rootfs(void)
 			initrd_end - initrd_start);
 		if (!err) {
 			free_initrd();
-			return 0;
+			goto done;
 		} else {
 			clean_rootfs();
 			unpack_to_rootfs(__initramfs_start, __initramfs_size);

@@ -607,6 +607,7 @@ static int __init populate_rootfs(void)
 			sys_close(fd);
 			free_initrd();
 		}
+	done:
 #else
 		printk(KERN_INFO "Unpacking initramfs...\n");
 		err = unpack_to_rootfs((char *)initrd_start,

@@ -615,6 +616,11 @@ static int __init populate_rootfs(void)
 			printk(KERN_EMERG "Initramfs unpacking failed: %s\n", err);
 		free_initrd();
 #endif
+		/*
+		 * Try loading default modules from initramfs.  This gives
+		 * us a chance to load before device_initcalls.
+		 */
+		load_default_modules();
 	}
 	return 0;
 }

index baf1f0f..18efadb 100644
@@ -70,6 +70,8 @@
 #include <linux/perf_event.h>
 #include <linux/file.h>
 #include <linux/ptrace.h>
+#include <linux/blkdev.h>
+#include <linux/elevator.h>
 
 #include <asm/io.h>
 #include <asm/bugs.h>

@@ -794,6 +796,17 @@ static void __init do_pre_smp_initcalls(void)
 		do_one_initcall(*fn);
 }
 
+/*
+ * This function requests modules which should be loaded by default and is
+ * called twice right after initrd is mounted and right before init is
+ * exec'd.  If such modules are on either initrd or rootfs, they will be
+ * loaded before control is passed to userland.
+ */
+void __init load_default_modules(void)
+{
+	load_default_elevator_module();
+}
+
 static int run_init_process(const char *init_filename)
 {
 	argv_init[0] = init_filename;

@@ -898,4 +911,7 @@ static void __init kernel_init_freeable(void)
 	 * we're essentially up and running. Get rid of the
 	 * initmem segments and start the user-mode stuff..
 	 */
+
+	/* rootfs is available now, try loading default modules */
+	load_default_modules();
 }

1.8.1

Block layer allows selecting an elevator which is built as a module to be selected as system default via kernel param "elevator=". This is achieved by automatically invoking request_module() whenever a new block device is initialized and the elevator is not available.

This led to an interesting deadlock problem involving async and module init. Block device probing running off an async job invokes request_module(). While the module is being loaded, it performs async_synchronize_full() which ends up waiting for the async job which is already waiting for request_module() to finish, leading to deadlock.

Invoking request_module() from deep in block device init path is already nasty in itself. It seems best to avoid these situations from the beginning by moving on-demand module loading out of block init path.

The previous patch made sure that the default elevator module is loaded early during boot if available. This patch removes on-demand loading of the default elevator from elevator init path. As the module would have been loaded during boot, userland-visible behavior difference should be minimal.

For more details, please refer to the following thread.

http://thread.gmane.org/gmane.linux.kernel/1420814

---
 block/elevator.c |   19 ++++++++++++-------
 1 file changed, 12 insertions(+), 7 deletions(-)

@@ -100,14 +100,14 @@ static void elevator_put(struct elevator
 	module_put(e->elevator_owner);
 }
 
-static struct elevator_type *elevator_get(const char *name)
+static struct elevator_type *elevator_get(const char *name, bool request_module)
 {
 	struct elevator_type *e;
 
 	spin_lock(&elv_list_lock);
 
 	e = elevator_find(name);
-	if (!e) {
+	if (!e && request_module) {
 		spin_unlock(&elv_list_lock);
 		request_module("%s-iosched", name);
 		spin_lock(&elv_list_lock);

@@ -207,25 +207,30 @@ int elevator_init(struct request_queue *
 	q->boundary_rq = NULL;
 
 	if (name) {
-		e = elevator_get(name);
+		e = elevator_get(name, true);
 		if (!e)
 			return -EINVAL;
 	}
 
+	/*
+	 * Use the default elevator specified by config boot param or
+	 * config option.  Don't try to load modules as we could be running
+	 * off async and request_module() isn't allowed from async.
+	 */
 	if (!e && *chosen_elevator) {
-		e = elevator_get(chosen_elevator);
+		e = elevator_get(chosen_elevator, false);
 		if (!e)
 			printk(KERN_ERR "I/O scheduler %s not found\n",
 							chosen_elevator);
 	}
 
 	if (!e) {
-		e = elevator_get(CONFIG_DEFAULT_IOSCHED);
+		e = elevator_get(CONFIG_DEFAULT_IOSCHED, false);
 		if (!e) {
 			printk(KERN_ERR
 				"Default I/O scheduler not found. " \
 				"Using noop.\n");
-			e = elevator_get("noop");
+			e = elevator_get("noop", false);
 		}
 	}
 

@@ -967,7 +972,7 @@ int elevator_change(struct request_queue
 		return -ENXIO;
 
 	strlcpy(elevator_name, name, sizeof(elevator_name));
-	e = elevator_get(strstrip(elevator_name));
+	e = elevator_get(strstrip(elevator_name), true);
 	if (!e) {
 		printk(KERN_ERR "elevator: type %s not found\n", elevator_name);
 		return -EINVAL;

From: Tejun Heo <[email protected]>
Date: Tue, 22 Jan 2013 16:48:03 -0800

Block layer allows selecting an elevator which is built as a module to be selected as system default via kernel param "elevator=". This is achieved by automatically invoking request_module() whenever a new block device is initialized and the elevator is not available.

This led to an interesting deadlock problem involving async and module init. Block device probing running off an async job invokes request_module(). While the module is being loaded, it performs async_synchronize_full() which ends up waiting for the async job which is already waiting for request_module() to finish, leading to deadlock.

Invoking request_module() from deep in block device init path is already nasty in itself. It seems best to avoid these situations from the beginning by moving on-demand module loading out of block init path.

The previous patch made sure that the default elevator module is loaded early during boot if available. This patch removes on-demand loading of the default elevator from elevator init path. As the module would have been loaded during boot, userland-visible behavior difference should be minimal.

For more details, please refer to the following thread.

http://thread.gmane.org/gmane.linux.kernel/1420814

v2: The bool parameter was named @request_module which conflicted with
request_module(). This built okay w/ CONFIG_MODULES because request_module() was defined as a macro. W/o CONFIG_MODULES, it causes build breakage. Rename the parameter to @try_loading. Reported by Fengguang.

---
Minor revision to fix build breakage on !CONFIG_MODULES reported by Fengguang. The patch has been queued to wq/for-3.9-async-deadlock-fixes.

Thanks.

 block/elevator.c | 19 ++++++++++++-------
 1 file changed, 12 insertions(+), 7 deletions(-)

index c2d61d5..603b2c1 100644
@@ -100,14 +100,14 @@ static void elevator_put(struct elevator_type *e)
 	module_put(e->elevator_owner);
 }
 
-static struct elevator_type *elevator_get(const char *name)
+static struct elevator_type *elevator_get(const char *name, bool try_loading)
 {
 	struct elevator_type *e;
 
 	spin_lock(&elv_list_lock);
 
 	e = elevator_find(name);
-	if (!e) {
+	if (!e && try_loading) {
 		spin_unlock(&elv_list_lock);
 		request_module("%s-iosched", name);
 		spin_lock(&elv_list_lock);

@@ -207,25 +207,30 @@ int elevator_init(struct request_queue *q, char *name)
 	q->boundary_rq = NULL;
 
 	if (name) {
-		e = elevator_get(name);
+		e = elevator_get(name, true);
 		if (!e)
 			return -EINVAL;
 	}
 
+	/*
+	 * Use the default elevator specified by config boot param or
+	 * config option.  Don't try to load modules as we could be running
+	 * off async and request_module() isn't allowed from async.
+	 */
 	if (!e && *chosen_elevator) {
-		e = elevator_get(chosen_elevator);
+		e = elevator_get(chosen_elevator, false);
 		if (!e)
 			printk(KERN_ERR "I/O scheduler %s not found\n",
 							chosen_elevator);
 	}
 
 	if (!e) {
-		e = elevator_get(CONFIG_DEFAULT_IOSCHED);
+		e = elevator_get(CONFIG_DEFAULT_IOSCHED, false);
 		if (!e) {
 			printk(KERN_ERR
 				"Default I/O scheduler not found. " \
 				"Using noop.\n");
-			e = elevator_get("noop");
+			e = elevator_get("noop", false);
 		}
 	}
 

@@ -967,7 +972,7 @@ int elevator_change(struct request_queue *q, const char *name)
 		return -ENXIO;
 
 	strlcpy(elevator_name, name, sizeof(elevator_name));
-	e = elevator_get(strstrip(elevator_name));
+	e = elevator_get(strstrip(elevator_name), true);
 	if (!e) {
 		printk(KERN_ERR "elevator: type %s not found\n", elevator_name);
 		return -EINVAL;

1.8.1

Looks it does fix the deadlock problem on my Pandaboard, also the scsi disk device node(/dev/sdX) comes just after loading module of 'sd_mod'.

Thanks,
--
Ming Lei

I confirm it fixes the original problem.

[   27.594951] hub 1-1:1.0: state 7 ports 6 chg 0000 evt 0004
[   27.595245] hub 1-1:1.0: port 2, status 0101, change 0001, 12 Mb/s
[   27.698995] hub 1-1:1.0: debounce: port 2: total 100ms stable 100ms
status 0x101
[   27.709977] hub 1-1:1.0: port 2 not reset yet, waiting 10ms
[   27.771888] usb 1-1.2: new high-speed USB device number 3 using ehci-pci
[   27.782871] hub 1-1:1.0: port 2 not reset yet, waiting 10ms
[   27.857503] usb 1-1.2: default language 0x0409
[   27.858248] usb 1-1.2: udev 3, busnum 1, minor = 2
[   27.858258] usb 1-1.2: New USB device found, idVendor=0781, idProduct=5408
[   27.858263] usb 1-1.2: New USB device strings: Mfr=1, Product=2,
SerialNumber=3
[   27.858267] usb 1-1.2: Product: U3 Titanium
[   27.858271] usb 1-1.2: Manufacturer: SanDisk Corporation
[   27.858275] usb 1-1.2: SerialNumber: 0000187A3A60F1E9
[   27.858800] usb 1-1.2: usb_probe_device
[   27.858815] usb 1-1.2: configuration #1 chosen from 1 choice
[   27.858940] usb 1-1.2: adding 1-1.2:1.0 (config #1, interface 0)
[   27.859246] usb-storage 1-1.2:1.0: usb_probe_interface
[   27.859258] usb-storage 1-1.2:1.0: usb_probe_interface - got id
[   27.859516] scsi6 : usb-storage 1-1.2:1.0
[   28.865771] io scheduler deadline registered (default)
[   28.866705] scsi 6:0:0:0: Direct-Access     SanDisk  U3 Titanium
  2.18 PQ: 0 ANSI: 2
[   28.869483] sd 6:0:0:0: Attached scsi generic sg1 type 0
[   28.869700] sd 6:0:0:0: [sdb] 4013713 512-byte logical blocks:
(2.05 GB/1.91 GiB)
[   28.870197] sd 6:0:0:0: [sdb] Write Protect is off
[   28.870204] sd 6:0:0:0: [sdb] Mode Sense: 03 00 00 00
[   28.870692] sd 6:0:0:0: [sdb] No Caching mode page present
[   28.870697] sd 6:0:0:0: [sdb] Assuming drive cache: write through
[   28.873565] sd 6:0:0:0: [sdb] No Caching mode page present
[   28.873575] sd 6:0:0:0: [sdb] Assuming drive cache: write through
[   28.883895]  sdb: sdb1
[   28.887775] sd 6:0:0:0: [sdb] No Caching mode page present
[   28.887783] sd 6:0:0:0: [sdb] Assuming drive cache: write through
[   28.887789] sd 6:0:0:0: [sdb] Attached SCSI removable disk

The filesystem can be mounted and files can be read.

Hi,

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?

Thanks,
Jonathan

[1] Screenshot: http://bugs.debian.org/cgi-bin/bugreport.cgi?msg=5;filename=bad_3.10.3-1.jpg;att=1;bug=719464
Screenshot in recovery mode: http://bugs.debian.org/cgi-bin/bugreport.cgi?msg=5;filename=bad_3.10.3-1_recovery.jpg;att=2;bug=719464
[2] http://bugs.debian.org/719464

[    0.000000] Initializing cgroup subsys cpuset
[    0.000000] Initializing cgroup subsys cpu
[    0.000000] Initializing cgroup subsys cpuacct
[    0.000000] Linux version 3.11.0-rc4+ (jrn@elie) (gcc version 4.7.3 (Debian 4.7.3-6) ) #2 SMP Sun Aug 11 23:20:20 PDT 2013
[    0.000000] Command line: BOOT_IMAGE=/vmlinuz-3.11.0-rc4+ root=/dev/mapper/data-root ro quiet
[    0.000000] e820: BIOS-provided physical RAM map:
[    0.000000] BIOS-e820: [mem 0x0000000000000000-0x000000000009fbff] usable
[    0.000000] BIOS-e820: [mem 0x000000000009fc00-0x000000000009ffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000000e0000-0x00000000000fffff] reserved
[    0.000000] BIOS-e820: [mem 0x0000000000100000-0x000000006e545fff] usable
[    0.000000] BIOS-e820: [mem 0x000000006e546000-0x000000006e745fff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x000000006e746000-0x000000006fd3efff] usable
[    0.000000] BIOS-e820: [mem 0x000000006fd3f000-0x000000006fdbefff] reserved
[    0.000000] BIOS-e820: [mem 0x000000006fdbf000-0x000000006febefff] ACPI NVS
[    0.000000] BIOS-e820: [mem 0x000000006febf000-0x000000006fef6fff] ACPI data
[    0.000000] BIOS-e820: [mem 0x000000006fef7000-0x000000006fefffff] usable
[    0.000000] BIOS-e820: [mem 0x00000000f8000000-0x00000000f8ffffff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fec00000-0x00000000fec00fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fec10000-0x00000000fec10fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000fee00000-0x00000000fee00fff] reserved
[    0.000000] BIOS-e820: [mem 0x00000000ffe00000-0x00000000ffffffff] reserved
[    0.000000] NX (Execute Disable) protection: active
[    0.000000] SMBIOS 2.6 present.
[    0.000000] DMI: TOSHIBA Satellite C650D/Portable PC, BIOS 1.60 09/02/2010
[    0.000000] e820: update [mem 0x00000000-0x00000fff] usable ==> reserved
[    0.000000] e820: remove [mem 0x000a0000-0x000fffff] usable
[    0.000000] No AGP bridge found
[    0.000000] e820: last_pfn = 0x6ff00 max_arch_pfn = 0x400000000
[    0.000000] MTRR default type: uncachable
[    0.000000] MTRR fixed ranges enabled:
[    0.000000]   00000-9FFFF write-back
[    0.000000]   A0000-BFFFF uncachable
[    0.000000]   C0000-FFFFF write-through
[    0.000000] MTRR variable ranges enabled:
[    0.000000]   0 base 000000000000 mask FFFFC0000000 write-back
[    0.000000]   1 base 000040000000 mask FFFFE0000000 write-back
[    0.000000]   2 base 000060000000 mask FFFFF0000000 write-back
[    0.000000]   3 base 00006FEBE000 mask FFFFFFFFF000 uncachable
[    0.000000]   4 base 0000FFE00000 mask FFFFFFE00000 write-protect
[    0.000000]   5 disabled
[    0.000000]   6 disabled
[    0.000000]   7 disabled
[    0.000000] x86 PAT enabled: cpu 0, old 0x7040600070406, new 0x7010600070106
[    0.000000] Base memory trampoline at [ffff880000099000] 99000 size 24576
[    0.000000] Using GB pages for direct mapping
[    0.000000] init_memory_mapping: [mem 0x00000000-0x000fffff]
[    0.000000]  [mem 0x00000000-0x000fffff] page 4k
[    0.000000] BRK [0x0184c000, 0x0184cfff] PGTABLE
[    0.000000] BRK [0x0184d000, 0x0184dfff] PGTABLE
[    0.000000] BRK [0x0184e000, 0x0184efff] PGTABLE
[    0.000000] init_memory_mapping: [mem 0x6fa00000-0x6fbfffff]
[    0.000000]  [mem 0x6fa00000-0x6fbfffff] page 2M
[    0.000000] BRK [0x0184f000, 0x0184ffff] PGTABLE
[    0.000000] init_memory_mapping: [mem 0x6c000000-0x6e545fff]
[    0.000000]  [mem 0x6c000000-0x6e3fffff] page 2M
[    0.000000]  [mem 0x6e400000-0x6e545fff] page 4k
[    0.000000] BRK [0x01850000, 0x01850fff] PGTABLE
[    0.000000] init_memory_mapping: [mem 0x6e746000-0x6f9fffff]
[    0.000000]  [mem 0x6e746000-0x6e7fffff] page 4k
[    0.000000]  [mem 0x6e800000-0x6f9fffff] page 2M
[    0.000000] init_memory_mapping: [mem 0x00100000-0x6bffffff]
[    0.000000]  [mem 0x00100000-0x001fffff] page 4k
[    0.000000]  [mem 0x00200000-0x6bffffff] page 2M
[    0.000000] init_memory_mapping: [mem 0x6fc00000-0x6fd3efff]
[    0.000000]  [mem 0x6fc00000-0x6fd3efff] page 4k
[    0.000000] init_memory_mapping: [mem 0x6fef7000-0x6fefffff]
[    0.000000]  [mem 0x6fef7000-0x6fefffff] page 4k
[    0.000000] RAMDISK: [mem 0x37ab2000-0x37d50fff]
[    0.000000] ACPI: RSDP 00000000000fe020 00024 (v02 TOSINV)
[    0.000000] ACPI: XSDT 000000006fef6120 0005C (v01 TOSINV TOSINV00 00000003      01000013)
[    0.000000] ACPI: FACP 000000006fef5000 000F4 (v04 TOSINV TOSINV00 00000003 MSFT 01000013)
[    0.000000] ACPI: DSDT 000000006fee6000 0BAD7 (v01 TOSINV TOSINV00 F0000000 MSFT 01000013)
[    0.000000] ACPI: FACS 000000006fe9c000 00040
[    0.000000] ACPI: HPET 000000006fef4000 00038 (v01 TOSINV TOSINV00 00000001 MSFT 01000013)
[    0.000000] ACPI: APIC 000000006fef3000 00084 (v02 TOSINV TOSINV00 00000001 MSFT 01000013)
[    0.000000] ACPI: MCFG 000000006fef2000 0003C (v01 TOSINV TOSINV00 00000001 MSFT 01000013)
[    0.000000] ACPI: BOOT 000000006fee5000 00028 (v01 TOSINV TOSINV00 00000001 MSFT 01000013)
[    0.000000] ACPI: SLIC 000000006fee4000 00176 (v01 TOSINV TOSINV00 00000001 MSFT 01000013)
[    0.000000] ACPI: SSDT 000000006fee3000 00392 (v01 AMD    POWERNOW 00000001 AMD  00000001)
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] Scanning NUMA topology in Northbridge 24
[    0.000000] No NUMA configuration found
[    0.000000] Faking a node at [mem 0x0000000000000000-0x000000006fefffff]
[    0.000000] Initmem setup node 0 [mem 0x00000000-0x6fefffff]
[    0.000000]   NODE_DATA [mem 0x6fefc000-0x6fefffff]
[    0.000000]  [ffffea0000000000-ffffea00019fffff] PMD -> [ffff88006c800000-ffff88006e1fffff] on node 0
[    0.000000] Zone ranges:
[    0.000000]   DMA      [mem 0x00001000-0x00ffffff]
[    0.000000]   DMA32    [mem 0x01000000-0xffffffff]
[    0.000000]   Normal   empty
[    0.000000] Movable zone start for each node
[    0.000000] Early memory node ranges
[    0.000000]   node   0: [mem 0x00001000-0x0009efff]
[    0.000000]   node   0: [mem 0x00100000-0x6e545fff]
[    0.000000]   node   0: [mem 0x6e746000-0x6fd3efff]
[    0.000000]   node   0: [mem 0x6fef7000-0x6fefffff]
[    0.000000] On node 0 totalpages: 457446
[    0.000000]   DMA zone: 56 pages used for memmap
[    0.000000]   DMA zone: 21 pages reserved
[    0.000000]   DMA zone: 3998 pages, LIFO batch:0
[    0.000000]   DMA32 zone: 6213 pages used for memmap
[    0.000000]   DMA32 zone: 453448 pages, LIFO batch:31
[    0.000000] ACPI: PM-Timer IO Port: 0x408
[    0.000000] ACPI: Local APIC address 0xfee00000
[    0.000000] ACPI: LAPIC (acpi_id[0x00] lapic_id[0x00] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x01] lapic_id[0x01] enabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x02] lapic_id[0x00] disabled)
[    0.000000] ACPI: LAPIC (acpi_id[0x03] lapic_id[0x00] disabled)
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x00] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x01] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x02] high edge lint[0x1])
[    0.000000] ACPI: LAPIC_NMI (acpi_id[0x03] high edge lint[0x1])
[    0.000000] ACPI: IOAPIC (id[0x04] address[0xfec00000] gsi_base[0])
[    0.000000] IOAPIC[0]: apic_id 4, version 33, address 0xfec00000, GSI 0-23
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 0 global_irq 2 dfl dfl)
[    0.000000] ACPI: INT_SRC_OVR (bus 0 bus_irq 9 global_irq 9 low level)
[    0.000000] ACPI: IRQ0 used by override.
[    0.000000] ACPI: IRQ2 used by override.
[    0.000000] ACPI: IRQ9 used by override.
[    0.000000] Using ACPI (MADT) for SMP configuration information
[    0.000000] ACPI: HPET id: 0x1002a201 base: 0xfed00000
[    0.000000] smpboot: Allowing 4 CPUs, 2 hotplug CPUs
[    0.000000] nr_irqs_gsi: 40
[    0.000000] PM: Registered nosave memory: [mem 0x0009f000-0x0009ffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000a0000-0x000dffff]
[    0.000000] PM: Registered nosave memory: [mem 0x000e0000-0x000fffff]
[    0.000000] PM: Registered nosave memory: [mem 0x6e546000-0x6e745fff]
[    0.000000] PM: Registered nosave memory: [mem 0x6fd3f000-0x6fdbefff]
[    0.000000] PM: Registered nosave memory: [mem 0x6fdbf000-0x6febefff]
[    0.000000] PM: Registered nosave memory: [mem 0x6febf000-0x6fef6fff]
[    0.000000] e820: [mem 0x6ff00000-0xf7ffffff] available for PCI devices
[    0.000000] setup_percpu: NR_CPUS:512 nr_cpumask_bits:512 nr_cpu_ids:4 nr_node_ids:1
[    0.000000] PERCPU: Embedded 27 pages/cpu @ffff88006f800000 s80512 r8192 d21888 u524288
[    0.000000] pcpu-alloc: s80512 r8192 d21888 u524288 alloc=1*2097152
[    0.000000] pcpu-alloc: [0] 0 1 2 3 
[    0.000000] Built 1 zonelists in Node order, mobility grouping on.  Total pages: 451156
[    0.000000] Policy zone: DMA32
[    0.000000] Kernel command line: BOOT_IMAGE=/vmlinuz-3.11.0-rc4+ root=/dev/mapper/data-root ro quiet
[    0.000000] PID hash table entries: 4096 (order: 3, 32768 bytes)
[    0.000000] Checking aperture...
[    0.000000] No AGP bridge found
[    0.000000] Node 0: aperture @ d912000000 size 32 MB
[    0.000000] Aperture beyond 4GB. Ignoring.
[    0.000000] Memory: 1791168K/1829784K available (3365K kernel code, 591K rwdata, 1444K rodata, 856K init, 884K bss, 38616K reserved)
[    0.000000] Hierarchical RCU implementation.
[    0.000000] 	RCU dyntick-idle grace-period acceleration is enabled.
[    0.000000] 	RCU restricting CPUs from NR_CPUS=512 to nr_cpu_ids=4.
[    0.000000] NR_IRQS:33024 nr_irqs:712 16
[    0.000000] spurious 8259A interrupt: IRQ7.
[    0.000000] Console: colour VGA+ 80x25
[    0.000000] console [tty0] enabled
[    0.000000] allocated 7340032 bytes of page_cgroup
[    0.000000] please try 'cgroup_disable=memory' option if you don't want memory cgroups
[    0.000000] hpet clockevent registered
[    0.000000] tsc: Fast TSC calibration using PIT
[    0.004000] tsc: Detected 2294.162 MHz processor
[    0.000003] Calibrating delay loop (skipped), value calculated using timer frequency.. 4588.32 BogoMIPS (lpj=9176648)
[    0.000007] pid_max: default: 32768 minimum: 301
[    0.000049] Security Framework initialized
[    0.000055] AppArmor: AppArmor disabled by boot time parameter
[    0.000208] Dentry cache hash table entries: 262144 (order: 9, 2097152 bytes)
[    0.001142] Inode-cache hash table entries: 131072 (order: 8, 1048576 bytes)
[    0.001587] Mount-cache hash table entries: 256
[    0.001813] Initializing cgroup subsys memory
[    0.001835] Initializing cgroup subsys devices
[    0.001837] Initializing cgroup subsys freezer
[    0.001840] Initializing cgroup subsys net_cls
[    0.001842] Initializing cgroup subsys blkio
[    0.001844] Initializing cgroup subsys perf_event
[    0.001867] tseg: 006ff00000
[    0.001870] CPU: Physical Processor ID: 0
[    0.001871] CPU: Processor Core ID: 0
[    0.001873] mce: CPU supports 6 MCE banks
[    0.001880] LVT offset 0 assigned for vector 0xf9
[    0.001885] process: using AMD E400 aware idle routine
[    0.001888] Last level iTLB entries: 4KB 512, 2MB 16, 4MB 8
[    0.001888] Last level dTLB entries: 4KB 512, 2MB 128, 4MB 64
[    0.001888] tlb_flushall_shift: 4
[    0.001960] Freeing SMP alternatives memory: 8K (ffffffff8176b000 - ffffffff8176d000)
[    0.001962] ACPI: Core revision 20130517
[    0.001964] TOSHIBA Satellite detected - force copy of DSDT to local memory
[    0.002085] ACPI: Forced DSDT copy: length 0x0BAD7 copied locally, original unmapped
[    0.006991] ACPI: All ACPI Tables successfully acquired
[    0.011022] ..TIMER: vector=0x30 apic1=0 pin1=2 apic2=-1 pin2=-1
[    0.050677] smpboot: CPU0: AMD Athlon(tm) II P360 Dual-Core Processor (fam: 10, model: 06, stepping: 03)
[    0.155726] Performance Events: AMD PMU driver.
[    0.155731] ... version:                0
[    0.155733] ... bit width:              48
[    0.155734] ... generic registers:      4
[    0.155735] ... value mask:             0000ffffffffffff
[    0.155737] ... max period:             00007fffffffffff
[    0.155738] ... fixed-purpose events:   0
[    0.155739] ... event mask:             000000000000000f
[    0.156004] NMI watchdog: enabled on all CPUs, permanently consumes one hw-PMU counter.
[    0.156121] smpboot: Booting Node   0, Processors  #1
[    0.169239] Brought up 2 CPUs
[    0.169242] smpboot: Total of 2 processors activated (9176.64 BogoMIPS)
[    0.169589] process: System has AMD C1E enabled
[    0.169607] process: Switch to broadcast mode on CPU1
[    0.169729] process: Switch to broadcast mode on CPU0
[    0.173823] devtmpfs: initialized
[    0.176836] PM: Registering ACPI NVS region [mem 0x6e546000-0x6e745fff] (2097152 bytes)
[    0.176908] PM: Registering ACPI NVS region [mem 0x6fdbf000-0x6febefff] (1048576 bytes)
[    0.177161] regulator-dummy: no parameters
[    0.177238] NET: Registered protocol family 16
[    0.177339] node 0 link 0: io port [0, ffffff]
[    0.177342] TOM: 0000000080000000 aka 2048M
[    0.177345] Fam 10h mmconf [mem 0xf8000000-0xfbffffff]
[    0.177348] node 0 link 0: mmio [80000000, 8fffffff]
[    0.177350] node 0 link 0: mmio [90000000, 920fffff]
[    0.177352] node 0 link 0: mmio [92100000, 922fffff]
[    0.177354] node 0 link 0: mmio [92300000, f7ffffff]
[    0.177356] node 0 link 0: mmio [f8000000, fbffffff] ==> none
[    0.177358] node 0 link 0: mmio [fc000000, febfffff]
[    0.177360] node 0 link 0: mmio [fec00000, fffeffff]
[    0.177362] node 0 link 0: mmio [ffff0000, ffffffff]
[    0.177364] bus: [bus 00-1f] on node 0 link 0
[    0.177366] bus: 00 [io  0x0000-0xffff]
[    0.177368] bus: 00 [mem 0x80000000-0xf7ffffff]
[    0.177370] bus: 00 [mem 0xfc000000-0xfcffffffff]
[    0.177400] ACPI: bus type PCI registered
[    0.177402] acpiphp: ACPI Hot Plug PCI Controller Driver version: 0.5
[    0.177460] PCI: MMCONFIG for domain 0000 [bus 00-3f] at [mem 0xf8000000-0xfbffffff] (base 0xf8000000)
[    0.177463] PCI: MMCONFIG at [mem 0xf8000000-0xfbffffff] reserved in E820
[    0.177466] PCI: MMCONFIG for 0000 [bus00-0f] at [mem 0xf8000000-0xf8ffffff] (base 0xf8000000) (size reduced!)
[    0.178326] PCI: Using configuration type 1 for base access
[    0.178455] mtrr: your CPUs had inconsistent fixed MTRR settings
[    0.178456] mtrr: your CPUs had inconsistent variable MTRR settings
[    0.178458] mtrr: probably your BIOS does not setup all CPUs.
[    0.178459] mtrr: corrected configuration.
[    0.179115] bio: create slab <bio-0> at 0
[    0.179249] ACPI: Added _OSI(Module Device)
[    0.179252] ACPI: Added _OSI(Processor Device)
[    0.179253] ACPI: Added _OSI(3.0 _SCP Extensions)
[    0.179255] ACPI: Added _OSI(Processor Aggregator Device)
[    0.180366] ACPI: EC: Look up EC in DSDT
[    0.181561] ACPI: Executed 1 blocks of module-level executable AML code
[    0.185333] [Firmware Bug]: ACPI: BIOS _OSI(Linux) query ignored
[    0.611520] ACPI: Interpreter enabled
[    0.611531] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S1_] (20130517/hwxface-571)
[    0.611536] ACPI Exception: AE_NOT_FOUND, While evaluating Sleep State [\_S2_] (20130517/hwxface-571)
[    0.611552] ACPI: (supports S0 S3 S4 S5)
[    0.611555] ACPI: Using IOAPIC for interrupt routing
[    0.611763] PCI: Using host bridge windows from ACPI; if necessary, use "pci=nocrs" and report a bug
[    0.639420] ACPI: Power Resource [PFA1] (off)
[    0.640221] ACPI: PCI Root Bridge [PCI0] (domain 0000 [bus 00-ff])
[    0.641101] acpi PNP0A08:00: ignoring host bridge window [mem 0x000cc000-0x000cffff] (conflicts with Video ROM [mem 0x000c0000-0x000cefff])
[    0.641108] acpi PNP0A08:00: [Firmware Info]: MMCONFIG for domain 0000 [bus 00-0f] only partially covers this bridge
[    0.641193] PCI host bridge to bus 0000:00
[    0.641196] pci_bus 0000:00: root bus resource [bus 00-ff]
[    0.641199] pci_bus 0000:00: root bus resource [io  0x0000-0x0cf7]
[    0.641202] pci_bus 0000:00: root bus resource [io  0x0d00-0xffff]
[    0.641204] pci_bus 0000:00: root bus resource [mem 0x000a0000-0x000bffff]
[    0.641207] pci_bus 0000:00: root bus resource [mem 0x000c0000-0x000c3fff]
[    0.641209] pci_bus 0000:00: root bus resource [mem 0x000c4000-0x000c7fff]
[    0.641211] pci_bus 0000:00: root bus resource [mem 0x000c8000-0x000cbfff]
[    0.641214] pci_bus 0000:00: root bus resource [mem 0x000d0000-0x000d3fff]
[    0.641216] pci_bus 0000:00: root bus resource [mem 0x000d4000-0x000d7fff]
[    0.641218] pci_bus 0000:00: root bus resource [mem 0x000d8000-0x000dbfff]
[    0.641221] pci_bus 0000:00: root bus resource [mem 0x000dc000-0x000dffff]
[    0.641223] pci_bus 0000:00: root bus resource [mem 0x000e0000-0x000e3fff]
[    0.641225] pci_bus 0000:00: root bus resource [mem 0x000e4000-0x000e7fff]
[    0.641228] pci_bus 0000:00: root bus resource [mem 0x000e8000-0x000ebfff]
[    0.641230] pci_bus 0000:00: root bus resource [mem 0x000ec000-0x000effff]
[    0.641232] pci_bus 0000:00: root bus resource [mem 0x80000000-0xf7ffffff]
[    0.641235] pci_bus 0000:00: root bus resource [mem 0xfc000000-0xfed3ffff]
[    0.641237] pci_bus 0000:00: root bus resource [mem 0xfed45000-0xffffffff]
[    0.641251] pci 0000:00:00.0: [1022:9601] type 00 class 0x060000
[    0.641384] pci 0000:00:01.0: [1022:9602] type 01 class 0x060400
[    0.641493] pci 0000:00:04.0: [1022:9604] type 01 class 0x060400
[    0.641529] pci 0000:00:04.0: PME# supported from D0 D3hot D3cold
[    0.641615] pci 0000:00:05.0: [1022:9605] type 01 class 0x060400
[    0.641650] pci 0000:00:05.0: PME# supported from D0 D3hot D3cold
[    0.641701] pci 0000:00:05.0: System wakeup disabled by ACPI
[    0.641796] pci 0000:00:11.0: [1002:4391] type 00 class 0x010601
[    0.641818] pci 0000:00:11.0: reg 0x10: [io  0x8038-0x803f]
[    0.641828] pci 0000:00:11.0: reg 0x14: [io  0x804c-0x804f]
[    0.641837] pci 0000:00:11.0: reg 0x18: [io  0x8030-0x8037]
[    0.641847] pci 0000:00:11.0: reg 0x1c: [io  0x8048-0x804b]
[    0.641856] pci 0000:00:11.0: reg 0x20: [io  0x8010-0x801f]
[    0.641866] pci 0000:00:11.0: reg 0x24: [mem 0x92307000-0x923073ff]
[    0.642000] pci 0000:00:12.0: [1002:4397] type 00 class 0x0c0310
[    0.642013] pci 0000:00:12.0: reg 0x10: [mem 0x92306000-0x92306fff]
[    0.649649] pci 0000:00:12.0: System wakeup disabled by ACPI
[    0.649700] pci 0000:00:12.2: [1002:4396] type 00 class 0x0c0320
[    0.649718] pci 0000:00:12.2: reg 0x10: [mem 0x92307600-0x923076ff]
[    0.649796] pci 0000:00:12.2: supports D1 D2
[    0.649798] pci 0000:00:12.2: PME# supported from D0 D1 D2 D3hot
[    0.658318] pci 0000:00:12.2: System wakeup disabled by ACPI
[    0.658368] pci 0000:00:13.0: [1002:4397] type 00 class 0x0c0310
[    0.658381] pci 0000:00:13.0: reg 0x10: [mem 0x92305000-0x92305fff]
[    0.658521] pci 0000:00:13.2: [1002:4396] type 00 class 0x0c0320
[    0.658539] pci 0000:00:13.2: reg 0x10: [mem 0x92307500-0x923075ff]
[    0.658617] pci 0000:00:13.2: supports D1 D2
[    0.658619] pci 0000:00:13.2: PME# supported from D0 D1 D2 D3hot
[    0.658715] pci 0000:00:14.0: [1002:4385] type 00 class 0x0c0500
[    0.658859] pci 0000:00:14.2: [1002:4383] type 00 class 0x040300
[    0.658880] pci 0000:00:14.2: reg 0x10: [mem 0x92300000-0x92303fff 64bit]
[    0.658942] pci 0000:00:14.2: PME# supported from D0 D3hot D3cold
[    0.658994] pci 0000:00:14.2: System wakeup disabled by ACPI
[    0.659038] pci 0000:00:14.3: [1002:439d] type 00 class 0x060100
[    0.659178] pci 0000:00:14.4: [1002:4384] type 01 class 0x060400
[    0.659253] pci 0000:00:14.4: System wakeup disabled by ACPI
[    0.659302] pci 0000:00:16.0: [1002:4397] type 00 class 0x0c0310
[    0.659316] pci 0000:00:16.0: reg 0x10: [mem 0x92304000-0x92304fff]
[    0.659451] pci 0000:00:16.2: [1002:4396] type 00 class 0x0c0320
[    0.659470] pci 0000:00:16.2: reg 0x10: [mem 0x92307400-0x923074ff]
[    0.659547] pci 0000:00:16.2: supports D1 D2
[    0.659549] pci 0000:00:16.2: PME# supported from D0 D1 D2 D3hot
[    0.659645] pci 0000:00:18.0: [1022:1200] type 00 class 0x060000
[    0.659724] pci 0000:00:18.1: [1022:1201] type 00 class 0x060000
[    0.659801] pci 0000:00:18.2: [1022:1202] type 00 class 0x060000
[    0.659876] pci 0000:00:18.3: [1022:1203] type 00 class 0x060000
[    0.659955] pci 0000:00:18.4: [1022:1204] type 00 class 0x060000
[    0.660123] pci 0000:01:05.0: [1002:9712] type 00 class 0x030000
[    0.660132] pci 0000:01:05.0: reg 0x10: [mem 0x80000000-0x8fffffff pref]
[    0.660137] pci 0000:01:05.0: reg 0x14: [io  0x7000-0x70ff]
[    0.660143] pci 0000:01:05.0: reg 0x18: [mem 0x92200000-0x9220ffff]
[    0.660153] pci 0000:01:05.0: reg 0x24: [mem 0x92100000-0x921fffff]
[    0.660171] pci 0000:01:05.0: supports D1 D2
[    0.660239] pci 0000:00:01.0: PCI bridge to [bus 01]
[    0.660243] pci 0000:00:01.0:   bridge window [io  0x7000-0x7fff]
[    0.660246] pci 0000:00:01.0:   bridge window [mem 0x92100000-0x922fffff]
[    0.660251] pci 0000:00:01.0:   bridge window [mem 0x80000000-0x8fffffff 64bit pref]
[    0.660307] pci 0000:02:00.0: [168c:002b] type 00 class 0x028000
[    0.660325] pci 0000:02:00.0: reg 0x10: [mem 0x91100000-0x9110ffff 64bit]
[    0.660401] pci 0000:02:00.0: supports D1
[    0.660404] pci 0000:02:00.0: PME# supported from D0 D1 D3hot
[    0.665344] pci 0000:00:04.0: PCI bridge to [bus 02-07]
[    0.665352] pci 0000:00:04.0:   bridge window [io  0x3000-0x6fff]
[    0.665356] pci 0000:00:04.0:   bridge window [mem 0x91100000-0x920fffff]
[    0.665361] pci 0000:00:04.0:   bridge window [mem 0x90000000-0x90ffffff 64bit pref]
[    0.665455] pci 0000:08:00.0: [1969:2060] type 00 class 0x020000
[    0.665478] pci 0000:08:00.0: reg 0x10: [mem 0x91000000-0x9103ffff 64bit]
[    0.665489] pci 0000:08:00.0: reg 0x18: [io  0x2000-0x207f]
[    0.665584] pci 0000:08:00.0: PME# supported from D0 D1 D2 D3hot D3cold
[    0.673339] pci 0000:00:05.0: PCI bridge to [bus 08]
[    0.673348] pci 0000:00:05.0:   bridge window [io  0x2000-0x2fff]
[    0.673352] pci 0000:00:05.0:   bridge window [mem 0x91000000-0x910fffff]
[    0.673462] pci 0000:00:14.4: PCI bridge to [bus 09]
[    0.673488] acpi PNP0A08:00: ACPI _OSC support notification failed, disabling PCIe ASPM
[    0.673491] acpi PNP0A08:00: Unable to request _OSC control (_OSC support mask: 0x08)
[    0.674186] ACPI: PCI Interrupt Link [LNKA] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674263] ACPI: PCI Interrupt Link [LNKB] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674339] ACPI: PCI Interrupt Link [LNKC] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674413] ACPI: PCI Interrupt Link [LNKD] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674473] ACPI: PCI Interrupt Link [LNKE] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674522] ACPI: PCI Interrupt Link [LNKF] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674571] ACPI: PCI Interrupt Link [LNKG] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674619] ACPI: PCI Interrupt Link [LNKH] (IRQs 3 4 5 7 10 11 12 14 15) *0
[    0.674825] ACPI: Enabled 1 GPEs in block 00 to 1F
[    0.674835] ACPI: \_SB_.PCI0: notify handler is installed
[    0.674886] Found 1 acpi root devices
[    0.675035] vgaarb: device added: PCI:0000:01:05.0,decodes=io+mem,owns=io+mem,locks=none
[    0.675037] vgaarb: loaded
[    0.675039] vgaarb: bridge control possible 0000:01:05.0
[    0.675089] PCI: Using ACPI for IRQ routing
[    0.675440] PCI: pci_cache_line_size set to 64 bytes
[    0.675497] e820: reserve RAM buffer [mem 0x0009fc00-0x0009ffff]
[    0.675499] e820: reserve RAM buffer [mem 0x6e546000-0x6fffffff]
[    0.675502] e820: reserve RAM buffer [mem 0x6fd3f000-0x6fffffff]
[    0.675504] e820: reserve RAM buffer [mem 0x6ff00000-0x6fffffff]
[    0.675640] hpet0: at MMIO 0xfed00000, IRQs 2, 8, 0
[    0.675644] hpet0: 3 comparators, 32-bit 14.318180 MHz counter
[    0.677707] Switched to clocksource hpet
[    0.679522] pnp: PnP ACPI init
[    0.679544] ACPI: bus type PNP registered
[    0.679971] system 00:00: [mem 0xfec00000-0xfec00fff] could not be reserved
[    0.679974] system 00:00: [mem 0xfee00000-0xfee00fff] has been reserved
[    0.679978] system 00:00: [mem 0xf8000000-0xfbffffff] could not be reserved
[    0.679983] system 00:00: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.680164] pnp 00:01: [dma 4]
[    0.680204] pnp 00:01: Plug and Play ACPI device, IDs PNP0200 (active)
[    0.680254] pnp 00:02: Plug and Play ACPI device, IDs PNP0c04 (active)
[    0.680316] pnp 00:03: Plug and Play ACPI device, IDs PNP0b00 (active)
[    0.680351] pnp 00:04: Plug and Play ACPI device, IDs PNP0800 (active)
[    0.680396] pnp 00:05: Plug and Play ACPI device, IDs PNP0303 (active)
[    0.680452] pnp 00:06: Plug and Play ACPI device, IDs TOS0100 SYN1900 SYN0002 PNP0f13 (active)
[    0.680519] system 00:07: [io  0x0400-0x04cf] could not be reserved
[    0.680522] system 00:07: [io  0x04d0-0x04d1] has been reserved
[    0.680525] system 00:07: [io  0x04d6] has been reserved
[    0.680528] system 00:07: [io  0x0680-0x06ff] has been reserved
[    0.680531] system 00:07: [io  0x077a] has been reserved
[    0.680533] system 00:07: [io  0x0c00-0x0c01] has been reserved
[    0.680536] system 00:07: [io  0x0c14] has been reserved
[    0.680539] system 00:07: [io  0x0c50-0x0c52] has been reserved
[    0.680542] system 00:07: [io  0x0c6c] has been reserved
[    0.680544] system 00:07: [io  0x0c6f] has been reserved
[    0.680547] system 00:07: [io  0x0cd0-0x0cdb] has been reserved
[    0.680550] system 00:07: Plug and Play ACPI device, IDs PNP0c02 (active)
[    0.680633] system 00:08: [mem 0x000e0000-0x000fffff] could not be reserved
[    0.680636] system 00:08: [mem 0xffe00000-0xffffffff] has been reserved
[    0.680639] system 00:08: [mem 0xfed80000-0xfed80fff] has been reserved
[    0.680643] system 00:08: Plug and Play ACPI device, IDs PNP0c01 (active)
[    0.681021] pnp: PnP ACPI: found 9 devices
[    0.681023] ACPI: bus type PNP unregistered
[    0.688732] pci 0000:00:01.0: PCI bridge to [bus 01]
[    0.688737] pci 0000:00:01.0:   bridge window [io  0x7000-0x7fff]
[    0.688741] pci 0000:00:01.0:   bridge window [mem 0x92100000-0x922fffff]
[    0.688745] pci 0000:00:01.0:   bridge window [mem 0x80000000-0x8fffffff 64bit pref]
[    0.688749] pci 0000:00:04.0: PCI bridge to [bus 02-07]
[    0.688751] pci 0000:00:04.0:   bridge window [io  0x3000-0x6fff]
[    0.688755] pci 0000:00:04.0:   bridge window [mem 0x91100000-0x920fffff]
[    0.688758] pci 0000:00:04.0:   bridge window [mem 0x90000000-0x90ffffff 64bit pref]
[    0.688762] pci 0000:00:05.0: PCI bridge to [bus 08]
[    0.688765] pci 0000:00:05.0:   bridge window [io  0x2000-0x2fff]
[    0.688768] pci 0000:00:05.0:   bridge window [mem 0x91000000-0x910fffff]
[    0.688772] pci 0000:00:14.4: PCI bridge to [bus 09]
[    0.688793] pci 0000:00:01.0: setting latency timer to 64
[    0.689044] pci_bus 0000:00: resource 4 [io  0x0000-0x0cf7]
[    0.689047] pci_bus 0000:00: resource 5 [io  0x0d00-0xffff]
[    0.689049] pci_bus 0000:00: resource 6 [mem 0x000a0000-0x000bffff]
[    0.689052] pci_bus 0000:00: resource 7 [mem 0x000c0000-0x000c3fff]
[    0.689054] pci_bus 0000:00: resource 8 [mem 0x000c4000-0x000c7fff]
[    0.689057] pci_bus 0000:00: resource 9 [mem 0x000c8000-0x000cbfff]
[    0.689059] pci_bus 0000:00: resource 10 [mem 0x000d0000-0x000d3fff]
[    0.689062] pci_bus 0000:00: resource 11 [mem 0x000d4000-0x000d7fff]
[    0.689064] pci_bus 0000:00: resource 12 [mem 0x000d8000-0x000dbfff]
[    0.689066] pci_bus 0000:00: resource 13 [mem 0x000dc000-0x000dffff]
[    0.689069] pci_bus 0000:00: resource 14 [mem 0x000e0000-0x000e3fff]
[    0.689071] pci_bus 0000:00: resource 15 [mem 0x000e4000-0x000e7fff]
[    0.689073] pci_bus 0000:00: resource 16 [mem 0x000e8000-0x000ebfff]
[    0.689076] pci_bus 0000:00: resource 17 [mem 0x000ec000-0x000effff]
[    0.689078] pci_bus 0000:00: resource 18 [mem 0x80000000-0xf7ffffff]
[    0.689081] pci_bus 0000:00: resource 19 [mem 0xfc000000-0xfed3ffff]
[    0.689083] pci_bus 0000:00: resource 20 [mem 0xfed45000-0xffffffff]
[    0.689086] pci_bus 0000:01: resource 0 [io  0x7000-0x7fff]
[    0.689088] pci_bus 0000:01: resource 1 [mem 0x92100000-0x922fffff]
[    0.689091] pci_bus 0000:01: resource 2 [mem 0x80000000-0x8fffffff 64bit pref]
[    0.689093] pci_bus 0000:02: resource 0 [io  0x3000-0x6fff]
[    0.689096] pci_bus 0000:02: resource 1 [mem 0x91100000-0x920fffff]
[    0.689098] pci_bus 0000:02: resource 2 [mem 0x90000000-0x90ffffff 64bit pref]
[    0.689101] pci_bus 0000:08: resource 0 [io  0x2000-0x2fff]
[    0.689103] pci_bus 0000:08: resource 1 [mem 0x91000000-0x910fffff]
[    0.689177] NET: Registered protocol family 2
[    0.689381] TCP established hash table entries: 16384 (order: 6, 262144 bytes)
[    0.689514] TCP bind hash table entries: 16384 (order: 6, 262144 bytes)
[    0.689606] TCP: Hash tables configured (established 16384 bind 16384)
[    0.689671] TCP: reno registered
[    0.689679] UDP hash table entries: 1024 (order: 3, 32768 bytes)
[    0.689764] UDP-Lite hash table entries: 1024 (order: 3, 32768 bytes)
[    0.689897] NET: Registered protocol family 1
[    0.689913] pci 0000:00:01.0: MSI quirk detected; subordinate MSI disabled
[    0.691212] pci 0000:01:05.0: Boot video device
[    0.691220] PCI: CLS 64 bytes, default 64
[    0.691278] Unpacking initramfs...
[    1.063294] Freeing initrd memory: 2684K (ffff880037ab2000 - ffff880037d51000)
[    1.063634] Simple Boot Flag at 0x44 set to 0x1
[    1.063716] LVT offset 1 assigned for vector 0x400
[    1.063722] IBS: LVT offset 1 assigned
[    1.063746] perf: AMD IBS detected (0x0000001f)
[    1.064125] audit: initializing netlink socket (disabled)
[    1.064141] type=2000 audit(1376290884.944:1): initialized
[    1.080423] bounce pool size: 64 pages
[    1.080430] HugeTLB registered 2 MB page size, pre-allocated 0 pages
[    1.080964] VFS: Disk quotas dquot_6.5.2
[    1.081008] Dquot-cache hash table entries: 512 (order 0, 4096 bytes)
[    1.081119] msgmni has been set to 3503
[    1.081427] alg: No test for stdrng (krng)
[    1.081462] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    1.081503] io scheduler noop registered
[    1.081504] io scheduler deadline registered
[    1.081517] io scheduler cfq registered (default)
[    1.081677] pcieport 0000:00:04.0: irq 40 for MSI/MSI-X
[    1.081825] pcieport 0000:00:05.0: irq 41 for MSI/MSI-X
[    1.081975] pci_hotplug: PCI Hot Plug PCI Core version: 0.5
[    1.081997] pciehp: PCI Express Hot Plug Controller Driver version: 0.4
[    1.082113] GHES: HEST is not enabled!
[    1.082207] Serial: 8250/16550 driver, 4 ports, IRQ sharing enabled
[    1.082819] Linux agpgart interface v0.103
[    1.082925] i8042: PNP: PS/2 Controller [PNP0303:KBC0,PNP0f13:PS2M] at 0x60,0x64 irq 1,12
[    1.112145] serio: i8042 KBD port at 0x60,0x64 irq 1
[    1.112151] serio: i8042 AUX port at 0x60,0x64 irq 12
[    1.112371] mousedev: PS/2 mouse device common for all mice
[    1.112404] rtc_cmos 00:03: RTC can wake from S4
[    1.112582] rtc_cmos 00:03: rtc core: registered rtc_cmos as rtc0
[    1.112617] rtc_cmos 00:03: alarms up to one day, 114 bytes nvram, hpet irqs
[    1.112632] cpuidle: using governor ladder
[    1.112634] cpuidle: using governor menu
[    1.112707] TCP: cubic registered
[    1.113254] NET: Registered protocol family 10
[    1.113486] NET: Registered protocol family 17
[    1.113844] PM: Hibernation image not present or could not be loaded.
[    1.113859] registered taskstats version 1
[    1.114443] rtc_cmos 00:03: setting system clock to 2013-08-12 07:01:25 UTC (1376290885)
[    1.115745] Freeing unused kernel memory: 856K (ffffffff81695000 - ffffffff8176b000)
[    1.115749] Write protecting the kernel read-only data: 6144k
[    1.118871] Freeing unused kernel memory: 720K (ffff88000134c000 - ffff880001400000)
[    1.121300] Freeing unused kernel memory: 604K (ffff880001569000 - ffff880001600000)
[    1.139759] udevd[56]: starting version 175
[    1.146791] input: AT Translated Set 2 keyboard as /devices/platform/i8042/serio0/input/input0
[    1.170368] ACPI: bus type USB registered
[    1.170405] usbcore: registered new interface driver usbfs
[    1.170417] usbcore: registered new interface driver hub
[    1.174602] SCSI subsystem initialized
[    1.176040] ACPI: bus type ATA registered
[    1.184322] usbcore: registered new device driver usb
[    1.184747] ehci_hcd: USB 2.0 'Enhanced' Host Controller (EHCI) Driver
[    1.184929] ehci-pci: EHCI PCI platform driver
[    1.185189] ehci-pci 0000:00:12.2: setting latency timer to 64
[    1.185209] ehci-pci 0000:00:12.2: EHCI Host Controller
[    1.185222] ehci-pci 0000:00:12.2: new USB bus registered, assigned bus number 1
[    1.185231] QUIRK: Enable AMD PLL fix
[    1.185233] ehci-pci 0000:00:12.2: applying AMD SB700/SB800/Hudson-2/3 EHCI dummy qh workaround
[    1.185249] ehci-pci 0000:00:12.2: debug port 1
[    1.185306] ehci-pci 0000:00:12.2: irq 17, io mem 0x92307600
[    1.190382] libata version 3.00 loaded.
[    1.193374] ehci-pci 0000:00:12.2: USB 2.0 started, EHCI 1.00
[    1.193411] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.193414] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.193417] usb usb1: Product: EHCI Host Controller
[    1.193419] usb usb1: Manufacturer: Linux 3.11.0-rc4+ ehci_hcd
[    1.193421] usb usb1: SerialNumber: 0000:00:12.2
[    1.193609] hub 1-0:1.0: USB hub found
[    1.193616] hub 1-0:1.0: 5 ports detected
[    1.194098] ehci-pci 0000:00:13.2: setting latency timer to 64
[    1.194107] ehci-pci 0000:00:13.2: EHCI Host Controller
[    1.194115] ehci-pci 0000:00:13.2: new USB bus registered, assigned bus number 2
[    1.194121] ehci-pci 0000:00:13.2: applying AMD SB700/SB800/Hudson-2/3 EHCI dummy qh workaround
[    1.194133] ehci-pci 0000:00:13.2: debug port 1
[    1.194168] ehci-pci 0000:00:13.2: irq 17, io mem 0x92307500
[    1.205350] ehci-pci 0000:00:13.2: USB 2.0 started, EHCI 1.00
[    1.205385] usb usb2: New USB device found, idVendor=1d6b, idProduct=0002
[    1.205389] usb usb2: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.205392] usb usb2: Product: EHCI Host Controller
[    1.205394] usb usb2: Manufacturer: Linux 3.11.0-rc4+ ehci_hcd
[    1.205396] usb usb2: SerialNumber: 0000:00:13.2
[    1.205550] hub 2-0:1.0: USB hub found
[    1.205556] hub 2-0:1.0: 5 ports detected
[    1.206000] ehci-pci 0000:00:16.2: setting latency timer to 64
[    1.206010] ehci-pci 0000:00:16.2: EHCI Host Controller
[    1.206017] ehci-pci 0000:00:16.2: new USB bus registered, assigned bus number 3
[    1.206023] ehci-pci 0000:00:16.2: applying AMD SB700/SB800/Hudson-2/3 EHCI dummy qh workaround
[    1.206034] ehci-pci 0000:00:16.2: debug port 1
[    1.206068] ehci-pci 0000:00:16.2: irq 17, io mem 0x92307400
[    1.213191] ACPI: Fan [FAN1] (off)
[    1.217381] ehci-pci 0000:00:16.2: USB 2.0 started, EHCI 1.00
[    1.217420] usb usb3: New USB device found, idVendor=1d6b, idProduct=0002
[    1.217423] usb usb3: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.217426] usb usb3: Product: EHCI Host Controller
[    1.217429] usb usb3: Manufacturer: Linux 3.11.0-rc4+ ehci_hcd
[    1.217431] usb usb3: SerialNumber: 0000:00:16.2
[    1.217603] hub 3-0:1.0: USB hub found
[    1.217610] hub 3-0:1.0: 4 ports detected
[    1.218096] ahci 0000:00:11.0: version 3.0
[    1.218345] ahci 0000:00:11.0: irq 42 for MSI/MSI-X
[    1.218433] ahci 0000:00:11.0: AHCI 0001.0200 32 slots 3 ports 3 Gbps 0x7 impl SATA mode
[    1.218438] ahci 0000:00:11.0: flags: 64bit ncq sntf ilck pm led clo pmp pio slum part sxs 
[    1.220913] thermal LNXTHERM:00: registered as thermal_zone0
[    1.220917] ACPI: Thermal Zone [THZN] (53 C)
[    1.221130] scsi0 : ahci
[    1.221946] scsi1 : ahci
[    1.222325] scsi2 : ahci
[    1.222463] ata1: SATA max UDMA/133 abar m1024@0x92307000 port 0x92307100 irq 42
[    1.222467] ata2: SATA max UDMA/133 abar m1024@0x92307000 port 0x92307180 irq 42
[    1.222470] ata3: SATA max UDMA/133 abar m1024@0x92307000 port 0x92307200 irq 42
[    1.541194] ata3: SATA link down (SStatus 0 SControl 300)
[    1.713059] ata2: SATA link up 1.5 Gbps (SStatus 113 SControl 300)
[    1.713095] ata1: SATA link up 3.0 Gbps (SStatus 123 SControl 300)
[    1.715641] ata2.00: ATAPI: HL-DT-STDVDRAM GT30N, TN08, max UDMA/100
[    1.718625] ata2.00: configured for UDMA/100
[    1.761836] ata1.00: ATA-8: TOSHIBA MK3265GSXN, GH101M, max UDMA/100
[    1.761841] ata1.00: 625142448 sectors, multi 16: LBA48 NCQ (depth 31/32), AA
[    1.762720] ata1.00: configured for UDMA/100
[    1.763006] scsi 0:0:0:0: Direct-Access     ATA      TOSHIBA MK3265GS GH10 PQ: 0 ANSI: 5
[    1.765590] scsi 1:0:0:0: CD-ROM            HL-DT-ST DVDRAM GT30N     TN08 PQ: 0 ANSI: 5
[    1.771968] sd 0:0:0:0: [sda] 625142448 512-byte logical blocks: (320 GB/298 GiB)
[    1.772022] sd 0:0:0:0: [sda] Write Protect is off
[    1.772025] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
[    1.772049] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
[    1.774714] sr0: scsi3-mmc drive: 24x/24x writer dvd-ram cd/rw xa/form2 cdda tray
[    1.774720] cdrom: Uniform CD-ROM driver Revision: 3.20
[    1.774896] sr 1:0:0:0: Attached scsi CD-ROM sr0
[    1.836272]  sda: sda1 sda2 sda3 < sda5 >
[    1.836951] sd 0:0:0:0: [sda] Attached SCSI disk
[    1.839130] sd 0:0:0:0: Attached scsi generic sg0 type 0
[    1.839304] sr 1:0:0:0: Attached scsi generic sg1 type 5
[    2.060799] tsc: Refined TSC clocksource calibration: 2294.254 MHz
[    2.243678] device-mapper: uevent: version 1.0.3
[    2.243750] device-mapper: ioctl: 4.25.0-ioctl (2013-06-26) initialised: [email protected]
[    2.348947] bio: create slab <bio-1> at 1
[    2.629501] PM: Starting manual resume from disk
[    2.629507] PM: Hibernation image partition 254:1 present
[    2.629509] PM: Looking for hibernation image.
[    2.639228] PM: Image not found (code -22)
[    2.639232] PM: Hibernation image not present or could not be loaded.
[    2.662957] EXT4-fs (dm-0): mounted filesystem with ordered data mode. Opts: (null)
[    3.060128] Switched to clocksource tsc
[    4.059917] udevd[375]: starting version 175
[    4.861125] ACPI: AC Adapter [ADP0] (on-line)
[    4.861748] ACPI: processor limited to max C-state 1
[    4.868631] piix4_smbus 0000:00:14.0: SMBus Host Controller at 0xb00, revision 0
[    4.868998] acpi-cpufreq: overriding BIOS provided _PSD data
[    4.877991] sp5100_tco: SP5100/SB800 TCO WatchDog Timer Driver v0.05
[    4.878049] sp5100_tco: PCI Revision ID: 0x42
[    4.878122] sp5100_tco: Using 0xfed80b00 for watchdog MMIO address
[    4.878135] sp5100_tco: Last reboot was not triggered by watchdog.
[    4.878187] sp5100_tco: initialized (0xffffc9000037ab00). heartbeat=60 sec (nowayout=0)
[    4.886280] microcode: CPU0: patch_level=0x010000b6
[    4.891107] ACPI: Battery Slot [BAT0] (battery present)
[    4.891378] input: Power Button as /devices/LNXSYSTM:00/device:00/PNP0C0C:00/input/input1
[    4.891393] ACPI: Power Button [PWRB]
[    4.891573] input: Lid Switch as /devices/LNXSYSTM:00/device:00/PNP0C0D:00/input/input2
[    4.893488] ACPI: Lid Switch [LID]
[    4.894026] input: Power Button as /devices/LNXSYSTM:00/LNXPWRBN:00/input/input3
[    4.894037] ACPI: Power Button [PWRF]
[    4.912777] acpi device:03: registered as cooling_device3
[    4.912801] ACPI: Video Device [VGA] (multi-head: yes  rom: no  post: no)
[    4.912865] input: Video Bus as /devices/LNXSYSTM:00/device:00/PNP0A08:00/device:01/LNXVIDEO:00/input/input4
[    4.973755] input: PC Speaker as /devices/platform/pcspkr/input/input5
[    4.976931] shpchp: Standard Hot Plug PCI Controller Driver version: 0.4
[    4.979706] ohci_hcd: USB 1.1 'Open' Host Controller (OHCI) Driver
[    4.987328] wmi: Mapper loaded
[    5.031810] toshiba_acpi: Toshiba Laptop ACPI Extras version 0.19
[    5.032469] input: Toshiba input device as /devices/virtual/input/input6
[    5.038401] microcode: failed to load file amd-ucode/microcode_amd.bin
[    5.038964] microcode: CPU1: patch_level=0x010000b6
[    5.039070] microcode: Microcode Update Driver: v2.00 <[email protected]>, Peter Oruba
[    5.065700] [drm] Initialized drm 1.1.0 20060810
[    5.087178] ohci-pci: OHCI PCI platform driver
[    5.087421] ohci-pci 0000:00:12.0: setting latency timer to 64
[    5.087428] ohci-pci 0000:00:12.0: OHCI PCI host controller
[    5.087442] ohci-pci 0000:00:12.0: new USB bus registered, assigned bus number 4
[    5.087487] ohci-pci 0000:00:12.0: irq 18, io mem 0x92306000
[    5.146595] usb usb4: New USB device found, idVendor=1d6b, idProduct=0001
[    5.146607] usb usb4: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    5.146615] usb usb4: Product: OHCI PCI host controller
[    5.146621] usb usb4: Manufacturer: Linux 3.11.0-rc4+ ohci_hcd
[    5.146627] usb usb4: SerialNumber: 0000:00:12.0
[    5.147948] hub 4-0:1.0: USB hub found
[    5.147964] hub 4-0:1.0: 5 ports detected
[    5.148903] ohci-pci 0000:00:13.0: setting latency timer to 64
[    5.148912] ohci-pci 0000:00:13.0: OHCI PCI host controller
[    5.148928] ohci-pci 0000:00:13.0: new USB bus registered, assigned bus number 5
[    5.148970] ohci-pci 0000:00:13.0: irq 18, io mem 0x92305000
[    5.163104] cfg80211: Calling CRDA to update world regulatory domain
[    5.206521] usb usb5: New USB device found, idVendor=1d6b, idProduct=0001
[    5.206534] usb usb5: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    5.206542] usb usb5: Product: OHCI PCI host controller
[    5.206549] usb usb5: Manufacturer: Linux 3.11.0-rc4+ ohci_hcd
[    5.206554] usb usb5: SerialNumber: 0000:00:13.0
[    5.206947] hub 5-0:1.0: USB hub found
[    5.207001] hub 5-0:1.0: 5 ports detected
[    5.208062] ohci-pci 0000:00:16.0: setting latency timer to 64
[    5.208072] ohci-pci 0000:00:16.0: OHCI PCI host controller
[    5.208090] ohci-pci 0000:00:16.0: new USB bus registered, assigned bus number 6
[    5.208142] ohci-pci 0000:00:16.0: irq 18, io mem 0x92304000
[    5.266524] usb usb6: New USB device found, idVendor=1d6b, idProduct=0001
[    5.266536] usb usb6: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    5.266544] usb usb6: Product: OHCI PCI host controller
[    5.266550] usb usb6: Manufacturer: Linux 3.11.0-rc4+ ohci_hcd
[    5.266555] usb usb6: SerialNumber: 0000:00:16.0
[    5.267006] hub 6-0:1.0: USB hub found
[    5.267032] hub 6-0:1.0: 4 ports detected
[    5.292584] [drm] radeon kernel modesetting enabled.
[    5.293455] [drm] initializing kernel modesetting (RS880 0x1002:0x9712 0x1179:0xFDE4).
[    5.293498] [drm] register mmio base: 0x92200000
[    5.293503] [drm] register mmio size: 65536
[    5.301098] ATOM BIOS: Tos_Berlin10AD
[    5.301149] radeon 0000:01:05.0: VRAM: 256M 0x00000000C0000000 - 0x00000000CFFFFFFF (256M used)
[    5.301157] radeon 0000:01:05.0: GTT: 512M 0x00000000A0000000 - 0x00000000BFFFFFFF
[    5.301166] [drm] Detected VRAM RAM=256M, BAR=256M
[    5.301170] [drm] RAM width 32bits DDR
[    5.301299] [TTM] Zone  kernel: Available graphics memory: 898020 kiB
[    5.301300] [TTM] Initializing pool allocator
[    5.301306] [TTM] Initializing DMA pool allocator
[    5.301333] [drm] radeon: 256M of VRAM memory ready
[    5.301335] [drm] radeon: 512M of GTT memory ready.
[    5.301347] [drm] GART: num cpu pages 131072, num gpu pages 131072
[    5.320736] [drm] Loading RS780 Microcode
[    5.338145] r600_cp: Failed to load firmware "radeon/RS780_pfp.bin"
[    5.338278] [drm:r600_startup] *ERROR* Failed to load firmware!
[    5.338331] radeon 0000:01:05.0: disabling GPU acceleration
[    5.339702] radeon 0000:01:05.0: ffff880069da9400 unpin not necessary
[    5.340300] [drm] radeon atom DIG backlight initialized
[    5.340305] [drm] Radeon Display Connectors
[    5.340309] [drm] Connector 0:
[    5.340313] [drm]   VGA-1
[    5.340319] [drm]   DDC: 0x7e40 0x7e40 0x7e44 0x7e44 0x7e48 0x7e48 0x7e4c 0x7e4c
[    5.340322] [drm]   Encoders:
[    5.340326] [drm]     CRT1: INTERNAL_KLDSCP_DAC1
[    5.340329] [drm] Connector 1:
[    5.340333] [drm]   LVDS-1
[    5.340339] [drm]   DDC: 0x7e50 0x7e50 0x7e54 0x7e54 0x7e58 0x7e58 0x7e5c 0x7e5c
[    5.340342] [drm]   Encoders:
[    5.340346] [drm]     LCD1: INTERNAL_KLDSCP_LVTMA
[    5.340377] [drm] radeon: power management initialized
[    5.733892] ath: phy0: ASPM enabled: 0x42
[    5.733903] ath: EEPROM regdomain: 0x65
[    5.733908] ath: EEPROM indicates we should expect a direct regpair map
[    5.733916] ath: Country alpha2 being used: 00
[    5.733920] ath: Regpair used: 0x65
[    5.772820] ieee80211 phy0: Selected rate control algorithm 'minstrel_ht'
[    5.773419] ieee80211 phy0: Atheros AR9285 Rev:2 mem=0xffffc900013e0000, irq=16
[    5.778400] kvm: Nested Virtualization enabled
[    5.778416] kvm: Nested Paging enabled
[    5.803078] snd_hda_intel 0000:00:14.2: setting latency timer to 64
[    5.864026] input: HDA Digital PCBeep as /devices/pci0000:00/0000:00:14.2/input/input7
[    6.251148] psmouse serio1: synaptics: Touchpad model: 1, fw: 7.2, id: 0x1c0b1, caps: 0xd04733/0xa40000/0xa0000, board id: 3655, fw id: 582762
[    6.251169] psmouse serio1: synaptics: Toshiba Satellite C650D detected, limiting rate to 40pps.
[    6.335430] [drm] fb mappable at 0x80040000
[    6.335439] [drm] vram apper at 0x80000000
[    6.335443] [drm] size 4325376
[    6.335447] [drm] fb depth is 24
[    6.335451] [drm]    pitch is 5632
[    6.335683] fbcon: radeondrmfb (fb0) is primary device
[    6.355680] input: SynPS/2 Synaptics TouchPad as /devices/platform/i8042/serio1/input/input8
[    6.410984] Console: switching to colour frame buffer device 170x48
[    6.424157] radeon 0000:01:05.0: fb0: radeondrmfb frame buffer device
[    6.424164] radeon 0000:01:05.0: registered panic notifier
[    6.424482] [drm] Initialized radeon 2.34.0 20080528 for 0000:01:05.0 on minor 0
[    8.014260] EXT4-fs (dm-0): re-mounted. Opts: (null)
[    8.139624] EXT4-fs (dm-0): re-mounted. Opts: errors=remount-ro
[    8.715272] Adding 4882428k swap on /dev/mapper/data-swap.  Priority:-1 extents:1 across:4882428k 
[    9.295763] fuse init (API version 7.22)
[    9.333131] loop: module loaded
[    9.435146] kjournald starting.  Commit interval 5 seconds
[    9.435688] EXT3-fs (sda1): using internal journal
[    9.435701] EXT3-fs (sda1): mounted filesystem with ordered data mode
[    9.483220] EXT4-fs (dm-4): mounted filesystem with ordered data mode. Opts: (null)
[    9.517596] EXT4-fs (dm-2): mounted filesystem with ordered data mode. Opts: (null)
[    9.557272] EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null)
[   14.805373] input: ACPI Virtual Keyboard Device as /devices/virtual/input/input9
[   24.300277] lp: driver loaded but no devices found
[   24.307971] ppdev: user-space parallel port driver

Hello, Jonathan.

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

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

Well, with the modern logic ("only wait for async probing if the module itself did async probing") the ahci and svw modules didn't really change any behavior.

But other modules did. I wonder, for example, if people insmod the dm module, and expect all devices to exist afterwards. Which the old logic of "we always wait for all async code regardless of whether we started it ourselves" would do, but the new logic does not.

Something similar might hit the (non-modular) md auto-detect ioctl.

So maybe we should just special-case those two issues, and say "let's just wait for async requests here"

Something like the appended (whitespace-damaged) diff. Does that make a difference to you guys? And if it does, can you check *which* of the two async_synchronize_full() calls it is that matters for your cases?

Linus

--- duh, apply by hand --

    diff --git a/drivers/md/dm.c b/drivers/md/dm.c
    index 0704c523a76b..7e7a2f743b11 100644
    --- a/drivers/md/dm.c
    +++ b/drivers/md/dm.c
    @@ -351,6 +351,7 @@ static int __init dm_init(void)
                            goto bad;
            }

    +       async_synchronize_full();
            return 0;

           bad:
    diff --git a/drivers/md/md.c b/drivers/md/md.c
    index b6b7a2866c9e..1d173dc662fc 100644
    --- a/drivers/md/md.c
    +++ b/drivers/md/md.c
    @@ -8602,6 +8602,7 @@ static void autostart_arrays(int part)
            i_scanned = 0;
            i_passed = 0;

    +       async_synchronize_full();
            printk(KERN_INFO "md: Autodetecting RAID arrays.\n");

            while (!list_empty(&all_detected_devices) && i_scanned < INT_MAX) {

I should have clarified that I'm not using dm/md in my setup. I know the modules are getting loaded in the log I attached, but root is not a md/dm device.

Josh

Hello,

Can you please still try it? The init script is broken and we're now just trying to restore just enough of the old behavior so that the issue is not exposed. The boot script in use seems to load md/dm modules after storage drivers and use their termination as the signal for "storage ready", so it could be a good enough bandaid even if you're not using dm/md.

Thanks.

tejun

Tejun

You're right. Thanks for pointing this out. I did not realize there was a bug in the init script. The version of initramfs-tools I was using had the following bug:
https://bugs.launchpad.net/ubuntu/+source/initramfs-tools/+bug/1215911

Updating to 0.99ubuntu13.4 of initramfs-tools resolved my boot hangs.

I did try using the workaround as suggested by Linus. In my setup the dm_init() code was hit, however it still appeared to be too late at times. I also tried moving the call to async_synchronize_full() above the for loop and it still had the same issue (patch attached.) Out of around 10 reboot tests it failed to find root 1 or 2 times.

The ubuntu scripts don't ever actually call do_mount() if it can't find the device. It seems to rely on some udev functionality to tell it when the device is present, and if that fails it just bails out.

This change has introduced a regression. However, I only noticed it b/c my init script had a bug which caused it not to wait around for the device to appear.

Josh

Index: linux-3.10/drivers/md/dm.c
===================================================================
@@ -16,12 +16,13 @@
 #include <linux/bio.h>
 #include <linux/mempool.h>
 #include <linux/slab.h>
 #include <linux/idr.h>
 #include <linux/hdreg.h>
 #include <linux/delay.h>
+#include <linux/async.h>
 
 #include <trace/events/block.h>
 
 #define DM_MSG_PREFIX "core"
 
 #ifdef CONFIG_PRINTK

@@ -275,12 +276,15 @@ static void (*_exits[])(void) = {
 static int __init dm_init(void)
 {
 	const int count = ARRAY_SIZE(_inits);
 
 	int r, i;
 
+	printk(KERN_CRIT "DBG: %s: Calling async_synchronize_full();\n", __func__);
+	async_synchronize_full();
+
 	for (i = 0; i < count; i++) {
 		r = _inits[i]();
 		if (r)
 			goto bad;
 	}
 

Index: linux-3.10/drivers/md/md.c
===================================================================
@@ -48,12 +48,13 @@
 #include <linux/file.h>
 #include <linux/compat.h>
 #include <linux/delay.h>
 #include <linux/raid/md_p.h>
 #include <linux/raid/md_u.h>
 #include <linux/slab.h>
+#include <linux/async.h>
 #include "md.h"
 #include "bitmap.h"
 
 #ifndef MODULE
 static void autostart_arrays(int part);
 #endif

@@ -8573,12 +8574,14 @@ static void autostart_arrays(int part)
 	dev_t dev;
 	int i_scanned, i_passed;
 
 	i_scanned = 0;
 	i_passed = 0;
 
+	printk(KERN_CRIT "DBG: %s: Calling async_synchronize_full()\n", __func__);
+	async_synchronize_full();
 	printk(KERN_INFO "md: Autodetecting RAID arrays.\n");
 
 	while (!list_empty(&all_detected_devices) && i_scanned < INT_MAX) {
 		i_scanned++;
 		node_detected_dev = list_entry(all_detected_devices.next,
 					struct detected_devices_node, list);

Hello,

Hmmm.... so, read the bug report, digged and asked around a bit. Here's the root problem - ubuntu's initramfs uses a tool to wait for the root device which uses libudev to listen for the device event; unfortunately, its rx buffer is not set large enough and the receiver isn't fast enough, which means that netlink broadcast messages from the kernel can overrun the buffer. When that happens, it sets an error on the socket, so the next recv fails with -ENOBUFS. If that happens, the wait for root aborts immediately and initramfs proceeds to mount non-existent root device.

The only thing which changes by these patches is the timing of events. The problem likely wasn't as exposed before because things were slow enough so that either the messages could be consumed fast enough or there's enough delay between libata module load and the root device wait hiding the bug in the wait logic.

So, yeah, it's a full blown timing bug. I'm not sure what we can do to work around from kernel side except for randomly slowing things down or forcefully enlarging rx buffer size. There really is no interlocking to take advantage of. :(

Thanks.

tejun

So there used to be a call to async_synchronize_full() in ata_host_register(), but it was removed by f29d3b23238e1955a8094e038c72546e99308e61 as part of some fastboot changes. Adding it back (in the attached patch) seems to resolve the issue when using the broken initrd. I'm guessing adding it back isn't an option, but I wanted to point it out.

Josh

Index: b/drivers/ata/libata-core.c
===================================================================
@@ -6181,12 +6181,14 @@ int ata_host_register(struct ata_host *h
 	/* perform each probe asynchronously */
 	for (i = 0; i < host->n_ports; i++) {
 		struct ata_port *ap = host->ports[i];
 		async_schedule(async_port_probe, ap);
 	}
 
+	async_synchronize_full();
+
 	return 0;
 
  err_tadd:
 	while (--i >= 0) {
 		ata_tport_delete(host->ports[i]);
 	}

Hello, Josh.

The problem is that really isn't the root cause of it. There's no real interlocking there and the problem gets hidden just because things are slower. Putting ssleep(2) there would work the same, so the true issue is "the kernel is faster with probing now", which is somewhat challenging to rectify. :(

Thanks.

tejun

Hmm. The initcall debugging doesn't actually show any of the "wait for async events", because those debug messages come from "do_one_initcall()", and the waiting happens later. Plus your messages don't actually show where you are trying to - and failing - to mount the root filesystem.

Without that kind of information, it's kind of hard to guess. Maybe you could add a few printk's to your kernel? Add one to do_init_module() *after* the

        if (current->flags & PF_USED_ASYNC)
                async_synchronize_full();

thing, and another to fs/namespace.c: do_mount() (just put something like

        printk("do_mount: %s at %s\n", dev_name, dir_name);

or whatever, so that we can see when that happens..

Linus

Right. Gees, there's even no way to link them.

tejun

083b804c4d3e1e3d0eace56bdbc0f674946d2847 ("async: use workqueue for worker pool") made it possible that async jobs are moved from pending to running out-of-order. While pending async jobs will be queued and dispatched for execution in the same order, nothing guarantees they'll enter "1) move self to the running queue" of async_run_entry_fn() in the same order.

This broke __lowest_in_progress(). running->domain may not be properly sorted and is not guaranteed to contain lower cookies than pending list when not empty. Fix it by ensuring sort-inserting to the running list and always looking at both pending and running when trying to determine the lowest cookie.

Over time, the async synchronization implementation became quite messy. We better restructure it such that each async_entry is linked to two lists - one global and one per domain - and not move it when execution starts. There's no reason to distinguish pending and running. They behave the same for synchronization purposes.

---
And here's the fix for the breakage I mentioned earlier. It wouldn't happen often in the wild and the effect of it happening wouldn't be critical for modern distros but it's still kinda surprising nobody noticed this.

We definitely need to rewrite async synchronization. It was already messy and this makes it worse and there's no reason to be messy here.

Thanks.

 kernel/async.c |   27 ++++++++++++++++++++-------
 1 file changed, 20 insertions(+), 7 deletions(-)

@@ -86,18 +86,27 @@ static atomic_t entry_count;
  */
 static async_cookie_t  __lowest_in_progress(struct async_domain *running)
 {
+	async_cookie_t first_running = next_cookie;	/* infinity value */
+	async_cookie_t first_pending = next_cookie;	/* ditto */
 	struct async_entry *entry;
 
+	/*
+	 * Both running and pending lists are sorted but not disjoint.
+	 * Take the first cookies from both and return the min.
+	 */
 	if (!list_empty(&running->domain)) {
 		entry = list_first_entry(&running->domain, typeof(*entry), list);
-		return entry->cookie;
+		first_running = entry->cookie;
 	}
 
-	list_for_each_entry(entry, &async_pending, list)
-		if (entry->running == running)
-			return entry->cookie;
+	list_for_each_entry(entry, &async_pending, list) {
+		if (entry->running == running) {
+			first_pending = entry->cookie;
+			break;
+		}
+	}
 
-	return next_cookie;	/* "infinity" value */
+	return min(first_running, first_pending);
 }
 
 static async_cookie_t  lowest_in_progress(struct async_domain *running)

@@ -118,13 +127,17 @@ static void async_run_entry_fn(struct wo
 {
 	struct async_entry *entry =
 		container_of(work, struct async_entry, work);
+	struct async_entry *pos;
 	unsigned long flags;
 	ktime_t uninitialized_var(calltime), delta, rettime;
 	struct async_domain *running = entry->running;
 
-	/* 1) move self to the running queue */
+	/* 1) move self to the running queue, make sure it stays sorted */
 	spin_lock_irqsave(&async_lock, flags);
-	list_move_tail(&entry->list, &running->domain);
+	list_for_each_entry_reverse(pos, &running->domain, list)
+		if (entry->cookie < pos->cookie)
+			break;
+	list_move_tail(&entry->list, &pos->list);
 	spin_unlock_irqrestore(&async_lock, flags);
 
 	/* 2) run (and print duration) */

Tejun, mind explaining this one a bit more to me?

If ordering matters, and we have a running queue and a pending queue, how could the pending queue *ever* be lower than the running one?

That implies that something was taken off the pending queue and put on the running queue out of order, right?

And that in turn implies that there isn't much of a "lowest" ordering at all, so how could anybody even care about what lowest is? It seems to be a meaningless measure.

So with that in mind, I don't see what semantics the first part of the patch fixes. Can you explain more?

Linus

Hello,

So, before being converted to workqueue, async spooled up its own workers and each worker would lock and move the first pending item to the executing list and everything was in order.

The conversion to workqueue was done by adding work_struct to each async_entry and async just schedules the work item. The queueing and dispatching of such work items are still in order but now each worker thread is associated with a specific async_entry and move that specific async_entry to the executing list. So, depending on which worker reaches that point earlier, which is completely non-deterministic, we may end up moving an async_entry with larger cookie before one with smaller one.

The execution is still lowest first as workqueue would dispatch workers in queued order. It just is that they can reach the synchronization point at their own differing paces.

The problem with the code is that it's keeping a global pending list and domain-specific running lists. I don't know why it developed like this but even before workqueue conversion the code was weird.

* It has sorted per-domain running list, so looking at the first item is easy.

* It has sorted global pennding list, and looking for first item in a domain involves scanning it.

Global syncing ends up scanning all per-domain running lists and domain syncing ends up scanning global pending list, when all we need is each async item to be queued on two lists - global and per-domain in-flight lists - and stay there until done.

The posted patch is minimal fix while keeping the basic operation the same so that it doesn't disturb -stable too much. I'll prep a patch to redo synchronization for 3.9.

Thanks.

tejun

083b804c4d3e1e3d0eace56bdbc0f674946d2847 ("async: use workqueue for worker pool") made it possible that async jobs are moved from pending to running out-of-order. While pending async jobs will be queued and dispatched for execution in the same order, nothing guarantees they'll enter "1) move self to the running queue" of async_run_entry_fn() in the same order.

Before the conversion, async implemented its own worker pool. An async worker, upon being woken up, fetches the first item from the pending list, which kept the executing lists sorted. The conversion to workqueue was done by adding work_struct to each async_entry and async just schedules the work item. The queueing and dispatching of such work items are still in order but now each worker thread is associated with a specific async_entry and moves that specific async_entry to the executing list. So, depending on which worker reaches that point earlier, which is non-deterministic, we may end up moving an async_entry with larger cookie before one with smaller one.

This broke __lowest_in_progress(). running->domain may not be properly sorted and is not guaranteed to contain lower cookies than pending list when not empty. Fix it by ensuring sort-inserting to the running list and always looking at both pending and running when trying to determine the lowest cookie.

Over time, the async synchronization implementation became quite messy. We better restructure it such that each async_entry is linked to two lists - one global and one per domain - and not move it when execution starts. There's no reason to distinguish pending and running. They behave the same for synchronization purposes.

v2: Description updated to better explain why it's broken.

---
Linus, I've updated the description to better explain why it's broken. The code is ugly but cleanup patches are already ready, so it will be cleaned up during 3.9-rc1. How should this be routed?

Thanks.

 kernel/async.c |   27 ++++++++++++++++++++-------
 1 file changed, 20 insertions(+), 7 deletions(-)

@@ -86,18 +86,27 @@ static atomic_t entry_count;
  */
 static async_cookie_t  __lowest_in_progress(struct async_domain *running)
 {
+	async_cookie_t first_running = next_cookie;	/* infinity value */
+	async_cookie_t first_pending = next_cookie;	/* ditto */
 	struct async_entry *entry;
 
+	/*
+	 * Both running and pending lists are sorted but not disjoint.
+	 * Take the first cookies from both and return the min.
+	 */
 	if (!list_empty(&running->domain)) {
 		entry = list_first_entry(&running->domain, typeof(*entry), list);
-		return entry->cookie;
+		first_running = entry->cookie;
 	}
 
-	list_for_each_entry(entry, &async_pending, list)
-		if (entry->running == running)
-			return entry->cookie;
+	list_for_each_entry(entry, &async_pending, list) {
+		if (entry->running == running) {
+			first_pending = entry->cookie;
+			break;
+		}
+	}
 
-	return next_cookie;	/* "infinity" value */
+	return min(first_running, first_pending);
 }
 
 static async_cookie_t  lowest_in_progress(struct async_domain *running)

@@ -118,13 +127,17 @@ static void async_run_entry_fn(struct wo
 {
 	struct async_entry *entry =
 		container_of(work, struct async_entry, work);
+	struct async_entry *pos;
 	unsigned long flags;
 	ktime_t uninitialized_var(calltime), delta, rettime;
 	struct async_domain *running = entry->running;
 
-	/* 1) move self to the running queue */
+	/* 1) move self to the running queue, make sure it stays sorted */
 	spin_lock_irqsave(&async_lock, flags);
-	list_move_tail(&entry->list, &running->domain);
+	list_for_each_entry_reverse(pos, &running->domain, list)
+		if (entry->cookie < pos->cookie)
+			break;
+	list_move_tail(&entry->list, &pos->list);
 	spin_unlock_irqrestore(&async_lock, flags);
 
 	/* 2) run (and print duration) */

I'm not a huge fan of the patch and I might even have preferred the whole cleanup, but I took it as-is.

Linus

As discussed previously, only the module which will populate device node for user space inside async func may require the synchronization, so that the below

modprobe A
mount /dev/XXX /mnt

script can't be broken, and that should be the original bug report:

           https://bugzilla.kernel.org/attachment.cgi?id=20937

For other modules, looks the synchonization isn't needed, at least there are lots of other async(work, kthread, ...) things which is scheduled in driver probe() and no any synchronize is added after the module init() completes inside loading module. Do we need to add that sync for all async things inside loading module?

So looks only sd.c and floppy.c are to be synchronized suppose some sync interfaces are introduced, doesn't it?

Thanks
--
Ming Lei

What about ata_host_register() (usually called through ata_host_activate())?

I don't understand why you continue to push for something fragile where you have to get things right in the driver, when it clearly is very fragile indeed, as now shown *twice* by how you seem to have missed some potential case.

This is *exactly* why I NAK'ed the patch, and said it has to be handled automatically (or at least default to the safe model, not the unsafe one).

We do have the automatic patch now. Admittedly it's not wonderful, and I agreed when Tejun called it slightly ugly, but at least it does these things automatically without humans having to go through these cases one by one and having to get them right. So please just stop pushing this "manual marking" thing. It's fundamentally flawed and broken.

Linus

OK, your trace is totally different. If your hangs are related, as is likely, my explanation goes out of the window.

Regards
Oliver

If I run 'shutdown' after unplugging usb storage device, another hang trace same with Alex's can be triggered too, so it should be one same problem.

Thanks,
--
Ming Lei

I used the USB2 port, but enabled the debugging for xHCI too, just because it is not as mature as you say, but in the same machine. And there are some traces from it, even though I didn't touch the USB3 ports. Might be unrelated, but just in case...

For the record, I just retested: the problem persists with 3.7.1.

Attached. A remount in the middle is me remounting an SATA device to save dmesg output in case the system crashes hard.