Return-Path: Received: (majordomo@vger.kernel.org) by vger.kernel.org via listexpand id S1752272AbdG2VRQ (ORCPT ); Sat, 29 Jul 2017 17:17:16 -0400 Received: from vulcan.natalenko.name ([104.207.131.136]:50948 "EHLO vulcan.natalenko.name" rhost-flags-OK-OK-OK-OK) by vger.kernel.org with ESMTP id S1751612AbdG2VRO (ORCPT ); Sat, 29 Jul 2017 17:17:14 -0400 DMARC-Filter: OpenDMARC Filter v1.3.2 vulcan.natalenko.name 9B4532214A5 Authentication-Results: vulcan.natalenko.name; dmarc=fail (p=none dis=none) header.from=natalenko.name From: Oleksandr Natalenko To: Jens Axboe Cc: Christoph Hellwig , linux-block@vger.kernel.org, linux-kernel@vger.kernel.org Subject: Re: blk-mq breaks suspend even with runtime PM patch Date: Sat, 29 Jul 2017 23:17:11 +0200 Message-ID: <6500760.S2hGu5KfKp@natalenko.name> In-Reply-To: <5912148.iRCpNe8Dyb@natalenko.name> References: <5912148.iRCpNe8Dyb@natalenko.name> MIME-Version: 1.0 Content-Type: text/plain; charset="UTF-8" ARC-Message-Signature: i=1; a=rsa-sha256; c=relaxed/relaxed; d=natalenko.name; s=arc-20170712; t=1501363031; h=from:subject:date:message-id:to:cc:mime-version:content-type:content-transfer-encoding:in-reply-to:references; bh=vAp0Jo1vaSWwQf5l84qWGQaVhsyJT03q+CULK5X1JCg=; b=G+VmCfmWUFlFAfIq9ham7Td0q+siXS3kCcQhi+oWDJow+hTEvULKx8A62fJ8//IWx+mZNh QSTLUs+Q1eYiboEuj5Agl5uIVj9kB/0FDh+1/eEEd6LLbCacsdVbvhO63Fo/Gj2SIiS5he v71WNoe55RpZrot6DQujWb3+AhjWzPM= ARC-Seal: i=1; s=arc-20170712; d=natalenko.name; t=1501363031; a=rsa-sha256; cv=none; b=YhY7xUGI4VMGPJfxA/CG/NvioK9VMFsxJRYK3TCXWQrlXJxfV2Owo+AuBXzvkPvzpgUUhXU3zDmMwJURZy5ao0u11L+fs/FvOk1lq3jgFvWARnpSntSlikneyGj7oeKl6Q8n4w/5fs+sCgdIEbF6y8ihysFGQNa0XohjdmfwM/Y= ARC-Authentication-Results: i=1; auth=pass smtp.auth=oleksandr@natalenko.name smtp.mailfrom=oleksandr@natalenko.name Sender: linux-kernel-owner@vger.kernel.org List-ID: X-Mailing-List: linux-kernel@vger.kernel.org Content-Transfer-Encoding: 8bit X-MIME-Autoconverted: from quoted-printable to 8bit by nfs id v6TLHNt7026354 Content-Length: 10175 Lines: 220 Recompiled kernel with lockdep enabled gives me this: === [ 368.655051] Showing all locks held in the system: [ 368.656387] 1 lock held by khungtaskd/37: [ 368.657171] #0: (tasklist_lock){.+.+..}, at: [] debug_show_all_locks+0x3d/0x1a0 [ 368.658725] 1 lock held by md0_raid10/458: [ 368.659455] #0: (&mddev->reconfig_mutex){+.+.+.}, at: [] md_check_recovery+0xaf/0x4d0 [md_mod] [ 368.661403] 3 locks held by btrfs-transacti/550: [ 368.662754] #0: (&fs_info->transaction_kthread_mutex){+.+...}, at: [] transaction_kthread+0x69/0x1c0 [btrfs] [ 368.664797] #1: (&fs_info->reloc_mutex){+.+...}, at: [] btrfs_commit_transaction+0x2e1/0x9b0 [btrfs] [ 368.666669] #2: (&fs_info->tree_log_mutex){+.+...}, at: [] btrfs_commit_transaction+0x351/0x9b0 [btrfs] [ 368.668644] 4 locks held by kworker/0:2/888: [ 368.669384] #0: ("events"){.+.+.+}, at: [] process_one_work+0x1fb/0x6e0 [ 368.670916] #1: ((shepherd).work){+.+...}, at: [] process_one_work+0x1fb/0x6e0 [ 368.672592] #2: (cpu_hotplug.dep_map){++++++}, at: [] get_online_cpus.part.14+0x5/0x50 [ 368.674742] #3: (cpu_hotplug.lock){+.+.+.}, at: [] get_online_cpus.part.14+0x3a/0x50 [ 368.677494] 10 locks held by systemd-sleep/889: [ 368.678650] #0: (sb_writers#5){.+.+.+}, at: [] vfs_write+0x17b/0x1a0 [ 368.680483] #1: (&of->mutex){+.+.+.}, at: [] kernfs_fop_write+0x123/0x1e0 [ 368.682412] #2: (s_active#257){.+.+.+}, at: [] kernfs_fop_write+0x12c/0x1e0 [ 368.684440] #3: (autosleep_lock){+.+.+.}, at: [] pm_autosleep_lock+0x17/0x20 [ 368.686707] #4: (pm_mutex){+.+.+.}, at: [] pm_suspend +0x88/0x490 [ 368.688086] #5: (acpi_scan_lock){+.+.+.}, at: [] acpi_scan_lock_acquire+0x17/0x20 [ 368.690213] #6: (cpu_add_remove_lock){+.+.+.}, at: [] freeze_secondary_cpus+0x30/0x3c0 [ 368.692016] #7: (cpu_hotplug.dep_map){++++++}, at: [] cpu_hotplug_begin+0x5/0xe0 [ 368.694347] #8: (cpu_hotplug.lock){+.+.+.}, at: [] cpu_hotplug_begin+0x83/0xe0 [ 368.696010] #9: (all_q_mutex){+.+...}, at: [] blk_mq_queue_reinit_work+0x1a/0x110 [ 368.698624] [ 368.698990] ============================================= [ 368.698990] === Deadlock with CPU hotplug? On sobota 29. července 2017 17:27:41 CEST Oleksandr Natalenko wrote: > Hello Jens, Christoph. > > Unfortunately, even with "block: disable runtime-pm for blk-mq" patch > applied blk-mq breaks suspend to RAM for me. It is reproducible on my > laptop as well as in a VM. > > I use complex disk layout involving MD, LUKS and LVM, and managed to get > these warnings from VM via serial console when suspend fails: > > === > [ 245.516573] INFO: task kworker/0:1:49 blocked for more than 120 seconds. > [ 245.520025] Not tainted 4.12.0-pf4 #1 > [ 245.521836] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > this message. > [ 245.525612] kworker/0:1 D 0 49 2 0x00000000 > [ 245.527515] Workqueue: events vmstat_shepherd > [ 245.528685] Call Trace: > [ 245.529296] __schedule+0x459/0xe40 > [ 245.530115] ? kvm_clock_read+0x25/0x40 > [ 245.531003] ? ktime_get+0x40/0xa0 > [ 245.531819] schedule+0x3d/0xb0 > [ 245.532542] ? schedule+0x3d/0xb0 > [ 245.533299] schedule_preempt_disabled+0x15/0x20 > [ 245.534367] __mutex_lock.isra.5+0x295/0x530 > [ 245.535351] __mutex_lock_slowpath+0x13/0x20 > [ 245.536362] ? __mutex_lock_slowpath+0x13/0x20 > [ 245.537334] mutex_lock+0x25/0x30 > [ 245.538118] get_online_cpus.part.14+0x15/0x30 > [ 245.539588] get_online_cpus+0x20/0x30 > [ 245.540560] vmstat_shepherd+0x21/0xc0 > [ 245.541538] process_one_work+0x1de/0x430 > [ 245.542364] worker_thread+0x47/0x3f0 > [ 245.543042] kthread+0x125/0x140 > [ 245.543649] ? process_one_work+0x430/0x430 > [ 245.544417] ? kthread_create_on_node+0x70/0x70 > [ 245.545737] ret_from_fork+0x25/0x30 > [ 245.546490] INFO: task md0_raid10:459 blocked for more than 120 seconds. > [ 245.547668] Not tainted 4.12.0-pf4 #1 > [ 245.548769] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > this message. > [ 245.550133] md0_raid10 D 0 459 2 0x00000000 > [ 245.551092] Call Trace: > [ 245.551539] __schedule+0x459/0xe40 > [ 245.552163] schedule+0x3d/0xb0 > [ 245.552728] ? schedule+0x3d/0xb0 > [ 245.553344] md_super_wait+0x6e/0xa0 [md_mod] > [ 245.554118] ? wake_bit_function+0x60/0x60 > [ 245.554854] md_update_sb.part.60+0x3df/0x840 [md_mod] > [ 245.555771] md_check_recovery+0x215/0x4b0 [md_mod] > [ 245.556732] raid10d+0x62/0x13c0 [raid10] > [ 245.557456] ? schedule+0x3d/0xb0 > [ 245.558169] ? schedule+0x3d/0xb0 > [ 245.558803] ? schedule_timeout+0x21f/0x330 > [ 245.559593] md_thread+0x120/0x160 [md_mod] > [ 245.560380] ? md_thread+0x120/0x160 [md_mod] > [ 245.561202] ? wake_bit_function+0x60/0x60 > [ 245.561975] kthread+0x125/0x140 > [ 245.562601] ? find_pers+0x70/0x70 [md_mod] > [ 245.563394] ? kthread_create_on_node+0x70/0x70 > [ 245.564516] ret_from_fork+0x25/0x30 > [ 245.565669] INFO: task dmcrypt_write:487 blocked for more than 120 > seconds. [ 245.567151] Not tainted 4.12.0-pf4 #1 > [ 245.567946] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > this message. > [ 245.569390] dmcrypt_write D 0 487 2 0x00000000 > [ 245.570352] Call Trace: > [ 245.570801] __schedule+0x459/0xe40 > [ 245.571601] ? preempt_schedule_common+0x1f/0x30 > [ 245.572421] ? ___preempt_schedule+0x16/0x18 > [ 245.573168] schedule+0x3d/0xb0 > [ 245.573733] ? schedule+0x3d/0xb0 > [ 245.574378] md_write_start+0xe3/0x270 [md_mod] > [ 245.575180] ? wake_bit_function+0x60/0x60 > [ 245.575915] raid10_make_request+0x3f/0x140 [raid10] > [ 245.576827] md_make_request+0xa9/0x2a0 [md_mod] > [ 245.577659] generic_make_request+0x11e/0x2f0 > [ 245.578464] dmcrypt_write+0x22d/0x250 [dm_crypt] > [ 245.579288] ? dmcrypt_write+0x22d/0x250 [dm_crypt] > [ 245.580183] ? wake_up_process+0x20/0x20 > [ 245.580875] kthread+0x125/0x140 > [ 245.581455] ? kthread+0x125/0x140 > [ 245.582064] ? crypt_iv_essiv_dtr+0x70/0x70 [dm_crypt] > [ 245.582971] ? kthread_create_on_node+0x70/0x70 > [ 245.583772] ret_from_fork+0x25/0x30 > [ 245.584424] INFO: task btrfs-transacti:553 blocked for more than 120 > seconds. > [ 245.585830] Not tainted 4.12.0-pf4 #1 > [ 245.586596] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > this message. > [ 245.587947] btrfs-transacti D 0 553 2 0x00000000 > [ 245.588922] Call Trace: > [ 245.589377] __schedule+0x459/0xe40 > [ 245.590062] ? btrfs_submit_bio_hook+0x8c/0x180 [btrfs] > [ 245.590976] schedule+0x3d/0xb0 > [ 245.591538] ? schedule+0x3d/0xb0 > [ 245.592175] io_schedule+0x16/0x40 > [ 245.592794] wait_on_page_bit_common+0xe3/0x180 > [ 245.593589] ? page_cache_tree_insert+0xc0/0xc0 > [ 245.594387] __filemap_fdatawait_range+0x12a/0x1a0 > [ 245.595229] filemap_fdatawait_range+0x14/0x30 > [ 245.596033] btrfs_wait_ordered_range+0x6b/0x110 [btrfs] > [ 245.596998] ? _raw_spin_unlock+0x10/0x30 > [ 245.597735] __btrfs_wait_cache_io+0x45/0x1c0 [btrfs] > [ 245.599091] btrfs_wait_cache_io+0x2c/0x30 [btrfs] > [ 245.600789] btrfs_write_dirty_block_groups+0x206/0x390 [btrfs] > [ 245.602068] commit_cowonly_roots+0x221/0x2c0 [btrfs] > [ 245.602981] btrfs_commit_transaction+0x3c4/0x900 [btrfs] > [ 245.603940] transaction_kthread+0x190/0x1c0 [btrfs] > [ 245.604806] kthread+0x125/0x140 > [ 245.605398] ? btrfs_cleanup_transaction+0x500/0x500 [btrfs] > [ 245.606414] ? kthread_create_on_node+0x70/0x70 > [ 245.607213] ret_from_fork+0x25/0x30 > [ 245.607846] INFO: task systemd-sleep:677 blocked for more than 120 > seconds. [ 245.609061] Not tainted 4.12.0-pf4 #1 > [ 245.609858] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables > this message. > [ 245.611202] systemd-sleep D 0 677 1 0x00000000 > [ 245.612160] Call Trace: > [ 245.612604] __schedule+0x459/0xe40 > [ 245.613231] ? blk_mq_queue_reinit_work+0x100/0x100 > [ 245.614080] schedule+0x3d/0xb0 > [ 245.614637] ? schedule+0x3d/0xb0 > [ 245.615222] blk_mq_freeze_queue_wait+0x46/0xb0 > [ 245.616015] ? wake_bit_function+0x60/0x60 > [ 245.616778] blk_mq_queue_reinit_work+0x6e/0x100 > [ 245.617592] blk_mq_queue_reinit_dead+0x3d/0x50 > [ 245.618420] ? __flow_cache_shrink+0x170/0x170 > [ 245.619199] cpuhp_invoke_callback+0x84/0x430 > [ 245.619965] ? cpuhp_invoke_callback+0x84/0x430 > [ 245.620754] ? __flow_cache_shrink+0x170/0x170 > [ 245.621530] cpuhp_down_callbacks+0x42/0x80 > [ 245.622267] _cpu_down+0xc5/0x100 > [ 245.622856] freeze_secondary_cpus+0x9e/0x230 > [ 245.623629] suspend_devices_and_enter+0x2e6/0x800 > [ 245.624471] pm_suspend+0x349/0x3c0 > [ 245.625090] state_store+0x49/0xa0 > [ 245.625699] kobj_attr_store+0xf/0x20 > [ 245.626379] sysfs_kf_write+0x37/0x40 > [ 245.627038] kernfs_fop_write+0x11c/0x1a0 > [ 245.627800] __vfs_write+0x37/0x140 > [ 245.628448] ? handle_mm_fault+0xde/0x220 > [ 245.629155] vfs_write+0xb1/0x1a0 > [ 245.629745] SyS_write+0x55/0xc0 > [ 245.630337] ? trace_do_page_fault+0x37/0xf0 > [ 245.631088] entry_SYSCALL_64_fastpath+0x1a/0xa5 > [ 245.632109] RIP: 0033:0x7f810459dbf0 > [ 245.632821] RSP: 002b:00007ffec9ba2e58 EFLAGS: 00000246 ORIG_RAX: > 0000000000000001 > [ 245.634127] RAX: ffffffffffffffda RBX: 00000000000000c6 RCX: > 00007f810459dbf0 > [ 245.635353] RDX: 0000000000000004 RSI: 000000b716c73390 RDI: > 0000000000000004 > [ 245.636778] RBP: 000000000000270f R08: 000000b716c73240 R09: > 00007f8104a718c0 > [ 245.638254] R10: 00007f810485ead8 R11: 0000000000000246 R12: > 00007f810485ead8 > [ 245.639500] R13: 0000000000001010 R14: 000000b716c73380 R15: > 00007f810485ea80 > === > > With blk-mq disabled everything works okay. > > How can I help you in solving this issue?