> From: linux-kernel-owner@xxxxxxxxxxxxxxx [mailto:linux-kernel- > owner@xxxxxxxxxxxxxxx] On Behalf Of Hannes Reinecke > Sent: Wednesday, February 1, 2017 00:15 > To: Bart Van Assche <Bart.VanAssche@xxxxxxxxxxx>; hare@xxxxxxx; > axboe@xxxxxxxxx > Cc: hch@xxxxxx; linux-kernel@xxxxxxxxxxxxxxx; linux-block@xxxxxxxxxxxxxxx; > jth@xxxxxxxxxx > Subject: Re: [PATCH] genhd: Do not hold event lock when scheduling workqueue > elements > > On 01/31/2017 01:31 AM, Bart Van Assche wrote: > > On Wed, 2017-01-18 at 10:48 +0100, Hannes Reinecke wrote: > >> @@ -1488,26 +1487,13 @@ static unsigned long > disk_events_poll_jiffies(struct gendisk *disk) > >> void disk_block_events(struct gendisk *disk) > >> { > >> struct disk_events *ev = disk->ev; > >> - unsigned long flags; > >> - bool cancel; > >> > >> if (!ev) > >> return; > >> > >> - /* > >> - * Outer mutex ensures that the first blocker completes canceling > >> - * the event work before further blockers are allowed to finish. > >> - */ > >> - mutex_lock(&ev->block_mutex); > >> - > >> - spin_lock_irqsave(&ev->lock, flags); > >> - cancel = !ev->block++; > >> - spin_unlock_irqrestore(&ev->lock, flags); > >> - > >> - if (cancel) > >> + if (atomic_inc_return(&ev->block) == 1) > >> cancel_delayed_work_sync(&disk->ev->dwork); > >> > >> - mutex_unlock(&ev->block_mutex); > >> } > > > > Hello Hannes, > > > > I have already encountered a few times a deadlock that was caused by the > > event checking code so I agree with you that it would be a big step forward > > if such deadlocks wouldn't occur anymore. However, this patch realizes a > > change that has not been described in the patch description, namely that > > disk_block_events() calls are no longer serialized. Are you sure it is safe > > to drop the serialization of disk_block_events() calls? > > > Well, this whole synchronization stuff it a bit weird; I so totally fail > to see the rationale for it. > But anyway, once we've converted ev->block to atomics I _think_ the > mutex_lock can remain; will be checking. > > Cheers, > > Hannes > -- Hi, I think I got the same calltrace with today's linux-next (next-20170203). The issue happened every time when my Linux virtual machine booted and Hannes's patch could NOT help. The calltrace is pasted below. Thanks, -- Dexuan [ 9.718802] scsi host2: storvsc_host_t [ 9.723854] scsi 2:0:0:0: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 5 [ 9.753161] sd 2:0:0:0: Attached scsi generic sg1 type 0 [ 9.766383] scsi host3: storvsc_host_t [ 9.771759] scsi 3:0:0:0: Direct-Access Msft Virtual Disk 1.0 PQ: 0 ANSI: 5 [ 9.781836] hv_utils: VSS IC version 5.0 [ 9.822511] sd 3:0:0:0: Attached scsi generic sg2 type 0 [ 9.829039] sd 3:0:0:0: [sdb] 266338304 512-byte logical blocks: (136 GB/127 GiB) [ 9.838525] sd 3:0:0:0: [sdb] 4096-byte physical blocks [ 9.845350] sd 3:0:0:0: [sdb] Write Protect is off [ 9.851077] sd 3:0:0:0: [sdb] Mode Sense: 0f 00 00 00 [ 9.859765] sd 3:0:0:0: [sdb] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA [ 9.872728] sdb: sdb1 [ 9.877279] sd 3:0:0:0: [sdb] Attached SCSI disk [ 9.964093] psmouse serio1: trackpoint: failed to get extended button data [ 14.864110] psmouse serio1: trackpoint: IBM TrackPoint firmware: 0x01, buttons: 0/0 [ 14.876423] input: TPPS/2 IBM TrackPoint as /devices/platform/i8042/serio1/input/input3 [ 14.887216] input: AT Translated Set 2 keyboard as /devices/LNXSYSTM:00/LNXSYBUS:00/PNP0A03:00/device:07/VMBUS:01/d34b2567-b9b6-42b9-8778-0a4ec0b955bf/serio2/input/input5 [ 44.644061] random: crng init done [ 66.524169] hv_utils: KVP IC version 4.0 Begin: Loading essential drivers ... done. Begin: Running /scripts/init-premount ... done. Begin: Mounting root file system ... Begin: Running /scripts/local-top ... done. Begin: Running /scripts/local-premount ... done. Begin: Waiting for root file system ... Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. Begin: Running /scripts/local-block ... done. [ 242.652127] INFO: task systemd-udevd:183 blocked for more than 120 seconds. [ 242.661008] Not tainted 4.10.0-rc6-next-20170203+ #2 [ 242.697270] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 242.707872] systemd-udevd D 0 183 170 0x00000004 [ 242.714654] Call Trace: [ 242.717904] __schedule+0x27d/0x8d0 [ 242.724618] schedule+0x36/0x80 [ 242.729042] schedule_timeout+0x235/0x3f0 [ 242.736667] ? sched_clock+0x9/0x10 [ 242.741144] ? try_to_wake_up+0x4a/0x460 [ 242.745580] wait_for_completion+0xa5/0x120 [ 242.751417] ? wake_up_q+0x70/0x70 [ 242.759394] flush_work+0x11a/0x1c0 [ 242.764846] ? worker_detach_from_pool+0xb0/0xb0 [ 242.770943] __cancel_work_timer+0xf3/0x1b0 [ 242.776073] ? disk_map_sector_rcu+0x70/0x70 [ 242.783857] cancel_delayed_work_sync+0x13/0x20 [ 242.789438] disk_block_events+0x34/0x40 [ 242.794641] __blkdev_get+0x10c/0x470 [ 242.799227] blkdev_get+0x11a/0x320 [ 242.803161] ? unlock_new_inode+0x49/0x80 [ 242.807451] ? bdget+0x110/0x130 [ 242.811415] blkdev_open+0x5b/0x70 [ 242.820215] do_dentry_open+0x208/0x310 [ 242.825336] ? blkdev_get_by_dev+0x50/0x50 [ 242.836362] vfs_open+0x4c/0x70 [ 242.839839] ? may_open+0x9b/0x100 [ 242.843803] path_openat+0x297/0x13e0 [ 242.848410] ? _copy_to_user+0x2e/0x40 [ 242.852966] ? move_addr_to_user+0xa3/0xc0 [ 242.857961] do_filp_open+0x7e/0xe0 [ 242.862154] ? _cond_resched+0x1a/0x50 [ 242.867045] ? kmem_cache_alloc+0x156/0x1b0 [ 242.872004] ? getname_flags+0x56/0x1f0 [ 242.881609] ? __alloc_fd+0x46/0x170 [ 242.891812] do_sys_open+0x11b/0x1f0 [ 242.896506] SyS_open+0x1e/0x20 [ 242.900365] entry_SYSCALL_64_fastpath+0x1e/0xad [ 242.905607] RIP: 0033:0x7efd3827aca0 [ 242.909773] RSP: 002b:00007ffd7ceaeb38 EFLAGS: 00000246 ORIG_RAX: 0000000000000002 [ 242.918778] RAX: ffffffffffffffda RBX: 0000555fdf1a2d40 RCX: 00007efd3827aca0 [ 242.925725] RDX: 0000555fde106058 RSI: 00000000000a0800 RDI: 0000555fdf1a2ff0 [ 242.929715] RBP: 0000000000000000 R08: 0000000000000073 R09: 0000000000000003 [ 242.933921] R10: 00007efd37fe6520 R11: 0000000000000246 R12: 0000000000000000 [ 242.942260] R13: 0000555fdf1a2d40 R14: 00007ffd7ceaea00 R15: 0000000000000000 [ 242.952780] INFO: task systemd-udevd:191 blocked for more than 120 seconds. [ 242.960994] Not tainted 4.10.0-rc6-next-20170203+ #2 [ 242.966936] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 242.975395] systemd-udevd D 0 191 170 0x00000004 [ 242.983460] Call Trace: [ 242.986694] __schedule+0x27d/0x8d0 [ 242.992603] ? mutex_lock+0x12/0x40 [ 242.996467] ? kprobes_module_callback+0x15b/0x1d0 [ 243.001934] schedule+0x36/0x80 [ 243.005908] async_synchronize_cookie_domain+0x91/0x130 [ 243.012331] ? wake_atomic_t_function+0x60/0x60 [ 243.017690] async_synchronize_full+0x17/0x20 [ 243.022662] do_init_module+0xc1/0x1ff [ 243.026965] load_module+0x2313/0x29a0 [ 243.031232] ? __symbol_put+0x40/0x40 [ 243.035347] ? security_kernel_post_read_file+0x6b/0x80 [ 243.042541] SYSC_finit_module+0xbc/0xf0 [ 243.045130] SyS_finit_module+0xe/0x10 [ 243.049116] entry_SYSCALL_64_fastpath+0x1e/0xad [ 243.054517] RIP: 0033:0x7efd37fa1c19 [ 243.058744] RSP: 002b:00007ffd7ceae188 EFLAGS: 00000246 ORIG_RAX: 0000000000000139 [ 243.067483] RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 00007efd37fa1c19 [ 243.075801] RDX: 0000000000000000 RSI: 00007efd38497e2a RDI: 000000000000000c [ 243.084162] RBP: 00007ffd7cead190 R08: 0000000000000000 R09: 0000000000000000 [ 243.093738] R10: 000000000000000c R11: 0000000000000246 R12: 0000555fdf1a3300 [ 243.103158] R13: 00007ffd7cead170 R14: 0000000000000005 R15: 000000000aba9500 [ 363.484110] INFO: task systemd-udevd:183 blocked for more than 120 seconds. [ 363.493200] Not tainted 4.10.0-rc6-next-20170203+ #2 [ 363.500109] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 363.509635] systemd-udevd D 0 183 170 0x00000004 [ 363.516428] Call Trace: [ 363.519492] __schedule+0x27d/0x8d0 [ 363.523850] schedule+0x36/0x80 [ 363.529927] schedule_timeout+0x235/0x3f0 [ 363.534884] ? sched_clock+0x9/0x10 [ 363.539006] ? try_to_wake_up+0x4a/0x460 [ 363.543686] wait_for_completion+0xa5/0x120 [ 363.548831] ? wake_up_q+0x70/0x70 [ 363.552993] flush_work+0x11a/0x1c0 [ 363.557236] ? worker_detach_from_pool+0xb0/0xb0 [ 363.562851] __cancel_work_timer+0xf3/0x1b0 [ 363.567942] ? disk_map_sector_rcu+0x70/0x70 [ 363.572973] cancel_delayed_work_sync+0x13/0x20 [ 363.580271] disk_block_events+0x34/0x40 [ 363.585284] __blkdev_get+0x10c/0x470 [ 363.589774] blkdev_get+0x11a/0x320 [ 363.593851] ? unlock_new_inode+0x49/0x80 [ 363.598509] ? bdget+0x110/0x130 [ 363.602272] blkdev_open+0x5b/0x70 [ 363.606254] do_dentry_open+0x208/0x310 [ 363.610722] ? blkdev_get_by_dev+0x50/0x50 [ 363.615493] vfs_open+0x4c/0x70 [ 363.619287] ? may_open+0x9b/0x100 [ 363.623386] path_openat+0x297/0x13e0 [ 363.627752] ? _copy_to_user+0x2e/0x40 [ 363.633978] ? move_addr_to_user+0xa3/0xc0 [ 363.638833] do_filp_open+0x7e/0xe0 [ 363.642809] ? _cond_resched+0x1a/0x50 [ 363.647070] ? kmem_cache_alloc+0x156/0x1b0 [ 363.651785] ? getname_flags+0x56/0x1f0 [ 363.656285] ? __alloc_fd+0x46/0x170 [ 363.660490] do_sys_open+0x11b/0x1f0 [ 363.664655] SyS_open+0x1e/0x20 [ 363.668405] entry_SYSCALL_64_fastpath+0x1e/0xad [ 363.674075] RIP: 0033:0x7efd3827aca0 [ 363.678582] RSP: 002b:00007ffd7ceaeb38 EFLAGS: 00000246 ORIG_RAX: 0000000000000002 [ 363.689873] RAX: ffffffffffffffda RBX: 0000555fdf1a2d40 RCX: 00007efd3827aca0 [ 363.698127] RDX: 0000555fde106058 RSI: 00000000000a0800 RDI: 0000555fdf1a2ff0 [ 363.706494] RBP: 0000000000000000 R08: 0000000000000073 R09: 0000000000000003 [ 363.714696] R10: 00007efd37fe6520 R11: 0000000000000246 R12: 0000000000000000 [ 363.722922] R13: 0000555fdf1a2d40 R14: 00007ffd7ceaea00 R15: 0000000000000000 [ 363.731123] INFO: task systemd-udevd:191 blocked for more than 120 seconds. [ 363.739454] Not tainted 4.10.0-rc6-next-20170203+ #2 [ 363.745246] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 363.753890] systemd-udevd D 0 191 170 0x00000004 [ 363.760085] Call Trace: [ 363.763006] __schedule+0x27d/0x8d0 [ 363.767016] ? mutex_lock+0x12/0x40 [ 363.770943] ? kprobes_module_callback+0x15b/0x1d0 [ 363.780593] schedule+0x36/0x80 [ 363.785119] async_synchronize_cookie_domain+0x91/0x130 [ 363.793021] ? wake_atomic_t_function+0x60/0x60 [ 363.798351] async_synchronize_full+0x17/0x20 [ 363.803405] do_init_module+0xc1/0x1ff [ 363.807564] load_module+0x2313/0x29a0 [ 363.811786] ? __symbol_put+0x40/0x40 [ 363.815895] ? security_kernel_post_read_file+0x6b/0x80 [ 363.821852] SYSC_finit_module+0xbc/0xf0 [ 363.826433] SyS_finit_module+0xe/0x10 [ 363.830732] entry_SYSCALL_64_fastpath+0x1e/0xad [ 363.836311] RIP: 0033:0x7efd37fa1c19 [ 363.842740] RSP: 002b:00007ffd7ceae188 EFLAGS: 00000246 ORIG_RAX: 0000000000000139 [ 363.852003] RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 00007efd37fa1c19 [ 363.860774] RDX: 0000000000000000 RSI: 00007efd38497e2a RDI: 000000000000000c [ 363.869669] RBP: 00007ffd7cead190 R08: 0000000000000000 R09: 0000000000000000 [ 363.878494] R10: 000000000000000c R11: 0000000000000246 R12: 0000555fdf1a3300 [ 363.887931] R13: 00007ffd7cead170 R14: 0000000000000005 R15: 000000000aba9500 [ 484.316121] INFO: task systemd-udevd:183 blocked for more than 120 seconds. [ 484.327141] Not tainted 4.10.0-rc6-next-20170203+ #2 [ 484.333747] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 484.342486] systemd-udevd D 0 183 170 0x00000004 [ 484.348790] Call Trace: [ 484.351712] __schedule+0x27d/0x8d0 [ 484.355904] schedule+0x36/0x80 [ 484.359718] schedule_timeout+0x235/0x3f0 [ 484.364932] ? sched_clock+0x9/0x10 [ 484.368892] ? try_to_wake_up+0x4a/0x460 [ 484.376582] wait_for_completion+0xa5/0x120 [ 484.383779] ? wake_up_q+0x70/0x70 [ 484.389885] flush_work+0x11a/0x1c0 [ 484.394048] ? worker_detach_from_pool+0xb0/0xb0 [ 484.399464] __cancel_work_timer+0xf3/0x1b0 [ 484.404326] ? disk_map_sector_rcu+0x70/0x70 [ 484.409379] cancel_delayed_work_sync+0x13/0x20 [ 484.414449] disk_block_events+0x34/0x40 [ 484.418615] __blkdev_get+0x10c/0x470 [ 484.423391] blkdev_get+0x11a/0x320 [ 484.429312] ? unlock_new_inode+0x49/0x80 [ 484.433618] ? bdget+0x110/0x130 [ 484.437300] blkdev_open+0x5b/0x70 [ 484.441376] do_dentry_open+0x208/0x310 [ 484.446108] ? blkdev_get_by_dev+0x50/0x50 [ 484.450946] vfs_open+0x4c/0x70 [ 484.454693] ? may_open+0x9b/0x100 [ 484.458682] path_openat+0x297/0x13e0 [ 484.462656] ? _copy_to_user+0x2e/0x40 [ 484.467125] ? move_addr_to_user+0xa3/0xc0 [ 484.472370] do_filp_open+0x7e/0xe0 [ 484.479195] ? _cond_resched+0x1a/0x50 [ 484.484027] ? kmem_cache_alloc+0x156/0x1b0 [ 484.488851] ? getname_flags+0x56/0x1f0 [ 484.493049] ? __alloc_fd+0x46/0x170 [ 484.496899] do_sys_open+0x11b/0x1f0 [ 484.500784] SyS_open+0x1e/0x20 [ 484.504284] entry_SYSCALL_64_fastpath+0x1e/0xad [ 484.510767] RIP: 0033:0x7efd3827aca0 [ 484.515460] RSP: 002b:00007ffd7ceaeb38 EFLAGS: 00000246 ORIG_RAX: 0000000000000002 [ 484.527246] RAX: ffffffffffffffda RBX: 0000555fdf1a2d40 RCX: 00007efd3827aca0 [ 484.537307] RDX: 0000555fde106058 RSI: 00000000000a0800 RDI: 0000555fdf1a2ff0 [ 484.545620] RBP: 0000000000000000 R08: 0000000000000073 R09: 0000000000000003 [ 484.554372] R10: 00007efd37fe6520 R11: 0000000000000246 R12: 0000000000000000 [ 484.563267] R13: 0000555fdf1a2d40 R14: 00007ffd7ceaea00 R15: 0000000000000000 [ 484.571966] INFO: task systemd-udevd:191 blocked for more than 120 seconds. [ 484.580711] Not tainted 4.10.0-rc6-next-20170203+ #2 [ 484.589555] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [ 484.598799] systemd-udevd D 0 191 170 0x00000004 [ 484.605231] Call Trace: [ 484.608308] __schedule+0x27d/0x8d0 [ 484.612702] ? mutex_lock+0x12/0x40 [ 484.617071] ? kprobes_module_callback+0x15b/0x1d0 [ 484.621625] schedule+0x36/0x80 [ 484.623511] async_synchronize_cookie_domain+0x91/0x130 [ 484.626443] ? wake_atomic_t_function+0x60/0x60 [ 484.629059] async_synchronize_full+0x17/0x20 [ 484.635723] do_init_module+0xc1/0x1ff [ 484.640226] load_module+0x2313/0x29a0 [ 484.645030] ? __symbol_put+0x40/0x40 [ 484.649870] ? security_kernel_post_read_file+0x6b/0x80 [ 484.658016] SYSC_finit_module+0xbc/0xf0 [ 484.662676] SyS_finit_module+0xe/0x10 [ 484.667374] entry_SYSCALL_64_fastpath+0x1e/0xad [ 484.673822] RIP: 0033:0x7efd37fa1c19 [ 484.677771] RSP: 002b:00007ffd7ceae188 EFLAGS: 00000246 ORIG_RAX: 0000000000000139 [ 484.688668] RAX: ffffffffffffffda RBX: 0000000000000005 RCX: 00007efd37fa1c19 [ 484.697959] RDX: 0000000000000000 RSI: 00007efd38497e2a RDI: 000000000000000c [ 484.707793] RBP: 00007ffd7cead190 R08: 0000000000000000 R09: 0000000000000000 [ 484.716695] R10: 000000000000000c R11: 0000000000000246 R12: 0000555fdf1a3300 [ 484.724415] R13: 00007ffd7cead170 R14: 0000000000000005 R15: 000000000aba9500 -- To unsubscribe from this list: send the line "unsubscribe linux-block" in the body of a message to majordomo@xxxxxxxxxxxxxxx More majordomo info at http://vger.kernel.org/majordomo-info.html
