* [PATCH] Btrfs: adjust len of writes if following a preallocated extent
@ 2016-11-04 19:20 Liu Bo
2016-11-22 19:59 ` Chris Mason
` (2 more replies)
0 siblings, 3 replies; 11+ messages in thread
From: Liu Bo @ 2016-11-04 19:20 UTC (permalink / raw)
To: linux-btrfs; +Cc: David Sterba
If we have
|0--hole--4095||4096--preallocate--12287|
instead of using preallocated space, a 8K direct write will just
create a new 8K extent and it'll end up with
|0--new extent--8191||8192--preallocate--12287|
It's because we find a hole em and then go to create a new 8K
extent directly without adjusting @len.
Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
---
fs/btrfs/inode.c | 8 +++++---
1 file changed, 5 insertions(+), 3 deletions(-)
diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
index 2b790bd..48e9356 100644
--- a/fs/btrfs/inode.c
+++ b/fs/btrfs/inode.c
@@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
}
/*
- * this will cow the extent, reset the len in case we changed
- * it above
+ * this will cow the extent, if em is within [start, len], then
+ * probably we've found a preallocated/existing extent, let's
+ * give it a chance to use preallocated space.
*/
- len = bh_result->b_size;
+ len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
+ len = ALIGN(len, root->sectorsize);
free_extent_map(em);
em = btrfs_new_extent_direct(inode, start, len);
if (IS_ERR(em)) {
--
2.5.5
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: [PATCH] Btrfs: adjust len of writes if following a preallocated extent
2016-11-04 19:20 [PATCH] Btrfs: adjust len of writes if following a preallocated extent Liu Bo
@ 2016-11-22 19:59 ` Chris Mason
2016-11-23 15:54 ` NOC - Profihost AG
2016-11-23 17:21 ` resend: " Stefan Priebe - Profihost AG
2 siblings, 0 replies; 11+ messages in thread
From: Chris Mason @ 2016-11-22 19:59 UTC (permalink / raw)
To: Liu Bo, linux-btrfs; +Cc: David Sterba
On 11/04/2016 03:20 PM, Liu Bo wrote:
> If we have
>
> |0--hole--4095||4096--preallocate--12287|
>
> instead of using preallocated space, a 8K direct write will just
> create a new 8K extent and it'll end up with
>
> |0--new extent--8191||8192--preallocate--12287|
>
> It's because we find a hole em and then go to create a new 8K
> extent directly without adjusting @len.
>
> Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
Reviewed-by: Chris Mason <clm@fb.com>
-chris
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-04 19:20 [PATCH] Btrfs: adjust len of writes if following a preallocated extent Liu Bo
2016-11-22 19:59 ` Chris Mason
@ 2016-11-23 15:54 ` NOC - Profihost AG
2016-11-23 17:21 ` resend: " Stefan Priebe - Profihost AG
2 siblings, 0 replies; 11+ messages in thread
From: NOC - Profihost AG @ 2016-11-23 15:54 UTC (permalink / raw)
To: Liu Bo, linux-btrfs; +Cc: David Sterba
Hi,
Am 04.11.2016 um 20:20 schrieb Liu Bo:
> If we have
>
> |0--hole--4095||4096--preallocate--12287|
>
> instead of using preallocated space, a 8K direct write will just
> create a new 8K extent and it'll end up with
>
> |0--new extent--8191||8192--preallocate--12287|
>
> It's because we find a hole em and then go to create a new 8K
> extent directly without adjusting @len.
after applying that one on top of my 4.4 btrfs branch (includes patches
up to 4.10 / next). i'm getting deadlocks in btrfs.
Traces here:
INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
[<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
[<ffffffff810a0cbb>] kthread+0xdb/0x100
[<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
Leftover inexact backtrace:
[<ffffffff810a0be0>] ? kthread_park+0x60/0x60
INFO: task mysqld:1977 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
[<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
[<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3249 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881475fdfa40 0 3249 1 0x00080000
ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b4cb7>]
wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
[<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
[<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
[<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
[<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
[<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3250 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881374edb868 0 3250 1 0x00080000
ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
[<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
Leftover inexact backtrace:
[<ffffffff816aa5a7>] ? down_read+0x17/0x20
[<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
[<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
[<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
[<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
[<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
[<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
[<ffffffff810f73c1>] ? futex_wake+0x81/0x150
[<ffffffff811cedd4>] new_sync_write+0x84/0xb0
[<ffffffff811cee26>] __vfs_write+0x26/0x40
[<ffffffff811cf419>] vfs_write+0xa9/0x190
[<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
[<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
[<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
[<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
[<ffffffff810a0cbb>] kthread+0xdb/0x100
[<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
Leftover inexact backtrace:
[<ffffffff810a0be0>] ? kthread_park+0x60/0x60
INFO: task mysqld:1977 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
[<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
[<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3249 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881475fdfa40 0 3249 1 0x00080000
ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b4cb7>]
wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
[<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
[<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
[<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
[<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
[<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3250 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881374edb868 0 3250 1 0x00080000
ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
[<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
Leftover inexact backtrace:
[<ffffffff816aa5a7>] ? down_read+0x17/0x20
[<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
[<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
[<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
[<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
[<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
[<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
[<ffffffff810f73c1>] ? futex_wake+0x81/0x150
[<ffffffff811cedd4>] new_sync_write+0x84/0xb0
[<ffffffff811cee26>] __vfs_write+0x26/0x40
[<ffffffff811cf419>] vfs_write+0xa9/0x190
[<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
[<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
[<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
[<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
[<ffffffff810a0cbb>] kthread+0xdb/0x100
[<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
Leftover inexact backtrace:
[<ffffffff810a0be0>] ? kthread_park+0x60/0x60
INFO: task mysqld:1977 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
[<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
[<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
Greets,
Stefan
>
> Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> Reviewed-by: Chris Mason <clm@fb.com>
> ---
> fs/btrfs/inode.c | 8 +++++---
> 1 file changed, 5 insertions(+), 3 deletions(-)
>
> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> index 2b790bd..48e9356 100644
> --- a/fs/btrfs/inode.c
> +++ b/fs/btrfs/inode.c
> @@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
> }
>
> /*
> - * this will cow the extent, reset the len in case we changed
> - * it above
> + * this will cow the extent, if em is within [start, len], then
> + * probably we've found a preallocated/existing extent, let's
> + * give it a chance to use preallocated space.
> */
> - len = bh_result->b_size;
> + len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
> + len = ALIGN(len, root->sectorsize);
> free_extent_map(em);
> em = btrfs_new_extent_direct(inode, start, len);
> if (IS_ERR(em)) {
>
--
Mit freundlichen Grüßen
Stefan Priebe
Ihr Profihost Team
-------------------------------
Profihost AG
Expo Plaza 1
30539 Hannover
Deutschland
Tel.: +49 (511) 5151 8181 | Fax.: +49 (511) 5151 8282
URL: http://www.profihost.com | E-Mail: info@profihost.com
Sitz der Gesellschaft: Hannover, USt-IdNr. DE813460827
Registergericht: Amtsgericht Hannover, Register-Nr.: HRB 202350
Vorstand: Cristoph Bluhm, Sebastian Bluhm, Stefan Priebe
Aufsichtsrat: Prof. Dr. iur. Winfried Huck (Vorsitzender)
^ permalink raw reply [flat|nested] 11+ messages in thread
* resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-04 19:20 [PATCH] Btrfs: adjust len of writes if following a preallocated extent Liu Bo
2016-11-22 19:59 ` Chris Mason
2016-11-23 15:54 ` NOC - Profihost AG
@ 2016-11-23 17:21 ` Stefan Priebe - Profihost AG
2016-11-23 18:23 ` Holger Hoffstätte
2016-11-23 21:22 ` Liu Bo
2 siblings, 2 replies; 11+ messages in thread
From: Stefan Priebe - Profihost AG @ 2016-11-23 17:21 UTC (permalink / raw)
To: Liu Bo, linux-btrfs; +Cc: David Sterba
Hi,
sorry last mail was from the wrong box.
Am 04.11.2016 um 20:20 schrieb Liu Bo:
> If we have
>
> |0--hole--4095||4096--preallocate--12287|
>
> instead of using preallocated space, a 8K direct write will just
> create a new 8K extent and it'll end up with
>
> |0--new extent--8191||8192--preallocate--12287|
>
> It's because we find a hole em and then go to create a new 8K
> extent directly without adjusting @len.
after applying that one on top of my 4.4 btrfs branch (includes patches
up to 4.10 / next). i'm getting deadlocks in btrfs.
Traces here:
INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
[<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
[<ffffffff810a0cbb>] kthread+0xdb/0x100
[<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
Leftover inexact backtrace:
[<ffffffff810a0be0>] ? kthread_park+0x60/0x60
INFO: task mysqld:1977 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
[<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
[<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3249 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881475fdfa40 0 3249 1 0x00080000
ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b4cb7>]
wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
[<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
[<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
[<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
[<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
[<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3250 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881374edb868 0 3250 1 0x00080000
ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
[<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
Leftover inexact backtrace:
[<ffffffff816aa5a7>] ? down_read+0x17/0x20
[<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
[<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
[<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
[<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
[<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
[<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
[<ffffffff810f73c1>] ? futex_wake+0x81/0x150
[<ffffffff811cedd4>] new_sync_write+0x84/0xb0
[<ffffffff811cee26>] __vfs_write+0x26/0x40
[<ffffffff811cf419>] vfs_write+0xa9/0x190
[<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
[<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
[<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
[<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
[<ffffffff810a0cbb>] kthread+0xdb/0x100
[<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
Leftover inexact backtrace:
[<ffffffff810a0be0>] ? kthread_park+0x60/0x60
INFO: task mysqld:1977 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
[<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
[<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3249 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881475fdfa40 0 3249 1 0x00080000
ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b4cb7>]
wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
[<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
[<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
[<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
[<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
[<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
INFO: task mysqld:3250 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff881374edb868 0 3250 1 0x00080000
ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
[<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
Leftover inexact backtrace:
[<ffffffff816aa5a7>] ? down_read+0x17/0x20
[<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
[<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
[<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
[<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
[<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
[<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
[<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
[<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
[<ffffffff810f73c1>] ? futex_wake+0x81/0x150
[<ffffffff811cedd4>] new_sync_write+0x84/0xb0
[<ffffffff811cee26>] __vfs_write+0x26/0x40
[<ffffffff811cf419>] vfs_write+0xa9/0x190
[<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
[<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
[<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
[<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
[<ffffffff810a0cbb>] kthread+0xdb/0x100
[<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
Leftover inexact backtrace:
[<ffffffff810a0be0>] ? kthread_park+0x60/0x60
INFO: task mysqld:1977 blocked for more than 120 seconds.
Not tainted 4.4.34 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
Call Trace:
[<ffffffff816a8425>] schedule+0x35/0x80
[<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
[<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
[<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
[<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
[<ffffffff8120062d>] do_fsync+0x3d/0x70
[<ffffffff812008a0>] SyS_fsync+0x10/0x20
[<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
Leftover inexact backtrace:
Greets,
Stefan
>
> Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> Reviewed-by: Chris Mason <clm@fb.com>
> ---
> fs/btrfs/inode.c | 8 +++++---
> 1 file changed, 5 insertions(+), 3 deletions(-)
>
> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> index 2b790bd..48e9356 100644
> --- a/fs/btrfs/inode.c
> +++ b/fs/btrfs/inode.c
> @@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
> }
>
> /*
> - * this will cow the extent, reset the len in case we changed
> - * it above
> + * this will cow the extent, if em is within [start, len], then
> + * probably we've found a preallocated/existing extent, let's
> + * give it a chance to use preallocated space.
> */
> - len = bh_result->b_size;
> + len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
> + len = ALIGN(len, root->sectorsize);
> free_extent_map(em);
> em = btrfs_new_extent_direct(inode, start, len);
> if (IS_ERR(em)) {
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-23 17:21 ` resend: " Stefan Priebe - Profihost AG
@ 2016-11-23 18:23 ` Holger Hoffstätte
2016-11-23 18:58 ` Stefan Priebe - Profihost AG
2016-11-23 21:22 ` Liu Bo
1 sibling, 1 reply; 11+ messages in thread
From: Holger Hoffstätte @ 2016-11-23 18:23 UTC (permalink / raw)
To: Stefan Priebe - Profihost AG, Liu Bo, linux-btrfs; +Cc: David Sterba
On 11/23/16 18:21, Stefan Priebe - Profihost AG wrote:
> Am 04.11.2016 um 20:20 schrieb Liu Bo:
>> If we have
>>
>> |0--hole--4095||4096--preallocate--12287|
>>
>> instead of using preallocated space, a 8K direct write will just
>> create a new 8K extent and it'll end up with
>>
>> |0--new extent--8191||8192--preallocate--12287|
>>
>> It's because we find a hole em and then go to create a new 8K
>> extent directly without adjusting @len.
>
> after applying that one on top of my 4.4 btrfs branch (includes patches
> up to 4.10 / next). i'm getting deadlocks in btrfs.
*ctrl+f sectorsize* ..
That's not surprising if you did what I suspect. If your tree is based
on my - now really very retired - 4.4.x queue, then you are likely missing
_all the other blocksize/sectorsize patches_ that came in from Chandra
Seetharaman et al., which I _really_ carefully patched around, for many
good reasons.
-h
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-23 18:23 ` Holger Hoffstätte
@ 2016-11-23 18:58 ` Stefan Priebe - Profihost AG
0 siblings, 0 replies; 11+ messages in thread
From: Stefan Priebe - Profihost AG @ 2016-11-23 18:58 UTC (permalink / raw)
To: Holger Hoffstätte, Liu Bo, linux-btrfs; +Cc: David Sterba
Am 23.11.2016 um 19:23 schrieb Holger Hoffstätte:
> On 11/23/16 18:21, Stefan Priebe - Profihost AG wrote:
>> Am 04.11.2016 um 20:20 schrieb Liu Bo:
>>> If we have
>>>
>>> |0--hole--4095||4096--preallocate--12287|
>>>
>>> instead of using preallocated space, a 8K direct write will just
>>> create a new 8K extent and it'll end up with
>>>
>>> |0--new extent--8191||8192--preallocate--12287|
>>>
>>> It's because we find a hole em and then go to create a new 8K
>>> extent directly without adjusting @len.
>>
>> after applying that one on top of my 4.4 btrfs branch (includes patches
>> up to 4.10 / next). i'm getting deadlocks in btrfs.
>
> *ctrl+f sectorsize* ..
>
> That's not surprising if you did what I suspect. If your tree is based
> on my - now really very retired - 4.4.x queue, then you are likely missing
> _all the other blocksize/sectorsize patches_ that came in from Chandra
> Seetharaman et al., which I _really_ carefully patched around, for many
> good reasons.
*arg* that makes sense. Still not easy to find out which ones to skip.
Yes that one is based on yours.
thanks,
Stefan
>
> -h
>
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-23 17:21 ` resend: " Stefan Priebe - Profihost AG
2016-11-23 18:23 ` Holger Hoffstätte
@ 2016-11-23 21:22 ` Liu Bo
2016-11-24 11:13 ` Filipe Manana
1 sibling, 1 reply; 11+ messages in thread
From: Liu Bo @ 2016-11-23 21:22 UTC (permalink / raw)
To: Stefan Priebe - Profihost AG
Cc: linux-btrfs, David Sterba, Filipe David Borba Manana
Hi,
On Wed, Nov 23, 2016 at 06:21:35PM +0100, Stefan Priebe - Profihost AG wrote:
> Hi,
>
> sorry last mail was from the wrong box.
>
> Am 04.11.2016 um 20:20 schrieb Liu Bo:
> > If we have
> >
> > |0--hole--4095||4096--preallocate--12287|
> >
> > instead of using preallocated space, a 8K direct write will just
> > create a new 8K extent and it'll end up with
> >
> > |0--new extent--8191||8192--preallocate--12287|
> >
> > It's because we find a hole em and then go to create a new 8K
> > extent directly without adjusting @len.
>
> after applying that one on top of my 4.4 btrfs branch (includes patches
> up to 4.10 / next). i'm getting deadlocks in btrfs.
This is really interesting, thanks for the quick testing.
After going through the stacks listed below, I think the patch has
exposed a bug around BTRFS_I(inode)->dio_sem:
1. Since fsync has acquired inode_lock(), the dio write must be
an overwrite within EOF.
2. Lets say the inode size is 16k and it already has a preallocated extent [4k, 8k],
then we feed it with a dio write against [0k, 8k], with this patch
applied, the write can be splitted into a new extent of [0, 4k] and a
fill-write against the preallocated one [4k, 8k],
3.
dio fsync
->btrfs_direct_IO btrfs_sync_file
->do_direct_IO
->get_more_blocks() ->inode_lock()
->btrfs_get_blocks_direct() # for [0, 8k] ->btrfs_log_inode()
->btrfs_new_direct_extent() ->btrfs_log_changed_extents()
->btrfs_create_dio_extent()
->down_read(&BTRFS_I(inode)->dio_sem)
# dio write is splitted and
# em of [0, 4k] is inserted as well as
# the ordered extent.
->up_read(&BTRFS_I(inode)->dio_sem)
# do_direct_IO tries to collect more pages
# before sending them down, so [0, 4k] is not
# yet submitted.
--------------------------------------------------------------------------------------------------------
->down_write(&BTRFS_I(inode)->dio_sem)
# found ordered extent of [0, 4k]
# wait for [0, 4k] to finish
->get_more_blocks()
->btrfs_get_blocks_direct() # for [4k, 8k]
->btrfs_create_dio_extent()
-> up_read(&BTRFS_I(inode)->dio_sem)
# deadlock occurs
4. _Without_ this patch, we could hit the deadlock as well under space pressure,
i.e. if we request [0, 8k], but btrfs_reserve_extent() returns only [0, 4k].
(Filipe may correct me, cc'd Filipe.)
Thanks,
-liubo
>
> Traces here:
> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
> [<ffffffff810a0cbb>] kthread+0xdb/0x100
> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>
> Leftover inexact backtrace:
>
> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
> INFO: task mysqld:1977 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>
> Leftover inexact backtrace:
>
> INFO: task mysqld:3249 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03b4cb7>]
> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>
> Leftover inexact backtrace:
>
> INFO: task mysqld:3250 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff881374edb868 0 3250 1 0x00080000
> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
>
> Leftover inexact backtrace:
>
> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
> [<ffffffff811cee26>] __vfs_write+0x26/0x40
> [<ffffffff811cf419>] vfs_write+0xa9/0x190
> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
> [<ffffffff810a0cbb>] kthread+0xdb/0x100
> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>
> Leftover inexact backtrace:
>
> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
> INFO: task mysqld:1977 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>
> Leftover inexact backtrace:
>
> INFO: task mysqld:3249 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03b4cb7>]
> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>
> Leftover inexact backtrace:
>
> INFO: task mysqld:3250 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff881374edb868 0 3250 1 0x00080000
> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
>
> Leftover inexact backtrace:
>
> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
> [<ffffffff811cee26>] __vfs_write+0x26/0x40
> [<ffffffff811cf419>] vfs_write+0xa9/0x190
> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
> [<ffffffff810a0cbb>] kthread+0xdb/0x100
> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>
> Leftover inexact backtrace:
>
> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
> INFO: task mysqld:1977 blocked for more than 120 seconds.
> Not tainted 4.4.34 #1
> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
> Call Trace:
> [<ffffffff816a8425>] schedule+0x35/0x80
> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>
> Leftover inexact backtrace:
>
> Greets,
> Stefan
>
> >
> > Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> > Reviewed-by: Chris Mason <clm@fb.com>
> > ---
> > fs/btrfs/inode.c | 8 +++++---
> > 1 file changed, 5 insertions(+), 3 deletions(-)
> >
> > diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> > index 2b790bd..48e9356 100644
> > --- a/fs/btrfs/inode.c
> > +++ b/fs/btrfs/inode.c
> > @@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
> > }
> >
> > /*
> > - * this will cow the extent, reset the len in case we changed
> > - * it above
> > + * this will cow the extent, if em is within [start, len], then
> > + * probably we've found a preallocated/existing extent, let's
> > + * give it a chance to use preallocated space.
> > */
> > - len = bh_result->b_size;
> > + len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
> > + len = ALIGN(len, root->sectorsize);
> > free_extent_map(em);
> > em = btrfs_new_extent_direct(inode, start, len);
> > if (IS_ERR(em)) {
> >
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-23 21:22 ` Liu Bo
@ 2016-11-24 11:13 ` Filipe Manana
2016-12-02 1:41 ` Liu Bo
0 siblings, 1 reply; 11+ messages in thread
From: Filipe Manana @ 2016-11-24 11:13 UTC (permalink / raw)
To: Liu Bo
Cc: Stefan Priebe - Profihost AG, linux-btrfs@vger.kernel.org,
David Sterba, Josef Bacik
On Wed, Nov 23, 2016 at 9:22 PM, Liu Bo <bo.li.liu@oracle.com> wrote:
> Hi,
>
> On Wed, Nov 23, 2016 at 06:21:35PM +0100, Stefan Priebe - Profihost AG wrote:
>> Hi,
>>
>> sorry last mail was from the wrong box.
>>
>> Am 04.11.2016 um 20:20 schrieb Liu Bo:
>> > If we have
>> >
>> > |0--hole--4095||4096--preallocate--12287|
>> >
>> > instead of using preallocated space, a 8K direct write will just
>> > create a new 8K extent and it'll end up with
>> >
>> > |0--new extent--8191||8192--preallocate--12287|
>> >
>> > It's because we find a hole em and then go to create a new 8K
>> > extent directly without adjusting @len.
>>
>> after applying that one on top of my 4.4 btrfs branch (includes patches
>> up to 4.10 / next). i'm getting deadlocks in btrfs.
>
> This is really interesting, thanks for the quick testing.
>
> After going through the stacks listed below, I think the patch has
> exposed a bug around BTRFS_I(inode)->dio_sem:
>
> 1. Since fsync has acquired inode_lock(), the dio write must be
> an overwrite within EOF.
>
> 2. Lets say the inode size is 16k and it already has a preallocated extent [4k, 8k],
> then we feed it with a dio write against [0k, 8k], with this patch
> applied, the write can be splitted into a new extent of [0, 4k] and a
> fill-write against the preallocated one [4k, 8k],
>
> 3.
> dio fsync
> ->btrfs_direct_IO btrfs_sync_file
> ->do_direct_IO
> ->get_more_blocks() ->inode_lock()
> ->btrfs_get_blocks_direct() # for [0, 8k] ->btrfs_log_inode()
> ->btrfs_new_direct_extent() ->btrfs_log_changed_extents()
> ->btrfs_create_dio_extent()
> ->down_read(&BTRFS_I(inode)->dio_sem)
> # dio write is splitted and
> # em of [0, 4k] is inserted as well as
> # the ordered extent.
> ->up_read(&BTRFS_I(inode)->dio_sem)
> # do_direct_IO tries to collect more pages
> # before sending them down, so [0, 4k] is not
> # yet submitted.
> --------------------------------------------------------------------------------------------------------
> ->down_write(&BTRFS_I(inode)->dio_sem)
> # found ordered extent of [0, 4k]
> # wait for [0, 4k] to finish
> ->get_more_blocks()
> ->btrfs_get_blocks_direct() # for [4k, 8k]
> ->btrfs_create_dio_extent()
> -> up_read(&BTRFS_I(inode)->dio_sem)
> # deadlock occurs
>
> 4. _Without_ this patch, we could hit the deadlock as well under space pressure,
> i.e. if we request [0, 8k], but btrfs_reserve_extent() returns only [0, 4k].
>
> (Filipe may correct me, cc'd Filipe.)
The analysis is correct Bo.
Originally to fix races between fsync and direct IO writes there was a
solution [1, 2] that didn't involve adding a semaphore and relied on
creating first the ordered extents and then the extent maps only in
the direct IO write path (we do things in the reverse order everywhere
else). It worked and was documented in comments but wasn't
particularly elegant and Josef was not happy because of that, so then
we added the semaphore and made direct IO write path create the extent
maps and ordered extents in the same order as everywhere else [3].
So here I can only see 2 simple solutions. Either revert [3] (which
added the semaphore) or acquire the semaphore at a higher level in
direct IO write path like this:
diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
index 1f980ef..b2c277d 100644
--- a/fs/btrfs/inode.c
+++ b/fs/btrfs/inode.c
@@ -7237,7 +7237,6 @@ static struct extent_map
*btrfs_create_dio_extent(struct inode *inode,
struct extent_map *em = NULL;
int ret;
- down_read(&BTRFS_I(inode)->dio_sem);
if (type != BTRFS_ORDERED_NOCOW) {
em = create_pinned_em(inode, start, len, orig_start,
block_start, block_len, orig_block_len,
@@ -7256,8 +7255,6 @@ static struct extent_map
*btrfs_create_dio_extent(struct inode *inode,
em = ERR_PTR(ret);
}
out:
- up_read(&BTRFS_I(inode)->dio_sem);
-
return em;
}
@@ -8715,11 +8712,14 @@ static ssize_t btrfs_direct_IO(struct kiocb
*iocb, struct iov_iter *iter)
wakeup = false;
}
+ if (iov_iter_rw(iter) == WRITE)
+ down_read(&BTRFS_I(inode)->dio_sem);
ret = __blockdev_direct_IO(iocb, inode,
BTRFS_I(inode)->root->fs_info->fs_devices->latest_bdev,
iter, btrfs_get_blocks_direct, NULL,
btrfs_submit_direct, flags);
if (iov_iter_rw(iter) == WRITE) {
+ up_read(&BTRFS_I(inode)->dio_sem);
current->journal_info = NULL;
if (ret < 0 && ret != -EIOCBQUEUED) {
if (dio_data.reserve)
Let me know what you think. Thanks.
[1] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=de0ee0edb21fbab4c7afa3e94573ecfebfb0244e
[2] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=0b901916a00bc7b14ee83cc8e41c3b0d561a8f22
[3] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=5f9a8a51d8b95505d8de8b7191ae2ed8c504d4af
>
> Thanks,
>
> -liubo
>
>>
>> Traces here:
>> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
>> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
>> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
>> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
>> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
>> [<ffffffff810a0cbb>] kthread+0xdb/0x100
>> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
>> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>>
>> Leftover inexact backtrace:
>>
>> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
>> INFO: task mysqld:1977 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
>> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
>> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
>> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
>> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
>> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
>> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>>
>> Leftover inexact backtrace:
>>
>> INFO: task mysqld:3249 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
>> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
>> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
>> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03b4cb7>]
>> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
>> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
>> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
>> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
>> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
>> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
>> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>>
>> Leftover inexact backtrace:
>>
>> INFO: task mysqld:3250 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff881374edb868 0 3250 1 0x00080000
>> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
>> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
>> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
>> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
>> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
>>
>> Leftover inexact backtrace:
>>
>> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
>> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
>> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
>> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
>> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
>> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
>> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
>> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
>> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
>> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
>> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
>> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
>> [<ffffffff811cee26>] __vfs_write+0x26/0x40
>> [<ffffffff811cf419>] vfs_write+0xa9/0x190
>> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
>> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
>> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
>> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
>> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
>> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
>> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
>> [<ffffffff810a0cbb>] kthread+0xdb/0x100
>> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
>> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>>
>> Leftover inexact backtrace:
>>
>> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
>> INFO: task mysqld:1977 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
>> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
>> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
>> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
>> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
>> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
>> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>>
>> Leftover inexact backtrace:
>>
>> INFO: task mysqld:3249 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
>> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
>> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
>> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03b4cb7>]
>> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
>> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
>> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
>> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
>> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
>> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
>> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>>
>> Leftover inexact backtrace:
>>
>> INFO: task mysqld:3250 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff881374edb868 0 3250 1 0x00080000
>> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
>> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
>> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
>> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
>> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
>>
>> Leftover inexact backtrace:
>>
>> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
>> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
>> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
>> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
>> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
>> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
>> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
>> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
>> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
>> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
>> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
>> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
>> [<ffffffff811cee26>] __vfs_write+0x26/0x40
>> [<ffffffff811cf419>] vfs_write+0xa9/0x190
>> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
>> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
>> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
>> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
>> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
>> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
>> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
>> [<ffffffff810a0cbb>] kthread+0xdb/0x100
>> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
>> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>>
>> Leftover inexact backtrace:
>>
>> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
>> INFO: task mysqld:1977 blocked for more than 120 seconds.
>> Not tainted 4.4.34 #1
>> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
>> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
>> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
>> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
>> Call Trace:
>> [<ffffffff816a8425>] schedule+0x35/0x80
>> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
>> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
>> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
>> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>>
>> Leftover inexact backtrace:
>>
>> Greets,
>> Stefan
>>
>> >
>> > Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
>> > Reviewed-by: Chris Mason <clm@fb.com>
>> > ---
>> > fs/btrfs/inode.c | 8 +++++---
>> > 1 file changed, 5 insertions(+), 3 deletions(-)
>> >
>> > diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
>> > index 2b790bd..48e9356 100644
>> > --- a/fs/btrfs/inode.c
>> > +++ b/fs/btrfs/inode.c
>> > @@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
>> > }
>> >
>> > /*
>> > - * this will cow the extent, reset the len in case we changed
>> > - * it above
>> > + * this will cow the extent, if em is within [start, len], then
>> > + * probably we've found a preallocated/existing extent, let's
>> > + * give it a chance to use preallocated space.
>> > */
>> > - len = bh_result->b_size;
>> > + len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
>> > + len = ALIGN(len, root->sectorsize);
>> > free_extent_map(em);
>> > em = btrfs_new_extent_direct(inode, start, len);
>> > if (IS_ERR(em)) {
>> >
--
Filipe David Manana,
"People will forget what you said,
people will forget what you did,
but people will never forget how you made them feel."
^ permalink raw reply related [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-11-24 11:13 ` Filipe Manana
@ 2016-12-02 1:41 ` Liu Bo
2016-12-02 12:25 ` Filipe Manana
0 siblings, 1 reply; 11+ messages in thread
From: Liu Bo @ 2016-12-02 1:41 UTC (permalink / raw)
To: Filipe Manana
Cc: Stefan Priebe - Profihost AG, linux-btrfs@vger.kernel.org,
David Sterba, Josef Bacik
On Thu, Nov 24, 2016 at 11:13:37AM +0000, Filipe Manana wrote:
> On Wed, Nov 23, 2016 at 9:22 PM, Liu Bo <bo.li.liu@oracle.com> wrote:
> > Hi,
> >
> > On Wed, Nov 23, 2016 at 06:21:35PM +0100, Stefan Priebe - Profihost AG wrote:
> >> Hi,
> >>
> >> sorry last mail was from the wrong box.
> >>
> >> Am 04.11.2016 um 20:20 schrieb Liu Bo:
> >> > If we have
> >> >
> >> > |0--hole--4095||4096--preallocate--12287|
> >> >
> >> > instead of using preallocated space, a 8K direct write will just
> >> > create a new 8K extent and it'll end up with
> >> >
> >> > |0--new extent--8191||8192--preallocate--12287|
> >> >
> >> > It's because we find a hole em and then go to create a new 8K
> >> > extent directly without adjusting @len.
> >>
> >> after applying that one on top of my 4.4 btrfs branch (includes patches
> >> up to 4.10 / next). i'm getting deadlocks in btrfs.
> >
> > This is really interesting, thanks for the quick testing.
> >
> > After going through the stacks listed below, I think the patch has
> > exposed a bug around BTRFS_I(inode)->dio_sem:
> >
> > 1. Since fsync has acquired inode_lock(), the dio write must be
> > an overwrite within EOF.
> >
> > 2. Lets say the inode size is 16k and it already has a preallocated extent [4k, 8k],
> > then we feed it with a dio write against [0k, 8k], with this patch
> > applied, the write can be splitted into a new extent of [0, 4k] and a
> > fill-write against the preallocated one [4k, 8k],
> >
> > 3.
> > dio fsync
> > ->btrfs_direct_IO btrfs_sync_file
> > ->do_direct_IO
> > ->get_more_blocks() ->inode_lock()
> > ->btrfs_get_blocks_direct() # for [0, 8k] ->btrfs_log_inode()
> > ->btrfs_new_direct_extent() ->btrfs_log_changed_extents()
> > ->btrfs_create_dio_extent()
> > ->down_read(&BTRFS_I(inode)->dio_sem)
> > # dio write is splitted and
> > # em of [0, 4k] is inserted as well as
> > # the ordered extent.
> > ->up_read(&BTRFS_I(inode)->dio_sem)
> > # do_direct_IO tries to collect more pages
> > # before sending them down, so [0, 4k] is not
> > # yet submitted.
> > --------------------------------------------------------------------------------------------------------
> > ->down_write(&BTRFS_I(inode)->dio_sem)
> > # found ordered extent of [0, 4k]
> > # wait for [0, 4k] to finish
> > ->get_more_blocks()
> > ->btrfs_get_blocks_direct() # for [4k, 8k]
> > ->btrfs_create_dio_extent()
> > -> up_read(&BTRFS_I(inode)->dio_sem)
> > # deadlock occurs
> >
> > 4. _Without_ this patch, we could hit the deadlock as well under space pressure,
> > i.e. if we request [0, 8k], but btrfs_reserve_extent() returns only [0, 4k].
> >
> > (Filipe may correct me, cc'd Filipe.)
>
> The analysis is correct Bo.
> Originally to fix races between fsync and direct IO writes there was a
> solution [1, 2] that didn't involve adding a semaphore and relied on
> creating first the ordered extents and then the extent maps only in
> the direct IO write path (we do things in the reverse order everywhere
> else). It worked and was documented in comments but wasn't
> particularly elegant and Josef was not happy because of that, so then
> we added the semaphore and made direct IO write path create the extent
> maps and ordered extents in the same order as everywhere else [3].
>
> So here I can only see 2 simple solutions. Either revert [3] (which
> added the semaphore) or acquire the semaphore at a higher level in
> direct IO write path like this:
>
> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> index 1f980ef..b2c277d 100644
> --- a/fs/btrfs/inode.c
> +++ b/fs/btrfs/inode.c
> @@ -7237,7 +7237,6 @@ static struct extent_map
> *btrfs_create_dio_extent(struct inode *inode,
> struct extent_map *em = NULL;
> int ret;
>
> - down_read(&BTRFS_I(inode)->dio_sem);
> if (type != BTRFS_ORDERED_NOCOW) {
> em = create_pinned_em(inode, start, len, orig_start,
> block_start, block_len, orig_block_len,
> @@ -7256,8 +7255,6 @@ static struct extent_map
> *btrfs_create_dio_extent(struct inode *inode,
> em = ERR_PTR(ret);
> }
> out:
> - up_read(&BTRFS_I(inode)->dio_sem);
> -
> return em;
> }
>
> @@ -8715,11 +8712,14 @@ static ssize_t btrfs_direct_IO(struct kiocb
> *iocb, struct iov_iter *iter)
> wakeup = false;
> }
>
> + if (iov_iter_rw(iter) == WRITE)
> + down_read(&BTRFS_I(inode)->dio_sem);
> ret = __blockdev_direct_IO(iocb, inode,
>
> BTRFS_I(inode)->root->fs_info->fs_devices->latest_bdev,
> iter, btrfs_get_blocks_direct, NULL,
> btrfs_submit_direct, flags);
> if (iov_iter_rw(iter) == WRITE) {
> + up_read(&BTRFS_I(inode)->dio_sem);
> current->journal_info = NULL;
> if (ret < 0 && ret != -EIOCBQUEUED) {
> if (dio_data.reserve)
>
>
> Let me know what you think. Thanks.
Hi Filipe,
After going over again fs/direct-io.c, the AIO dio_complete is diffrent from the
'Note that' part in your patch [1], what am I missing?
-------------------------------------------------------------------------
static ssize_t dio_complete(struct dio *dio, ssize_t ret, bool is_async)
{
...
if (!(dio->flags & DIO_SKIP_DIO_COUNT))
inode_dio_end(dio->inode);
if (is_async) {
/*
* generic_write_sync expects ki_pos to have been updated
* already, but the submission path only does this for
* synchronous I/O.
*/
dio->iocb->ki_pos += transferred;
if (dio->op == REQ_OP_WRITE)
ret = generic_write_sync(dio->iocb, transferred);
dio->iocb->ki_complete(dio->iocb, ret, 0);
}
...
}
-------------------------------------------------------------------------
[1] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=de0ee0edb21fbab4c7afa3e94573ecfebfb0244e
Thanks,
-liubo
>
> [1] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=de0ee0edb21fbab4c7afa3e94573ecfebfb0244e
> [2] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=0b901916a00bc7b14ee83cc8e41c3b0d561a8f22
> [3] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=5f9a8a51d8b95505d8de8b7191ae2ed8c504d4af
>
>
> >
> > Thanks,
> >
> > -liubo
> >
> >>
> >> Traces here:
> >> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
> >> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
> >> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
> >> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
> >> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
> >> [<ffffffff810a0cbb>] kthread+0xdb/0x100
> >> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
> >> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
> >>
> >> Leftover inexact backtrace:
> >>
> >> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
> >> INFO: task mysqld:1977 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
> >> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
> >> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
> >> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
> >> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
> >> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
> >>
> >> Leftover inexact backtrace:
> >>
> >> INFO: task mysqld:3249 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
> >> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
> >> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
> >> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03b4cb7>]
> >> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
> >> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
> >> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
> >> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
> >> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
> >> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
> >>
> >> Leftover inexact backtrace:
> >>
> >> INFO: task mysqld:3250 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff881374edb868 0 3250 1 0x00080000
> >> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
> >> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
> >> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
> >> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
> >> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
> >>
> >> Leftover inexact backtrace:
> >>
> >> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
> >> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
> >> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
> >> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
> >> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
> >> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> >> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> >> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> >> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
> >> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
> >> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
> >> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
> >> [<ffffffff811cee26>] __vfs_write+0x26/0x40
> >> [<ffffffff811cf419>] vfs_write+0xa9/0x190
> >> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
> >> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
> >> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
> >> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
> >> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
> >> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
> >> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
> >> [<ffffffff810a0cbb>] kthread+0xdb/0x100
> >> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
> >> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
> >>
> >> Leftover inexact backtrace:
> >>
> >> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
> >> INFO: task mysqld:1977 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
> >> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
> >> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
> >> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
> >> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
> >> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
> >>
> >> Leftover inexact backtrace:
> >>
> >> INFO: task mysqld:3249 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
> >> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
> >> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
> >> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03b4cb7>]
> >> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
> >> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
> >> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
> >> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
> >> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
> >> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
> >>
> >> Leftover inexact backtrace:
> >>
> >> INFO: task mysqld:3250 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff881374edb868 0 3250 1 0x00080000
> >> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
> >> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
> >> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
> >> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
> >> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
> >>
> >> Leftover inexact backtrace:
> >>
> >> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
> >> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
> >> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
> >> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
> >> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
> >> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> >> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> >> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
> >> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
> >> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
> >> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
> >> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
> >> [<ffffffff811cee26>] __vfs_write+0x26/0x40
> >> [<ffffffff811cf419>] vfs_write+0xa9/0x190
> >> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
> >> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
> >> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
> >> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
> >> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
> >> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
> >> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
> >> [<ffffffff810a0cbb>] kthread+0xdb/0x100
> >> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
> >> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
> >>
> >> Leftover inexact backtrace:
> >>
> >> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
> >> INFO: task mysqld:1977 blocked for more than 120 seconds.
> >> Not tainted 4.4.34 #1
> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
> >> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
> >> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
> >> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
> >> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
> >> Call Trace:
> >> [<ffffffff816a8425>] schedule+0x35/0x80
> >> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
> >> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
> >> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
> >>
> >> Leftover inexact backtrace:
> >>
> >> Greets,
> >> Stefan
> >>
> >> >
> >> > Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
> >> > Reviewed-by: Chris Mason <clm@fb.com>
> >> > ---
> >> > fs/btrfs/inode.c | 8 +++++---
> >> > 1 file changed, 5 insertions(+), 3 deletions(-)
> >> >
> >> > diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> >> > index 2b790bd..48e9356 100644
> >> > --- a/fs/btrfs/inode.c
> >> > +++ b/fs/btrfs/inode.c
> >> > @@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
> >> > }
> >> >
> >> > /*
> >> > - * this will cow the extent, reset the len in case we changed
> >> > - * it above
> >> > + * this will cow the extent, if em is within [start, len], then
> >> > + * probably we've found a preallocated/existing extent, let's
> >> > + * give it a chance to use preallocated space.
> >> > */
> >> > - len = bh_result->b_size;
> >> > + len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
> >> > + len = ALIGN(len, root->sectorsize);
> >> > free_extent_map(em);
> >> > em = btrfs_new_extent_direct(inode, start, len);
> >> > if (IS_ERR(em)) {
> >> >
>
>
>
> --
> Filipe David Manana,
>
> "People will forget what you said,
> people will forget what you did,
> but people will never forget how you made them feel."
> --
> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at http://vger.kernel.org/majordomo-info.html
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-12-02 1:41 ` Liu Bo
@ 2016-12-02 12:25 ` Filipe Manana
2016-12-16 22:37 ` Liu Bo
0 siblings, 1 reply; 11+ messages in thread
From: Filipe Manana @ 2016-12-02 12:25 UTC (permalink / raw)
To: Liu Bo
Cc: Stefan Priebe - Profihost AG, linux-btrfs@vger.kernel.org,
David Sterba, Josef Bacik
On Fri, Dec 2, 2016 at 1:41 AM, Liu Bo <bo.li.liu@oracle.com> wrote:
> On Thu, Nov 24, 2016 at 11:13:37AM +0000, Filipe Manana wrote:
>> On Wed, Nov 23, 2016 at 9:22 PM, Liu Bo <bo.li.liu@oracle.com> wrote:
>> > Hi,
>> >
>> > On Wed, Nov 23, 2016 at 06:21:35PM +0100, Stefan Priebe - Profihost AG wrote:
>> >> Hi,
>> >>
>> >> sorry last mail was from the wrong box.
>> >>
>> >> Am 04.11.2016 um 20:20 schrieb Liu Bo:
>> >> > If we have
>> >> >
>> >> > |0--hole--4095||4096--preallocate--12287|
>> >> >
>> >> > instead of using preallocated space, a 8K direct write will just
>> >> > create a new 8K extent and it'll end up with
>> >> >
>> >> > |0--new extent--8191||8192--preallocate--12287|
>> >> >
>> >> > It's because we find a hole em and then go to create a new 8K
>> >> > extent directly without adjusting @len.
>> >>
>> >> after applying that one on top of my 4.4 btrfs branch (includes patches
>> >> up to 4.10 / next). i'm getting deadlocks in btrfs.
>> >
>> > This is really interesting, thanks for the quick testing.
>> >
>> > After going through the stacks listed below, I think the patch has
>> > exposed a bug around BTRFS_I(inode)->dio_sem:
>> >
>> > 1. Since fsync has acquired inode_lock(), the dio write must be
>> > an overwrite within EOF.
>> >
>> > 2. Lets say the inode size is 16k and it already has a preallocated extent [4k, 8k],
>> > then we feed it with a dio write against [0k, 8k], with this patch
>> > applied, the write can be splitted into a new extent of [0, 4k] and a
>> > fill-write against the preallocated one [4k, 8k],
>> >
>> > 3.
>> > dio fsync
>> > ->btrfs_direct_IO btrfs_sync_file
>> > ->do_direct_IO
>> > ->get_more_blocks() ->inode_lock()
>> > ->btrfs_get_blocks_direct() # for [0, 8k] ->btrfs_log_inode()
>> > ->btrfs_new_direct_extent() ->btrfs_log_changed_extents()
>> > ->btrfs_create_dio_extent()
>> > ->down_read(&BTRFS_I(inode)->dio_sem)
>> > # dio write is splitted and
>> > # em of [0, 4k] is inserted as well as
>> > # the ordered extent.
>> > ->up_read(&BTRFS_I(inode)->dio_sem)
>> > # do_direct_IO tries to collect more pages
>> > # before sending them down, so [0, 4k] is not
>> > # yet submitted.
>> > --------------------------------------------------------------------------------------------------------
>> > ->down_write(&BTRFS_I(inode)->dio_sem)
>> > # found ordered extent of [0, 4k]
>> > # wait for [0, 4k] to finish
>> > ->get_more_blocks()
>> > ->btrfs_get_blocks_direct() # for [4k, 8k]
>> > ->btrfs_create_dio_extent()
>> > -> up_read(&BTRFS_I(inode)->dio_sem)
>> > # deadlock occurs
>> >
>> > 4. _Without_ this patch, we could hit the deadlock as well under space pressure,
>> > i.e. if we request [0, 8k], but btrfs_reserve_extent() returns only [0, 4k].
>> >
>> > (Filipe may correct me, cc'd Filipe.)
>>
>> The analysis is correct Bo.
>> Originally to fix races between fsync and direct IO writes there was a
>> solution [1, 2] that didn't involve adding a semaphore and relied on
>> creating first the ordered extents and then the extent maps only in
>> the direct IO write path (we do things in the reverse order everywhere
>> else). It worked and was documented in comments but wasn't
>> particularly elegant and Josef was not happy because of that, so then
>> we added the semaphore and made direct IO write path create the extent
>> maps and ordered extents in the same order as everywhere else [3].
>>
>> So here I can only see 2 simple solutions. Either revert [3] (which
>> added the semaphore) or acquire the semaphore at a higher level in
>> direct IO write path like this:
>>
>> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
>> index 1f980ef..b2c277d 100644
>> --- a/fs/btrfs/inode.c
>> +++ b/fs/btrfs/inode.c
>> @@ -7237,7 +7237,6 @@ static struct extent_map
>> *btrfs_create_dio_extent(struct inode *inode,
>> struct extent_map *em = NULL;
>> int ret;
>>
>> - down_read(&BTRFS_I(inode)->dio_sem);
>> if (type != BTRFS_ORDERED_NOCOW) {
>> em = create_pinned_em(inode, start, len, orig_start,
>> block_start, block_len, orig_block_len,
>> @@ -7256,8 +7255,6 @@ static struct extent_map
>> *btrfs_create_dio_extent(struct inode *inode,
>> em = ERR_PTR(ret);
>> }
>> out:
>> - up_read(&BTRFS_I(inode)->dio_sem);
>> -
>> return em;
>> }
>>
>> @@ -8715,11 +8712,14 @@ static ssize_t btrfs_direct_IO(struct kiocb
>> *iocb, struct iov_iter *iter)
>> wakeup = false;
>> }
>>
>> + if (iov_iter_rw(iter) == WRITE)
>> + down_read(&BTRFS_I(inode)->dio_sem);
>> ret = __blockdev_direct_IO(iocb, inode,
>>
>> BTRFS_I(inode)->root->fs_info->fs_devices->latest_bdev,
>> iter, btrfs_get_blocks_direct, NULL,
>> btrfs_submit_direct, flags);
>> if (iov_iter_rw(iter) == WRITE) {
>> + up_read(&BTRFS_I(inode)->dio_sem);
>> current->journal_info = NULL;
>> if (ret < 0 && ret != -EIOCBQUEUED) {
>> if (dio_data.reserve)
>>
>>
>> Let me know what you think. Thanks.
>
> Hi Filipe,
>
> After going over again fs/direct-io.c, the AIO dio_complete is diffrent from the
> 'Note that' part in your patch [1], what am I missing?
>
> -------------------------------------------------------------------------
> static ssize_t dio_complete(struct dio *dio, ssize_t ret, bool is_async)
> {
> ...
> if (!(dio->flags & DIO_SKIP_DIO_COUNT))
> inode_dio_end(dio->inode);
>
> if (is_async) {
> /*
> * generic_write_sync expects ki_pos to have been updated
> * already, but the submission path only does this for
> * synchronous I/O.
> */
> dio->iocb->ki_pos += transferred;
>
> if (dio->op == REQ_OP_WRITE)
> ret = generic_write_sync(dio->iocb, transferred);
> dio->iocb->ki_complete(dio->iocb, ret, 0);
> }
> ...
> }
It's still the same as when I checked. The problem is that even after
that call to inode_dio_end(), the inode->i_dio_count() is still
non-zero (it's 1 iirc).
I don't have any longer the debugging patch I used to find out that
out (nor remember all the details), but I just tried again the
approach of calling inode_dio_wait() in btrfs_sync_file() after
locking the inode:
https://friendpaste.com/pRwJkgsFXv6HglftK1BqH
And the same deadlock ends up happening, which is trivial to reproduce
with fstest generic/113:
[ 2593.870593] run fstests generic/113 at 2016-12-02 11:19:39
[ 2594.308402] BTRFS info (device sdb): disk space caching is enabled
[ 2594.309654] BTRFS info (device sdb): has skinny extents
[ 2595.460142] BTRFS info (device sdb): disk space caching is enabled
[ 2595.461161] BTRFS info (device sdb): has skinny extents
[ 2597.011706] BTRFS info (device sdb): disk space caching is enabled
[ 2597.012918] BTRFS info (device sdb): has skinny extents
[ 2605.098582] BTRFS info (device sdb): disk space caching is enabled
[ 2605.099324] BTRFS info (device sdb): has skinny extents
[ 2677.131447] systemd-journald[571]: Sent WATCHDOG=1 notification.
[ 2727.133247] systemd-journald[571]: Sent WATCHDOG=1 notification.
[ 2782.176191] INFO: task aio-stress:17143 blocked for more than 120 seconds.
[ 2782.177659] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.178722] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.180484] aio-stress D ffff8800b30c7a98 0 17143 16641 0x00000000
[ 2782.181652] ffff8800b30c7a98 0000000000000282 00ff8800b30c7a50
ffff88023f3175c0
[ 2782.183042] ffff8802156b1680 ffff8800b60fc280 ffff8800b30c8000
ffff8800b60fc280
[ 2782.184586] fffffffe00000001 ffff8800b60fc280 ffff8800b1e8e4e0
ffff8800b30c7ab0
[ 2782.186266] Call Trace:
[ 2782.186884] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.187965] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2782.190039] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2782.191195] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2782.192413] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2782.193829] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2782.194908] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2782.195963] [<ffffffffa04dd48c>] ? btrfs_direct_IO+0x26e/0x280 [btrfs]
[ 2782.197235] [<ffffffffa04dd48c>] btrfs_direct_IO+0x26e/0x280 [btrfs]
[ 2782.198439] [<ffffffff811299bc>] generic_file_direct_write+0xb1/0x125
[ 2782.199692] [<ffffffffa04ee700>] btrfs_file_write_iter+0x24d/0x4a4 [btrfs]
[ 2782.200976] [<ffffffffa04ee4b3>] ? btrfs_sync_file+0x43a/0x43a [btrfs]
[ 2782.202356] [<ffffffff811ca6cd>] aio_run_iocb+0x161/0x245
[ 2782.203556] [<ffffffff81091300>] ? arch_local_irq_save+0x9/0xc
[ 2782.204777] [<ffffffff81151964>] ? __might_fault+0x37/0x84
[ 2782.205821] [<ffffffff81151964>] ? __might_fault+0x37/0x84
[ 2782.206909] [<ffffffff811cb482>] do_io_submit+0x2e4/0x37b
[ 2782.207888] [<ffffffff811cb482>] ? do_io_submit+0x2e4/0x37b
[ 2782.209121] [<ffffffff81093fe9>] ? trace_hardirqs_on_caller+0x17b/0x197
[ 2782.210470] [<ffffffff811cb529>] SyS_io_submit+0x10/0x12
[ 2782.211529] [<ffffffff811cb529>] ? SyS_io_submit+0x10/0x12
[ 2782.212724] [<ffffffff814b9565>] entry_SYSCALL_64_fastpath+0x18/0xa8
[ 2782.214026] [<ffffffff81091b08>] ? trace_hardirqs_off_caller+0x3f/0xaa
[ 2782.215547] 2 locks held by aio-stress/17143:
[ 2782.216444] #0: (sb_writers#12){.+.+.+}, at: [<ffffffff8118cb3c>]
__sb_start_write+0x5f/0xb0
[ 2782.217857] #1: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04dd48c>] btrfs_direct_IO+0x26e/0x280 [btrfs]
[ 2782.219450] INFO: task dio/sdb:17146 blocked for more than 120 seconds.
[ 2782.220397] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.221378] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.222950] dio/sdb D ffff8800b28a3ae8 0 17146 2 0x00000000
[ 2782.224438] Workqueue: dio/sdb dio_aio_complete_work
[ 2782.225462] ffff8800b28a3ae8 ffffffff814b8f06 00fffffe00000001
ffff88023f3175c0
[ 2782.227141] ffff88002a3a40c0 ffff8800baad1940 ffff8800b28a4000
ffff8800baad1940
[ 2782.228745] fffffffe00000001 ffff8800baad1940 ffff8800b1e8e4e0
ffff8800b28a3b00
[ 2782.230345] Call Trace:
[ 2782.230888] [<ffffffff814b8f06>] ? _raw_spin_unlock_irq+0x2c/0x4a
[ 2782.232833] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.233814] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2782.235243] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2782.236443] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2782.237918] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2782.238890] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2782.239790] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2782.240769] [<ffffffffa04ee1ca>] ? btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.242060] [<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.243410] [<ffffffff8106c476>] ? rescuer_thread+0xf6/0x2b3
[ 2782.244525] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2782.245632] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2782.246731] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2782.248037] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2782.249126] [<ffffffff8106c379>] process_scheduled_works+0x2c/0x33
[ 2782.250279] [<ffffffff8106c530>] rescuer_thread+0x1b0/0x2b3
[ 2782.251399] [<ffffffff8106c380>] ? process_scheduled_works+0x33/0x33
[ 2782.252674] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2782.253652] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2782.254631] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2782.255824] 3 locks held by dio/sdb/17146:
[ 2782.256699] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.258711] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.260676] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.262831] INFO: task kworker/4:8:17191 blocked for more than 120 seconds.
[ 2782.264195] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.265215] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.266750] kworker/4:8 D ffff8800b6187c18 0 17191 2 0x00000000
[ 2782.268353] Workqueue: dio/sdb dio_aio_complete_work
[ 2782.269194] ffff8800b6187c18 ffff8800b6187bd8 00ffffff81094012
ffff88023f3175c0
[ 2782.270729] ffff8800b4059240 ffff8802144e1740 ffff8800b6188000
ffff88023ffa66c8
[ 2782.272279] ffff8800b6187c58 0000000000000001 ffff880215784a80
ffff8800b6187c30
[ 2782.273810] Call Trace:
[ 2782.274364] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.275290] [<ffffffff811a13e6>] inode_dio_wait+0x9e/0xc3
[ 2782.276340] [<ffffffff8108af0a>] ? autoremove_wake_function+0x3a/0x3a
[ 2782.277553] [<ffffffffa04ee1d2>] btrfs_sync_file+0x159/0x43a [btrfs]
[ 2782.278537] [<ffffffff81094903>] ? __lock_acquire+0x669/0xe86
[ 2782.279193] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2782.280252] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2782.281195] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2782.282205] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2782.283264] [<ffffffff8106c81e>] worker_thread+0x1eb/0x2c9
[ 2782.284410] [<ffffffff8106c633>] ? rescuer_thread+0x2b3/0x2b3
[ 2782.285478] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2782.286350] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2782.287469] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2782.288572] 3 locks held by kworker/4:8/17191:
[ 2782.289263] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.290930] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.292603] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.294547] INFO: task kworker/4:9:17192 blocked for more than 120 seconds.
[ 2782.295650] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.304623] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.305783] kworker/4:9 D ffff8800b618bb38 0 17192 2 0x00000000
[ 2782.306974] Workqueue: dio/sdb dio_aio_complete_work
[ 2782.307741] ffff8800b618bb38 ffffffff814b8f06 00fffffe00000001
ffff88023f3175c0
[ 2782.309254] ffff8800b1525100 ffff8800b4059240 ffff8800b618c000
ffff8800b4059240
[ 2782.310678] fffffffe00000001 ffff8800b4059240 ffff8800b1e8e4e0
ffff8800b618bb50
[ 2782.312090] Call Trace:
[ 2782.312478] [<ffffffff814b8f06>] ? _raw_spin_unlock_irq+0x2c/0x4a
[ 2782.313555] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.314299] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2782.315464] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2782.316531] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2782.317478] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2782.318598] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2782.319406] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2782.320241] [<ffffffffa04ee1ca>] ? btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.321300] [<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.322220] [<ffffffff81094903>] ? __lock_acquire+0x669/0xe86
[ 2782.323133] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2782.323993] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2782.324871] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2782.325816] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2782.326523] [<ffffffff8106c81e>] worker_thread+0x1eb/0x2c9
[ 2782.327301] [<ffffffff8106c633>] ? rescuer_thread+0x2b3/0x2b3
[ 2782.327869] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2782.328539] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2782.329402] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2782.330230] 3 locks held by kworker/4:9/17192:
[ 2782.330897] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.332445] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.334011] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.335776] INFO: task kworker/4:10:17193 blocked for more than 120 seconds.
[ 2782.336905] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.337693] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.338956] kworker/4:10 D ffff8800b618fb38 0 17193 2 0x00000000
[ 2782.339986] Workqueue: dio/sdb dio_aio_complete_work
[ 2782.340766] ffff8800b618fb38 ffffffff814b8f06 00fffffe00000001
ffff88023f3175c0
[ 2782.341956] ffff8800b65c1340 ffff8800b1525100 ffff8800b6190000
ffff8800b1525100
[ 2782.343201] fffffffe00000001 ffff8800b1525100 ffff8800b1e8e4e0
ffff8800b618fb50
[ 2782.344469] Call Trace:
[ 2782.344896] [<ffffffff814b8f06>] ? _raw_spin_unlock_irq+0x2c/0x4a
[ 2782.345713] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.346505] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2782.347610] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2782.348621] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2782.349652] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2782.350598] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2782.351414] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2782.352229] [<ffffffffa04ee1ca>] ? btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.353221] [<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.354204] [<ffffffff81094903>] ? __lock_acquire+0x669/0xe86
[ 2782.355110] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2782.355873] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2782.356771] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2782.357707] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2782.358662] [<ffffffff8106c81e>] worker_thread+0x1eb/0x2c9
[ 2782.359499] [<ffffffff8106c633>] ? rescuer_thread+0x2b3/0x2b3
[ 2782.360364] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2782.361136] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2782.361982] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2782.362951] 3 locks held by kworker/4:10/17193:
[ 2782.363719] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.365256] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.366944] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.368823] INFO: task kworker/4:11:17194 blocked for more than 120 seconds.
[ 2782.370066] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.370927] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.372287] kworker/4:11 D ffff8800b65c7b38 0 17194 2 0x00000000
[ 2782.373432] Workqueue: dio/sdb dio_aio_complete_work
[ 2782.374214] ffff8800b65c7b38 ffffffff814b8f06 00fffffe00000001
ffff88023f3175c0
[ 2782.375494] ffff8800b9339400 ffff8800b65c1340 ffff8800b65c8000
ffff8800b65c1340
[ 2782.376806] fffffffe00000001 ffff8800b65c1340 ffff8800b1e8e4e0
ffff8800b65c7b50
[ 2782.378164] Call Trace:
[ 2782.378640] [<ffffffff814b8f06>] ? _raw_spin_unlock_irq+0x2c/0x4a
[ 2782.379665] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.380493] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2782.381691] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2782.382660] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2782.383720] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2782.384768] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2782.385722] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2782.386605] [<ffffffffa04ee1ca>] ? btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.387679] [<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.388806] [<ffffffff81094903>] ? __lock_acquire+0x669/0xe86
[ 2782.389841] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2782.390741] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2782.391582] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2782.392523] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2782.393442] [<ffffffff8106c81e>] worker_thread+0x1eb/0x2c9
[ 2782.394295] [<ffffffff8106c633>] ? rescuer_thread+0x2b3/0x2b3
[ 2782.395225] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2782.395978] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2782.396790] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2782.397614] 3 locks held by kworker/4:11/17194:
[ 2782.398314] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.419771] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.422252] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.424843] INFO: task kworker/4:16:17333 blocked for more than 120 seconds.
[ 2782.426557] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2782.427804] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2782.441453] kworker/4:16 D ffff8800b2a2fb38 0 17333 2 0x00000000
[ 2782.443148] Workqueue: dio/sdb dio_aio_complete_work
[ 2782.444158] ffff8800b2a2fb38 ffffffff814b8f06 00fffffe00000001
ffff88023f3175c0
[ 2782.445657] ffff8800b14a8a40 ffff8800b2a299c0 ffff8800b2a30000
ffff8800b2a299c0
[ 2782.447384] fffffffe00000001 ffff8800b2a299c0 ffff8800b1e8e4e0
ffff8800b2a2fb50
[ 2782.449001] Call Trace:
[ 2782.449605] [<ffffffff814b8f06>] ? _raw_spin_unlock_irq+0x2c/0x4a
[ 2782.450740] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2782.451802] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2782.453466] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2782.454656] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2782.456114] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2782.457408] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2782.458456] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2782.459603] [<ffffffffa04ee1ca>] ? btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.461098] [<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2782.462503] [<ffffffff81094903>] ? __lock_acquire+0x669/0xe86
[ 2782.463803] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2782.465057] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2782.466265] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2782.467396] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2782.468650] [<ffffffff8106c81e>] worker_thread+0x1eb/0x2c9
[ 2782.469855] [<ffffffff8106c633>] ? rescuer_thread+0x2b3/0x2b3
[ 2782.471156] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2782.472290] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2782.473417] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2782.474284] 3 locks held by kworker/4:16/17333:
[ 2782.474941] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.476541] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2782.478453] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2857.131317] systemd-journald[571]: Sent WATCHDOG=1 notification.
[ 2903.008172] INFO: task aio-stress:17143 blocked for more than 120 seconds.
[ 2903.009649] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2903.010530] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2903.012326] aio-stress D ffff8800b30c7a98 0 17143 16641 0x00000000
[ 2903.013807] ffff8800b30c7a98 0000000000000282 00ff8800b30c7a50
ffff88023f3175c0
[ 2903.015553] ffff8802156b1680 ffff8800b60fc280 ffff8800b30c8000
ffff8800b60fc280
[ 2903.017383] fffffffe00000001 ffff8800b60fc280 ffff8800b1e8e4e0
ffff8800b30c7ab0
[ 2903.019364] Call Trace:
[ 2903.020085] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2903.020963] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2903.022745] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2903.024136] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2903.036455] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2903.037884] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2903.038942] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2903.040098] [<ffffffffa04dd48c>] ? btrfs_direct_IO+0x26e/0x280 [btrfs]
[ 2903.041480] [<ffffffffa04dd48c>] btrfs_direct_IO+0x26e/0x280 [btrfs]
[ 2903.042808] [<ffffffff811299bc>] generic_file_direct_write+0xb1/0x125
[ 2903.044274] [<ffffffffa04ee700>] btrfs_file_write_iter+0x24d/0x4a4 [btrfs]
[ 2903.045882] [<ffffffffa04ee4b3>] ? btrfs_sync_file+0x43a/0x43a [btrfs]
[ 2903.047293] [<ffffffff811ca6cd>] aio_run_iocb+0x161/0x245
[ 2903.048545] [<ffffffff81091300>] ? arch_local_irq_save+0x9/0xc
[ 2903.049829] [<ffffffff81151964>] ? __might_fault+0x37/0x84
[ 2903.051047] [<ffffffff81151964>] ? __might_fault+0x37/0x84
[ 2903.052343] [<ffffffff811cb482>] do_io_submit+0x2e4/0x37b
[ 2903.053608] [<ffffffff811cb482>] ? do_io_submit+0x2e4/0x37b
[ 2903.054837] [<ffffffff81093fe9>] ? trace_hardirqs_on_caller+0x17b/0x197
[ 2903.056280] [<ffffffff811cb529>] SyS_io_submit+0x10/0x12
[ 2903.057416] [<ffffffff811cb529>] ? SyS_io_submit+0x10/0x12
[ 2903.058569] [<ffffffff814b9565>] entry_SYSCALL_64_fastpath+0x18/0xa8
[ 2903.059978] [<ffffffff81091b08>] ? trace_hardirqs_off_caller+0x3f/0xaa
[ 2903.061360] 2 locks held by aio-stress/17143:
[ 2903.062410] #0: (sb_writers#12){.+.+.+}, at: [<ffffffff8118cb3c>]
__sb_start_write+0x5f/0xb0
[ 2903.064445] #1: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04dd48c>] btrfs_direct_IO+0x26e/0x280 [btrfs]
[ 2903.066711] INFO: task dio/sdb:17146 blocked for more than 120 seconds.
[ 2903.068153] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2903.069288] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2903.070790] dio/sdb D ffff8800b28a3ae8 0 17146 2 0x00000000
[ 2903.072289] Workqueue: dio/sdb dio_aio_complete_work
[ 2903.073331] ffff8800b28a3ae8 ffffffff814b8f06 00fffffe00000001
ffff88023f3175c0
[ 2903.074942] ffff88002a3a40c0 ffff8800baad1940 ffff8800b28a4000
ffff8800baad1940
[ 2903.076601] fffffffe00000001 ffff8800baad1940 ffff8800b1e8e4e0
ffff8800b28a3b00
[ 2903.078005] Call Trace:
[ 2903.078589] [<ffffffff814b8f06>] ? _raw_spin_unlock_irq+0x2c/0x4a
[ 2903.079635] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2903.080600] [<ffffffff81098982>]
__rwsem_down_write_failed_common+0x340/0x401
[ 2903.082051] [<ffffffff814b81e1>] rwsem_down_write_failed+0x13/0x15
[ 2903.083246] [<ffffffff814b81e1>] ? rwsem_down_write_failed+0x13/0x15
[ 2903.084396] [<ffffffff81286cf7>] call_rwsem_down_write_failed+0x17/0x30
[ 2903.085592] [<ffffffff810907b4>] __down_write+0x1f/0x21
[ 2903.086583] [<ffffffff814b7b8b>] down_write+0x43/0x57
[ 2903.087636] [<ffffffffa04ee1ca>] ? btrfs_sync_file+0x151/0x43a [btrfs]
[ 2903.088947] [<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2903.089950] [<ffffffff8106c476>] ? rescuer_thread+0xf6/0x2b3
[ 2903.091011] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2903.092101] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2903.092916] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2903.093766] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2903.094888] [<ffffffff8106c379>] process_scheduled_works+0x2c/0x33
[ 2903.095976] [<ffffffff8106c530>] rescuer_thread+0x1b0/0x2b3
[ 2903.096960] [<ffffffff8106c380>] ? process_scheduled_works+0x33/0x33
[ 2903.098150] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2903.099018] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2903.100044] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2903.101121] 3 locks held by dio/sdb/17146:
[ 2903.101897] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2903.103901] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2903.105768] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
[ 2903.107926] INFO: task kworker/4:8:17191 blocked for more than 120 seconds.
[ 2903.109139] Not tainted 4.8.0-rc8-btrfs-next-35+ #1
[ 2903.110129] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
disables this message.
[ 2903.111629] kworker/4:8 D ffff8800b6187c18 0 17191 2 0x00000000
[ 2903.112859] Workqueue: dio/sdb dio_aio_complete_work
[ 2903.113793] ffff8800b6187c18 ffff8800b6187bd8 00ffffff81094012
ffff88023f3175c0
[ 2903.115276] ffff8800b4059240 ffff8802144e1740 ffff8800b6188000
ffff88023ffa66c8
[ 2903.116829] ffff8800b6187c58 0000000000000001 ffff880215784a80
ffff8800b6187c30
[ 2903.118250] Call Trace:
[ 2903.118749] [<ffffffff814b514b>] schedule+0x8b/0xa3
[ 2903.119624] [<ffffffff811a13e6>] inode_dio_wait+0x9e/0xc3
[ 2903.120625] [<ffffffff8108af0a>] ? autoremove_wake_function+0x3a/0x3a
[ 2903.121786] [<ffffffffa04ee1d2>] btrfs_sync_file+0x159/0x43a [btrfs]
[ 2903.122851] [<ffffffff81094903>] ? __lock_acquire+0x669/0xe86
[ 2903.123749] [<ffffffff811b5882>] vfs_fsync_range+0x8c/0x9e
[ 2903.124735] [<ffffffff811bd260>] dio_complete+0xf0/0x144
[ 2903.125806] [<ffffffff811bd3f3>] dio_aio_complete_work+0x1c/0x1e
[ 2903.126844] [<ffffffff8106c0d3>] process_one_work+0x273/0x4ed
[ 2903.127835] [<ffffffff8106c81e>] worker_thread+0x1eb/0x2c9
[ 2903.128816] [<ffffffff8106c633>] ? rescuer_thread+0x2b3/0x2b3
[ 2903.129811] [<ffffffff81071e20>] kthread+0xd4/0xdc
[ 2903.130679] [<ffffffff814b977f>] ret_from_fork+0x1f/0x40
[ 2903.131620] [<ffffffff81071d4c>] ? kthread_stop+0x28a/0x28a
[ 2903.132571] 3 locks held by kworker/4:8/17191:
[ 2903.133310] #0: ("dio/%s"sb->s_id){++++..}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2903.134845] #1: ((&dio->complete_work)){+.+...}, at:
[<ffffffff8106bfb4>] process_one_work+0x154/0x4ed
[ 2903.136723] #2: (&sb->s_type->i_mutex_key#15){+.+.+.}, at:
[<ffffffffa04ee1ca>] btrfs_sync_file+0x151/0x43a [btrfs]
I don't have the time to go now figure out all the details of the aio
code path again as I'm on vacation. But it's pretty evident that that
solution doesn't work unfortunately.
Thanks.
> -------------------------------------------------------------------------
>
> [1] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=de0ee0edb21fbab4c7afa3e94573ecfebfb0244e
>
> Thanks,
>
> -liubo
>
>>
>> [1] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=de0ee0edb21fbab4c7afa3e94573ecfebfb0244e
>> [2] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=0b901916a00bc7b14ee83cc8e41c3b0d561a8f22
>> [3] https://git.kernel.org/cgit/linux/kernel/git/torvalds/linux.git/commit/?id=5f9a8a51d8b95505d8de8b7191ae2ed8c504d4af
>>
>>
>> >
>> > Thanks,
>> >
>> > -liubo
>> >
>> >>
>> >> Traces here:
>> >> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
>> >> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
>> >> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
>> >> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
>> >> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
>> >> [<ffffffff810a0cbb>] kthread+0xdb/0x100
>> >> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
>> >> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
>> >> INFO: task mysqld:1977 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
>> >> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
>> >> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
>> >> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
>> >> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
>> >> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
>> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> INFO: task mysqld:3249 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
>> >> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
>> >> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
>> >> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03b4cb7>]
>> >> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
>> >> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
>> >> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
>> >> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
>> >> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
>> >> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
>> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> INFO: task mysqld:3250 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff881374edb868 0 3250 1 0x00080000
>> >> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
>> >> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
>> >> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
>> >> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
>> >> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
>> >> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
>> >> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
>> >> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
>> >> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
>> >> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
>> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> >> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
>> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> >> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
>> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> >> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
>> >> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
>> >> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
>> >> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
>> >> [<ffffffff811cee26>] __vfs_write+0x26/0x40
>> >> [<ffffffff811cf419>] vfs_write+0xa9/0x190
>> >> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
>> >> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
>> >> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
>> >> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
>> >> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
>> >> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
>> >> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
>> >> [<ffffffff810a0cbb>] kthread+0xdb/0x100
>> >> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
>> >> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
>> >> INFO: task mysqld:1977 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
>> >> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
>> >> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
>> >> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
>> >> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
>> >> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
>> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> INFO: task mysqld:3249 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff881475fdfa40 0 3249 1 0x00080000
>> >> ffff881475fdfa40 ffff88017367ca80 ffff8814433d2540 ffff881475fe0000
>> >> ffff88040da39ba0 0000000000230000 ffff88040da39c20 0000000000238000
>> >> ffff881475fdfa58 ffffffff816a8425 0000000000008000 ffff881475fdfb18
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03b4cb7>]
>> >> wait_ordered_extents.isra.18.constprop.23+0x147/0x3d0 [btrfs]
>> >> [<ffffffffc03b5182>] btrfs_log_changed_extents+0x242/0x610 [btrfs]
>> >> [<ffffffffc03ba6a4>] btrfs_log_inode+0x874/0xb80 [btrfs]
>> >> [<ffffffffc03bac6c>] btrfs_log_inode_parent+0x22c/0x910 [btrfs]
>> >> [<ffffffffc03bc292>] btrfs_log_dentry_safe+0x62/0x80 [btrfs]
>> >> [<ffffffffc038d0ec>] btrfs_sync_file+0x28c/0x3d0 [btrfs]
>> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> INFO: task mysqld:3250 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff881374edb868 0 3250 1 0x00080000
>> >> ffff881374edb868 ffff8801736b2540 ffff8814433d4a80 ffff881374edc000
>> >> ffff8814e26f81c8 ffff8814e26f81e0 0000000000238000 00000000000a8000
>> >> ffff881374edb880 ffffffff816a8425 ffff8814433d4a80 ffff881374edb8d8
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffff816aaffd>] rwsem_down_read_failed+0xed/0x130
>> >> [<ffffffff813ce404>] call_rwsem_down_read_failed+0x14/0x30
>> >> DWARF2 unwinder stuck at call_rwsem_down_read_failed+0x14/0x30
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> [<ffffffff816aa5a7>] ? down_read+0x17/0x20
>> >> [<ffffffffc0376cc6>] btrfs_create_dio_extent+0x46/0x1e0 [btrfs]
>> >> [<ffffffffc0386a68>] btrfs_get_blocks_direct+0x3d8/0x730 [btrfs]
>> >> [<ffffffffc0378b2e>] ? btrfs_submit_direct+0x1ce/0x740 [btrfs]
>> >> [<ffffffff8120b2c7>] do_blockdev_direct_IO+0x11f7/0x2bc0
>> >> [<ffffffffc0386690>] ? btrfs_page_exists_in_range+0xe0/0xe0 [btrfs]
>> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> >> [<ffffffff8120ccd3>] __blockdev_direct_IO+0x43/0x50
>> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> >> [<ffffffffc0377e11>] btrfs_direct_IO+0x1d1/0x380 [btrfs]
>> >> [<ffffffffc0378960>] ? btrfs_getattr+0xa0/0xa0 [btrfs]
>> >> [<ffffffff8115656a>] generic_file_direct_write+0xaa/0x170
>> >> [<ffffffffc038d4de>] btrfs_file_write_iter+0x2ae/0x560 [btrfs]
>> >> [<ffffffff810f73c1>] ? futex_wake+0x81/0x150
>> >> [<ffffffff811cedd4>] new_sync_write+0x84/0xb0
>> >> [<ffffffff811cee26>] __vfs_write+0x26/0x40
>> >> [<ffffffff811cf419>] vfs_write+0xa9/0x190
>> >> [<ffffffff810026af>] ? enter_from_user_mode+0x1f/0x50
>> >> [<ffffffff811d027b>] SyS_pwrite64+0x6b/0xa0
>> >> [<ffffffff81002b20>] ? syscall_return_slowpath+0xb0/0x130
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> INFO: task btrfs-transacti:604 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> btrfs-transacti D ffff8814e78cbe00 0 604 2 0x00080000
>> >> ffff8814e78cbe00 ffff88017367a540 ffff8814e2f88000 ffff8814e78cc000
>> >> ffff8814e78cbe38 ffff88123616c510 ffff8814e24c81f0 ffff88153fb0a000
>> >> ffff8814e78cbe18 ffffffff816a8425 ffff8814e63165a0 ffff8814e78cbe88
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03751a5>] btrfs_commit_transaction+0x275/0xa50 [btrfs]
>> >> [<ffffffffc036fdd6>] transaction_kthread+0x1d6/0x200 [btrfs]
>> >> [<ffffffff810a0cbb>] kthread+0xdb/0x100
>> >> [<ffffffff816ac84f>] ret_from_fork+0x3f/0x70
>> >> DWARF2 unwinder stuck at ret_from_fork+0x3f/0x70
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> [<ffffffff810a0be0>] ? kthread_park+0x60/0x60
>> >> INFO: task mysqld:1977 blocked for more than 120 seconds.
>> >> Not tainted 4.4.34 #1
>> >> "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
>> >> mysqld D ffff88142ef1bcf8 0 1977 1 0x00080000
>> >> ffff88142ef1bcf8 ffffffff81e0f500 ffff8814dc2c4a80 ffff88142ef1c000
>> >> ffff8814e32ed298 ffff8814e32ed2c0 ffff88110aa9a000 ffff8814e32ed000
>> >> ffff88142ef1bd10 ffffffff816a8425 ffff8814e32ed000 ffff88142ef1bd60
>> >> Call Trace:
>> >> [<ffffffff816a8425>] schedule+0x35/0x80
>> >> [<ffffffffc03b38a2>] wait_for_writer+0xa2/0xb0 [btrfs]
>> >> [<ffffffffc03bb439>] btrfs_sync_log+0xe9/0xa00 [btrfs]
>> >> [<ffffffffc038d1bf>] btrfs_sync_file+0x35f/0x3d0 [btrfs]
>> >> [<ffffffff8120055d>] vfs_fsync_range+0x3d/0xb0
>> >> [<ffffffff8120062d>] do_fsync+0x3d/0x70
>> >> [<ffffffff812008a0>] SyS_fsync+0x10/0x20
>> >> [<ffffffff816ac4ee>] entry_SYSCALL_64_fastpath+0x12/0x71
>> >> DWARF2 unwinder stuck at entry_SYSCALL_64_fastpath+0x12/0x71
>> >>
>> >> Leftover inexact backtrace:
>> >>
>> >> Greets,
>> >> Stefan
>> >>
>> >> >
>> >> > Signed-off-by: Liu Bo <bo.li.liu@oracle.com>
>> >> > Reviewed-by: Chris Mason <clm@fb.com>
>> >> > ---
>> >> > fs/btrfs/inode.c | 8 +++++---
>> >> > 1 file changed, 5 insertions(+), 3 deletions(-)
>> >> >
>> >> > diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
>> >> > index 2b790bd..48e9356 100644
>> >> > --- a/fs/btrfs/inode.c
>> >> > +++ b/fs/btrfs/inode.c
>> >> > @@ -7783,10 +7783,12 @@ static int btrfs_get_blocks_direct(struct inode *inode, sector_t iblock,
>> >> > }
>> >> >
>> >> > /*
>> >> > - * this will cow the extent, reset the len in case we changed
>> >> > - * it above
>> >> > + * this will cow the extent, if em is within [start, len], then
>> >> > + * probably we've found a preallocated/existing extent, let's
>> >> > + * give it a chance to use preallocated space.
>> >> > */
>> >> > - len = bh_result->b_size;
>> >> > + len = min_t(u64, bh_result->b_size, em->len - (start - em->start));
>> >> > + len = ALIGN(len, root->sectorsize);
>> >> > free_extent_map(em);
>> >> > em = btrfs_new_extent_direct(inode, start, len);
>> >> > if (IS_ERR(em)) {
>> >> >
>>
>>
>>
>> --
>> Filipe David Manana,
>>
>> "People will forget what you said,
>> people will forget what you did,
>> but people will never forget how you made them feel."
>> --
>> To unsubscribe from this list: send the line "unsubscribe linux-btrfs" in
>> the body of a message to majordomo@vger.kernel.org
>> More majordomo info at http://vger.kernel.org/majordomo-info.html
--
Filipe David Manana,
"People will forget what you said,
people will forget what you did,
but people will never forget how you made them feel."
^ permalink raw reply [flat|nested] 11+ messages in thread
* Re: resend: Re: Btrfs: adjust len of writes if following a preallocated extent
2016-12-02 12:25 ` Filipe Manana
@ 2016-12-16 22:37 ` Liu Bo
0 siblings, 0 replies; 11+ messages in thread
From: Liu Bo @ 2016-12-16 22:37 UTC (permalink / raw)
To: Filipe Manana
Cc: Stefan Priebe - Profihost AG, linux-btrfs@vger.kernel.org,
David Sterba, Josef Bacik
On Fri, Dec 02, 2016 at 12:25:19PM +0000, Filipe Manana wrote:
> On Fri, Dec 2, 2016 at 1:41 AM, Liu Bo <bo.li.liu@oracle.com> wrote:
> > On Thu, Nov 24, 2016 at 11:13:37AM +0000, Filipe Manana wrote:
> >> On Wed, Nov 23, 2016 at 9:22 PM, Liu Bo <bo.li.liu@oracle.com> wrote:
...
> >>
> >> The analysis is correct Bo.
> >> Originally to fix races between fsync and direct IO writes there was a
> >> solution [1, 2] that didn't involve adding a semaphore and relied on
> >> creating first the ordered extents and then the extent maps only in
> >> the direct IO write path (we do things in the reverse order everywhere
> >> else). It worked and was documented in comments but wasn't
> >> particularly elegant and Josef was not happy because of that, so then
> >> we added the semaphore and made direct IO write path create the extent
> >> maps and ordered extents in the same order as everywhere else [3].
> >>
> >> So here I can only see 2 simple solutions. Either revert [3] (which
> >> added the semaphore) or acquire the semaphore at a higher level in
> >> direct IO write path like this:
> >>
> >> diff --git a/fs/btrfs/inode.c b/fs/btrfs/inode.c
> >> index 1f980ef..b2c277d 100644
> >> --- a/fs/btrfs/inode.c
> >> +++ b/fs/btrfs/inode.c
> >> @@ -7237,7 +7237,6 @@ static struct extent_map
> >> *btrfs_create_dio_extent(struct inode *inode,
> >> struct extent_map *em = NULL;
> >> int ret;
> >>
> >> - down_read(&BTRFS_I(inode)->dio_sem);
> >> if (type != BTRFS_ORDERED_NOCOW) {
> >> em = create_pinned_em(inode, start, len, orig_start,
> >> block_start, block_len, orig_block_len,
> >> @@ -7256,8 +7255,6 @@ static struct extent_map
> >> *btrfs_create_dio_extent(struct inode *inode,
> >> em = ERR_PTR(ret);
> >> }
> >> out:
> >> - up_read(&BTRFS_I(inode)->dio_sem);
> >> -
> >> return em;
> >> }
> >>
> >> @@ -8715,11 +8712,14 @@ static ssize_t btrfs_direct_IO(struct kiocb
> >> *iocb, struct iov_iter *iter)
> >> wakeup = false;
> >> }
> >>
> >> + if (iov_iter_rw(iter) == WRITE)
> >> + down_read(&BTRFS_I(inode)->dio_sem);
> >> ret = __blockdev_direct_IO(iocb, inode,
> >>
> >> BTRFS_I(inode)->root->fs_info->fs_devices->latest_bdev,
> >> iter, btrfs_get_blocks_direct, NULL,
> >> btrfs_submit_direct, flags);
> >> if (iov_iter_rw(iter) == WRITE) {
> >> + up_read(&BTRFS_I(inode)->dio_sem);
> >> current->journal_info = NULL;
> >> if (ret < 0 && ret != -EIOCBQUEUED) {
> >> if (dio_data.reserve)
> >>
> >>
> >> Let me know what you think. Thanks.
> >
> > Hi Filipe,
> >
> > After going over again fs/direct-io.c, the AIO dio_complete is diffrent from the
> > 'Note that' part in your patch [1], what am I missing?
> >
> > -------------------------------------------------------------------------
> > static ssize_t dio_complete(struct dio *dio, ssize_t ret, bool is_async)
> > {
> > ...
> > if (!(dio->flags & DIO_SKIP_DIO_COUNT))
> > inode_dio_end(dio->inode);
> >
> > if (is_async) {
> > /*
> > * generic_write_sync expects ki_pos to have been updated
> > * already, but the submission path only does this for
> > * synchronous I/O.
> > */
> > dio->iocb->ki_pos += transferred;
> >
> > if (dio->op == REQ_OP_WRITE)
> > ret = generic_write_sync(dio->iocb, transferred);
> > dio->iocb->ki_complete(dio->iocb, ret, 0);
> > }
> > ...
> > }
>
> It's still the same as when I checked. The problem is that even after
> that call to inode_dio_end(), the inode->i_dio_count() is still
> non-zero (it's 1 iirc).
> I don't have any longer the debugging patch I used to find out that
> out (nor remember all the details), but I just tried again the
> approach of calling inode_dio_wait() in btrfs_sync_file() after
> locking the inode:
>
> https://friendpaste.com/pRwJkgsFXv6HglftK1BqH
>
> And the same deadlock ends up happening, which is trivial to reproduce
> with fstest generic/113:
>
...
> I don't have the time to go now figure out all the details of the aio
> code path again as I'm on vacation. But it's pretty evident that that
> solution doesn't work unfortunately.
All right...I've got the deadlock under space pressure, i.e. run
generic/113 with '-o fragment=data'.
I was not able to reproduce the deadlock with generic/113 after applying
'inode_dio_wait' in fsync, but I agree on not using 'inode_dio_wait'
approach because dio reads also contribute to inode->i_dio_count.
With the above patch that acquires the semaphore at a higher level
in direct IO write path, the deadlock now has gone away.
So would you please make a single patch? (It's also a good candidate
for stable kernel.)
Thanks,
-liubo
^ permalink raw reply [flat|nested] 11+ messages in thread
end of thread, other threads:[~2016-12-16 22:37 UTC | newest]
Thread overview: 11+ messages (download: mbox.gz follow: Atom feed
-- links below jump to the message on this page --
2016-11-04 19:20 [PATCH] Btrfs: adjust len of writes if following a preallocated extent Liu Bo
2016-11-22 19:59 ` Chris Mason
2016-11-23 15:54 ` NOC - Profihost AG
2016-11-23 17:21 ` resend: " Stefan Priebe - Profihost AG
2016-11-23 18:23 ` Holger Hoffstätte
2016-11-23 18:58 ` Stefan Priebe - Profihost AG
2016-11-23 21:22 ` Liu Bo
2016-11-24 11:13 ` Filipe Manana
2016-12-02 1:41 ` Liu Bo
2016-12-02 12:25 ` Filipe Manana
2016-12-16 22:37 ` Liu Bo
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox;
as well as URLs for NNTP newsgroup(s).