Skip to contentSkip to conversation

3.15-rc6 - btrfs-transacti:4157 blocked for more than 120 seconds.

DISCUSSION Torbjørn 5 participants 12 messages May 27, 2014 – Jun 5, 2014 1 message not in the archive Btrfs file system

lore
Share & tools
lore

Torbjørn

author
#0 lore raw

Hi,

Btrfs-transaction keeps blocking for me on all 3.15-rc versions.
3.14 does not have this issue.
The process never gets unstuck. btrfs fi sync does not help. A hard reboot seems to be the only way to recover.

The volume is still readable when it's in this state.

dmesg + sysrq-w is available at http://pastebin.com/vHQnRE2F
It's over 6000 lines, and would most likely not be allowed on the list.

The blocking happons on a server with local kvm-clients reading and writing to a local btrfs-volume over nfs. The btrfs-volume is on top of dm-crypt devices.

Any additional info I can give to help?
Tests you want me to run?

--
Torbjørn

--snip--

[138011.263478] INFO: task btrfs-transacti:4157 blocked for more than 120 seconds.
[138011.263558]       Tainted: G            E 3.15.0-rc6 #58
[138011.263605] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[138011.263687] btrfs-transacti D ffff88042fc94500     0  4157 2 0x00000000
[138011.263744]  ffff880400737e10 0000000000000002 ffff880403b33260 ffff880400737fd8
[138011.263831]  0000000000014500 0000000000014500 ffff88041973b260 ffff8802a9c97b40
[138011.263919]  ffff880403a0e800 ffff880400737e30 ffff8800c950ac00 ffff8800c950ac58
[138011.264007] Call Trace:
[138011.264045]  [<ffffffff816f81a9>] schedule+0x29/0x70
[138011.264097]  [<ffffffffa01a6f65>] btrfs_commit_transaction+0x315/0xa10 [btrfs]
[138011.264178]  [<ffffffff810acf40>] ? prepare_to_wait_event+0x100/0x100
[138011.264235]  [<ffffffffa01a2ea5>] transaction_kthread+0x1b5/0x240 [btrfs]
[138011.264293]  [<ffffffffa01a2cf0>] ? btrfs_cleanup_transaction+0x560/0x560 [btrfs]
[138011.264376]  [<ffffffff81088e72>] kthread+0xd2/0xf0
[138011.264422]  [<ffffffff81088da0>] ? kthread_create_on_node+0x190/0x190
[138011.264475]  [<ffffffff81704dfc>] ret_from_fork+0x7c/0xb0
[138011.264522]  [<ffffffff81088da0>] ? kthread_create_on_node+0x190/0x190

--snip--

#1 lore raw
Quoted 12 lines · Torbjørn

Hi,

Btrfs-transaction keeps blocking for me on all 3.15-rc versions. 3.14 does not have this issue.
The process never gets unstuck. btrfs fi sync does not help. A hard reboot seems to be the only way to recover.

The volume is still readable when it's in this state.

dmesg + sysrq-w is available at
https://urldefense.proofpoint.com/v1/url?u=http://pastebin.com/vHQnRE2F&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=6%2FL0lzzDhu0Y1hL9xm%2BQyA%3D%3D%0A&m=IKSs%2F0C3x9a0LIiVKFmZVoP9lSAZ%2BK9JgEkchLEAAzM%3D%0A&s=127b40cc34dbb205b5277e6081b082f26e84fc417d35310f3aeee04998a679a8

Quoted 8 lines

It's over 6000 lines, and would most likely not be allowed on the list.

The blocking happons on a server with local kvm-clients reading and writing to a local btrfs-volume over nfs.
The btrfs-volume is on top of dm-crypt devices.

Any additional info I can give to help?
Tests you want me to run?

Very strange, since I don't actually see what we're waiting for. Can you please either send me your btrfs.ko or use gdb to see where this statement is:

btrfs_commit_transaction+0x315

The syntax is

gdb btrfs.ko
gdb> list *btrfs_commit_transaction+0x315

-chris

A message that is not in the archive (sent off-list or not yet received): [email protected]

author
#3 lore raw
Quoted 48 lines · Torbjørn
Quoted 28 lines · Chris Mason
Quoted 13 lines · Torbjørn

Hi,

Btrfs-transaction keeps blocking for me on all 3.15-rc versions. 3.14 does not have this issue.
The process never gets unstuck. btrfs fi sync does not help. A hard reboot seems to be the only way to recover.

The volume is still readable when it's in this state.

dmesg + sysrq-w is available at
https://urldefense.proofpoint.com/v1/url?u=http://pastebin.com/vHQnRE2F&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=6%2FL0lzzDhu0Y1hL9xm%2BQyA%3D%3D%0A&m=IKSs%2F0C3x9a0LIiVKFmZVoP9lSAZ%2BK9JgEkchLEAAzM%3D%0A&s=127b40cc34dbb205b5277e6081b082f26e84fc417d35310f3aeee04998a679a8

Quoted 8 lines

It's over 6000 lines, and would most likely not be allowed on the list.

The blocking happons on a server with local kvm-clients reading and writing to a local btrfs-volume over nfs.
The btrfs-volume is on top of dm-crypt devices.

Any additional info I can give to help?
Tests you want me to run?

Very strange, since I don't actually see what we're waiting for. Can you please either send me your btrfs.ko or use gdb to see where this statement is:

Quoted 8 lines

btrfs_commit_transaction+0x315

The syntax is

gdb btrfs.ko
gdb> list *btrfs_commit_transaction+0x315

-chris

Sure, here you go.

Reading symbols from btrfs.ko...done.
(gdb) list *btrfs_commit_transaction+0x315
0x30f95 is in btrfs_commit_transaction (fs/btrfs/transaction.c:1752).
1747 * COMMIT_DOING so make sure to wait for num_writers to == 1 again.
1748 */

1749        spin_lock(&root->fs_info->trans_lock);
1750        cur_trans->state = TRANS_STATE_COMMIT_DOING;
1751        spin_unlock(&root->fs_info->trans_lock);
1752        wait_event(cur_trans->writer_wait,
Quoted 9 lines

1753 atomic_read(&cur_trans->num_writers) == 1);
1754
1755 /* ->aborted might be set after the previous check, so check it */
1756 if (unlikely(ACCESS_ONCE(cur_trans->aborted))) {
(gdb)

I'm attaching the btrfs.ko as well, hopefully the 20M file gets through.

Signature · 1 line
Torbjørn

Seems like the attachment stopped the email from reaching the list. Resending with only debug info.

--
Torbjørn

#4 lore raw
Quoted 57 lines · Torbjørn
Quoted 56 lines · Torbjørn
Quoted 28 lines · Chris Mason
Quoted 13 lines · Torbjørn

Hi,

Btrfs-transaction keeps blocking for me on all 3.15-rc versions. 3.14 does not have this issue.
The process never gets unstuck. btrfs fi sync does not help. A hard reboot seems to be the only way to recover.

The volume is still readable when it's in this state.

dmesg + sysrq-w is available at
https://urldefense.proofpoint.com/v1/url?u=http://pastebin.com/vHQnRE2F&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=6%2FL0lzzDhu0Y1hL9xm%2BQyA%3D%3D%0A&m=IKSs%2F0C3x9a0LIiVKFmZVoP9lSAZ%2BK9JgEkchLEAAzM%3D%0A&s=127b40cc34dbb205b5277e6081b082f26e84fc417d35310f3aeee04998a679a8

Quoted 8 lines

It's over 6000 lines, and would most likely not be allowed on the list.

The blocking happons on a server with local kvm-clients reading and writing to a local btrfs-volume over nfs.
The btrfs-volume is on top of dm-crypt devices.

Any additional info I can give to help?
Tests you want me to run?

Very strange, since I don't actually see what we're waiting for. Can you please either send me your btrfs.ko or use gdb to see where this statement is:

Quoted 8 lines

btrfs_commit_transaction+0x315

The syntax is

gdb btrfs.ko
gdb> list *btrfs_commit_transaction+0x315

-chris

Sure, here you go.

Reading symbols from btrfs.ko...done.
(gdb) list *btrfs_commit_transaction+0x315
0x30f95 is in btrfs_commit_transaction (fs/btrfs/transaction.c:1752).
1747 * COMMIT_DOING so make sure to wait for num_writers to ==
1 again.
1748 */

1749        spin_lock(&root->fs_info->trans_lock);
1750        cur_trans->state = TRANS_STATE_COMMIT_DOING;
1751        spin_unlock(&root->fs_info->trans_lock);
1752        wait_event(cur_trans->writer_wait,

1753 atomic_read(&cur_trans->num_writers) == 1);
1754
1755 /* ->aborted might be set after the previous check, so
check it */
1756 if (unlikely(ACCESS_ONCE(cur_trans->aborted))) {
(gdb)

Quoted 1 line
Quoted 1 line

I'm attaching the btrfs.ko as well, hopefully the 20M file gets through.

Thanks, this is enough. Someone has the transaction pegged open. Checking your sysrq again.

-chris

#5 lore raw
Quoted 58 lines · Chris Mason
Quoted 57 lines · Torbjørn
Quoted 56 lines · Torbjørn
Quoted 28 lines · Chris Mason
Quoted 13 lines · Torbjørn

Hi,

Btrfs-transaction keeps blocking for me on all 3.15-rc versions. 3.14 does not have this issue.
The process never gets unstuck. btrfs fi sync does not help. A hard reboot seems to be the only way to recover.

The volume is still readable when it's in this state.

dmesg + sysrq-w is available at
https://urldefense.proofpoint.com/v1/url?u=http://pastebin.com/vHQnRE2F&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=6%2FL0lzzDhu0Y1hL9xm%2BQyA%3D%3D%0A&m=IKSs%2F0C3x9a0LIiVKFmZVoP9lSAZ%2BK9JgEkchLEAAzM%3D%0A&s=127b40cc34dbb205b5277e6081b082f26e84fc417d35310f3aeee04998a679a8

Quoted 8 lines

It's over 6000 lines, and would most likely not be allowed on the list.

The blocking happons on a server with local kvm-clients reading and writing to a local btrfs-volume over nfs.
The btrfs-volume is on top of dm-crypt devices.

Any additional info I can give to help?
Tests you want me to run?

Very strange, since I don't actually see what we're waiting for. Can you please either send me your btrfs.ko or use gdb to see where this statement is:

Quoted 8 lines

btrfs_commit_transaction+0x315

The syntax is

gdb btrfs.ko
gdb> list *btrfs_commit_transaction+0x315

-chris

Sure, here you go.

Reading symbols from btrfs.ko...done.
(gdb) list *btrfs_commit_transaction+0x315
0x30f95 is in btrfs_commit_transaction (fs/btrfs/transaction.c:1752).
1747 * COMMIT_DOING so make sure to wait for num_writers to ==
1 again.
1748 */

1749        spin_lock(&root->fs_info->trans_lock);
1750        cur_trans->state = TRANS_STATE_COMMIT_DOING;
1751        spin_unlock(&root->fs_info->trans_lock);
1752        wait_event(cur_trans->writer_wait,

1753 atomic_read(&cur_trans->num_writers) == 1);
1754
1755 /* ->aborted might be set after the previous check, so
check it */
1756 if (unlikely(ACCESS_ONCE(cur_trans->aborted))) {
(gdb)

Quoted 1 line
Quoted 1 line
Quoted 1 line

I'm attaching the btrfs.ko as well, hopefully the 20M file gets through.

Ok, we're stuck here. The transaction won't coomplete until this disk IO is done.

Since this is just a read, are you able to read from the device when this is happening? This would be the dm-crypt block device w/btrfs on it.

[180625.987870] kworker/u16:12  D ffff88042fd94500     0 15271      2 0x00000000 
[180625.987935] Workqueue: btrfs-delalloc normal_work_helper [btrfs]
[180625.987987]  ffff880107a4f648 0000000000000002 ffff88001383b260 ffff880107a4ffd8
[180625.988075]  0000000000014500 0000000000014500 ffff880419749930 ffff88042fd94e18
[180625.988163]  ffff88042ffadce8 0000000000000002 ffffffff8114df40 ffff880107a4f6c0
[180625.988251] Call Trace:
[180625.988291]  [<ffffffff8114df40>] ? wait_on_page_read+0x60/0x60
[180625.988342]  [<ffffffff816f84cd>] io_schedule+0x9d/0x140
[180625.988391]  [<ffffffff8114df4e>] sleep_on_page+0xe/0x20
[180625.988440]  [<ffffffff816f8962>] __wait_on_bit+0x62/0x90
[180625.988490]  [<ffffffff8114dd0f>] wait_on_page_bit+0x7f/0x90
[180625.988541]  [<ffffffff810acf80>] ? autoremove_wake_function+0x40/0x40
[180625.988601]  [<ffffffffa01c8e8a>] read_extent_buffer_pages+0x2ca/0x300 [btrfs]
[180625.988687]  [<ffffffffa019dd70>] ? free_root_pointers+0x60/0x60 [btrfs]
[180625.988746]  [<ffffffffa019efa3>] btree_read_extent_buffer_pages.constprop.52+0xb3/0x120 [btrfs]
[180625.988839]  [<ffffffffa01a00c8>] read_tree_block+0x38/0x60 [btrfs]
[180625.988895]  [<ffffffffa01828c8>] read_block_for_search.isra.33+0x148/0x380 [btrfs]
[180625.988983]  [<ffffffffa0187f97>] btrfs_next_old_leaf+0x297/0x4a0 [btrfs]
[180625.989041]  [<ffffffffa01881b0>] btrfs_next_leaf+0x10/0x20 [btrfs]
[180625.989099]  [<ffffffffa01cdc9c>] find_free_dev_extent+0xbc/0x350 [btrfs]
[180625.989159]  [<ffffffffa01ce0e4>] __btrfs_alloc_chunk+0x1b4/0x770 [btrfs]
[180625.989214]  [<ffffffff8101ad25>] ? native_sched_clock+0x35/0x90
[180625.989265]  [<ffffffff811bef49>] ? __sb_start_write+0x49/0xe0
[180625.989322]  [<ffffffffa01d0b94>] btrfs_alloc_chunk+0x34/0x40 [btrfs]
[180625.989380]  [<ffffffffa018f9fe>] do_chunk_alloc+0x23e/0x410 [btrfs]
[180625.989438]  [<ffffffffa0194753>] find_free_extent+0xb03/0xbb0 [btrfs]
[180625.989496]  [<ffffffffa01949d8>] btrfs_reserve_extent+0xa8/0x1a0 [btrfs]
[180625.989555]  [<ffffffffa01ad9f5>] cow_file_range+0x135/0x440 [btrfs]
[180625.989613]  [<ffffffffa01aecff>] submit_compressed_extents+0x1bf/0x480 [btrfs]
[180625.989700]  [<ffffffffa01ac804>] ? async_cow_free+0x24/0x30 [btrfs]
[180625.989758]  [<ffffffffa01aefc0>] ? submit_compressed_extents+0x480/0x480 [btrfs]
[180625.989845]  [<ffffffffa01af046>] async_cow_submit+0x86/0x90 [btrfs]
[180625.989904]  [<ffffffffa01d5333>] normal_work_helper+0x193/0x2b0 [btrfs]
[180625.989957]  [<ffffffff81081532>] process_one_work+0x182/0x450
[180625.990008]  [<ffffffff81082331>] worker_thread+0x121/0x410
[180625.990058]  [<ffffffff81082210>] ? rescuer_thread+0x430/0x430
[180625.990109]  [<ffffffff81088e72>] kthread+0xd2/0xf0
[180625.990156]  [<ffffffff81088da0>] ? kthread_create_on_node+0x190/0x190
[180625.990210]  [<ffffffff81704dfc>] ret_from_fork+0x7c/0xb0
[180625.990259]  [<ffffffff81088da0>] ? kthread_create_on_node+0x190/0x190
author
#6 lore raw
Quoted 97 lines · Chris Mason
Quoted 57 lines · Chris Mason
Quoted 56 lines · Torbjørn
Quoted 55 lines · Torbjørn
Quoted 27 lines · Chris Mason
Quoted 13 lines · Torbjørn

Hi,

Btrfs-transaction keeps blocking for me on all 3.15-rc versions. 3.14 does not have this issue.
The process never gets unstuck. btrfs fi sync does not help. A hard reboot seems to be the only way to recover.

The volume is still readable when it's in this state.

dmesg + sysrq-w is available at
https://urldefense.proofpoint.com/v1/url?u=http://pastebin.com/vHQnRE2F&k=ZVNjlDMF0FElm4dQtryO4A%3D%3D%0A&r=6%2FL0lzzDhu0Y1hL9xm%2BQyA%3D%3D%0A&m=IKSs%2F0C3x9a0LIiVKFmZVoP9lSAZ%2BK9JgEkchLEAAzM%3D%0A&s=127b40cc34dbb205b5277e6081b082f26e84fc417d35310f3aeee04998a679a8

Quoted 8 lines

It's over 6000 lines, and would most likely not be allowed on the list.

The blocking happons on a server with local kvm-clients reading and writing to a local btrfs-volume over nfs.
The btrfs-volume is on top of dm-crypt devices.

Any additional info I can give to help?
Tests you want me to run?

Very strange, since I don't actually see what we're waiting for. Can you please either send me your btrfs.ko or use gdb to see where this statement is:

Quoted 8 lines

btrfs_commit_transaction+0x315

The syntax is

gdb btrfs.ko
gdb> list *btrfs_commit_transaction+0x315

-chris

Sure, here you go.

Reading symbols from btrfs.ko...done.
(gdb) list *btrfs_commit_transaction+0x315
0x30f95 is in btrfs_commit_transaction (fs/btrfs/transaction.c:1752).
1747 * COMMIT_DOING so make sure to wait for num_writers to ==
1 again.
1748 */

1749        spin_lock(&root->fs_info->trans_lock);
1750        cur_trans->state = TRANS_STATE_COMMIT_DOING;
1751        spin_unlock(&root->fs_info->trans_lock);
1752        wait_event(cur_trans->writer_wait,

1753 atomic_read(&cur_trans->num_writers) == 1);
1754
1755 /* ->aborted might be set after the previous check, so
check it */
1756 if (unlikely(ACCESS_ONCE(cur_trans->aborted))) {
(gdb)

Quoted 1 line
Quoted 1 line
Quoted 1 line

I'm attaching the btrfs.ko as well, hopefully the 20M file gets through.

Ok, we're stuck here. The transaction won't coomplete until this disk IO is done.

Since this is just a read, are you able to read from the device when this is happening? This would be the dm-crypt block device w/btrfs on it.

[180625.987870] kworker/u16:12  D ffff88042fd94500     0 15271      2 0x00000000
[180625.987935] Workqueue: btrfs-delalloc normal_work_helper [btrfs]
[180625.987987]  ffff880107a4f648 0000000000000002 ffff88001383b260 ffff880107a4ffd8
[180625.988075]  0000000000014500 0000000000014500 ffff880419749930 ffff88042fd94e18
[180625.988163]  ffff88042ffadce8 0000000000000002 ffffffff8114df40 ffff880107a4f6c0
[180625.988251] Call Trace:
[180625.988291]  [<ffffffff8114df40>] ? wait_on_page_read+0x60/0x60
[180625.988342]  [<ffffffff816f84cd>] io_schedule+0x9d/0x140
[180625.988391]  [<ffffffff8114df4e>] sleep_on_page+0xe/0x20
[180625.988440]  [<ffffffff816f8962>] __wait_on_bit+0x62/0x90
[180625.988490]  [<ffffffff8114dd0f>] wait_on_page_bit+0x7f/0x90
[180625.988541]  [<ffffffff810acf80>] ? autoremove_wake_function+0x40/0x40
[180625.988601]  [<ffffffffa01c8e8a>] read_extent_buffer_pages+0x2ca/0x300 [btrfs]
[180625.988687]  [<ffffffffa019dd70>] ? free_root_pointers+0x60/0x60 [btrfs]
[180625.988746]  [<ffffffffa019efa3>] btree_read_extent_buffer_pages.constprop.52+0xb3/0x120 [btrfs]
[180625.988839]  [<ffffffffa01a00c8>] read_tree_block+0x38/0x60 [btrfs]
[180625.988895]  [<ffffffffa01828c8>] read_block_for_search.isra.33+0x148/0x380 [btrfs]
[180625.988983]  [<ffffffffa0187f97>] btrfs_next_old_leaf+0x297/0x4a0 [btrfs]
[180625.989041]  [<ffffffffa01881b0>] btrfs_next_leaf+0x10/0x20 [btrfs]
[180625.989099]  [<ffffffffa01cdc9c>] find_free_dev_extent+0xbc/0x350 [btrfs]
[180625.989159]  [<ffffffffa01ce0e4>] __btrfs_alloc_chunk+0x1b4/0x770 [btrfs]
[180625.989214]  [<ffffffff8101ad25>] ? native_sched_clock+0x35/0x90
[180625.989265]  [<ffffffff811bef49>] ? __sb_start_write+0x49/0xe0
[180625.989322]  [<ffffffffa01d0b94>] btrfs_alloc_chunk+0x34/0x40 [btrfs]
[180625.989380]  [<ffffffffa018f9fe>] do_chunk_alloc+0x23e/0x410 [btrfs]
[180625.989438]  [<ffffffffa0194753>] find_free_extent+0xb03/0xbb0 [btrfs]
[180625.989496]  [<ffffffffa01949d8>] btrfs_reserve_extent+0xa8/0x1a0 [btrfs]
[180625.989555]  [<ffffffffa01ad9f5>] cow_file_range+0x135/0x440 [btrfs]
[180625.989613]  [<ffffffffa01aecff>] submit_compressed_extents+0x1bf/0x480 [btrfs]
[180625.989700]  [<ffffffffa01ac804>] ? async_cow_free+0x24/0x30 [btrfs]
[180625.989758]  [<ffffffffa01aefc0>] ? submit_compressed_extents+0x480/0x480 [btrfs]
[180625.989845]  [<ffffffffa01af046>] async_cow_submit+0x86/0x90 [btrfs]
Quoted 9 lines
[180625.989904]  [<ffffffffa01d5333>] normal_work_helper+0x193/0x2b0 [btrfs]
[180625.989957]  [<ffffffff81081532>] process_one_work+0x182/0x450
[180625.990008]  [<ffffffff81082331>] worker_thread+0x121/0x410
[180625.990058]  [<ffffffff81082210>] ? rescuer_thread+0x430/0x430
[180625.990109]  [<ffffffff81088e72>] kthread+0xd2/0xf0
[180625.990156]  [<ffffffff81088da0>] ? kthread_create_on_node+0x190/0x190
[180625.990210]  [<ffffffff81704dfc>] ret_from_fork+0x7c/0xb0
[180625.990259]  [<ffffffff81088da0>] ? kthread_create_on_node+0x190/0x190

It's actually a raid10 array of 11 dm-crypt devices.
I'm able to read data from the array (accessing files), and also read directly from all the underlying dm-crypt devices using dd, if that's what you meant.

I have not rebooted the system since that dmesg, so it's still stuck in the same state. I can keep it like that for some days. The system is not critical at all.

--
Torbjørn

#7 lore raw
Quoted 9 lines · Torbjørn

It's actually a raid10 array of 11 dm-crypt devices.
I'm able to read data from the array (accessing files), and also read directly from all the underlying dm-crypt devices using dd, if that's what you meant.

I have not rebooted the system since that dmesg, so it's still stuck in the same state.
I can keep it like that for some days. The system is not critical at all.

Thanks,

Can you please capture the result of sysrq-t and sysrq-l? Maybe the IO is stuck in a thread that isn't in the D state.

-chris

author
#8 lore raw
Quoted 11 lines · Chris Mason
Quoted 9 lines · Torbjørn

It's actually a raid10 array of 11 dm-crypt devices.
I'm able to read data from the array (accessing files), and also read directly from all the underlying dm-crypt devices using dd, if that's what you meant.

I have not rebooted the system since that dmesg, so it's still stuck in the same state.
I can keep it like that for some days. The system is not critical at all.

Quoted 6 lines

Thanks,

Can you please capture the result of sysrq-t and sysrq-l? Maybe the IO is stuck in a thread that isn't in the D state.

-chris

The output of sysrq-t was too much data for pastebin, will send both to you as attachments outside of the list.

--
Torbjørn

#9 lore raw
Quoted 12 lines · Torbjørn
Quoted 11 lines · Chris Mason
Quoted 9 lines · Torbjørn

It's actually a raid10 array of 11 dm-crypt devices.
I'm able to read data from the array (accessing files), and also read directly from all the underlying dm-crypt devices using dd, if that's what you meant.

I have not rebooted the system since that dmesg, so it's still stuck in the same state.
I can keep it like that for some days. The system is not critical at all.

Quoted 8 lines
Quoted 6 lines

Thanks,

Can you please capture the result of sysrq-t and sysrq-l? Maybe the IO is stuck in a thread that isn't in the D state.

-chris

The output of sysrq-t was too much data for pastebin, will send both to you as attachments outside of the list.

Considering I have experienced this with with 3.15rc but wasn't able to save a sysrq since my save file and syslog got lost, did you find out anything from that?

Thanks,
Marc

Signature · 4 lines
"A mouse is a device used to point at the xterm you want to type in" - A.S.R.
Microsoft is to operating systems ....
                                      .... what McDonalds is to gourmet cooking
Home page: http://marc.merlins.org/                         | PGP 1024R/763BE901
#10 lore raw

Hi,

I'm getting "blocked for more than 120 seconds" messages too.

In my case, it is for a simple RAID1 volume that is rebuilding for the first time (new volume), whilst mounted as a LUKS crypt volume and writing /dev/zero before actual deployment.

I am running a stock Wheezy kernel:

~ # uname -a
Linux n4800eco-a 3.2.0-4-amd64 #1 SMP Debian 3.2.57-3 x86_64 GNU/Linux

As I am deliberately NOT running btrfs, the common link may be mdadm or LUKS.

I'm also noticing btrfs modules being loaded on another box, even though I am not at all ready to trust btrfs for any file system at this time.

There may be some bug with mdadm/crypt(LUKS)/btrfs -- or it may have nothing to do with btrfs. My problem almost certainly isn't btrfs unless there is some kernel code giving me grief without loading the btrfs module.

More details of my problem:

https://lists.debian.org/debian-user/2014/06/msg00070.html

NB: working through my problem in a dropbear busybox environment that hasn't loaded btrfs module. The kernel is the same as the /normal/ system, compliments of mkinitramfs tool....

Cheers
A.

author
#11 lore raw
In reply to Marc MERLIN
Quoted 19 lines · Marc MERLIN
Quoted 18 lines · Torbjørn
Quoted 17 lines · Chris Mason
Quoted 9 lines · Torbjørn

It's actually a raid10 array of 11 dm-crypt devices.
I'm able to read data from the array (accessing files), and also read directly from all the underlying dm-crypt devices using dd, if that's what you meant.

I have not rebooted the system since that dmesg, so it's still stuck in the same state.
I can keep it like that for some days. The system is not critical at all.

Thanks,

Can you please capture the result of sysrq-t and sysrq-l? Maybe the IO is stuck in a thread that isn't in the D state.

-chris

Quoted 8 lines
Quoted 2 lines

The output of sysrq-t was too much data for pastebin, will send both to you as attachments outside of the list.

Considering I have experienced this with with 3.15rc but wasn't able to save a sysrq since my save file and syslog got lost, did you find out anything from that?

Thanks,
Marc

Hi Marc,

I have not done any real investigation of those yet, so no.

The server is mainly for testing, so I had already netconsole set up for it.
Btrfs only blocked on the one array though. Root is btrfs raid1 with 2 devices, and it was operating as normal.

If it's of any interest, I can make the captured logs available for download.

--
Torbjørn

#12 lore raw
In reply to Marc MERLIN

I am also getting this...

My system is configured like so:

3.15.0-rc8
Btrfs v3.12

#btrfs fi show
Label: none uuid: e421ceeb-6e4e-4c7e-84b4-6f25442745fa

	Total devices 1 FS bytes used 22.51GiB
	devid    1 size 116.75GiB used 28.02GiB path /dev/sda4

Label: tank uuid: 52044d1c-5308-40f7-9d21-4edca3b63d05

	Total devices 5 FS bytes used 1.87TiB
	devid    2 size 931.51GiB used 367.00GiB path /dev/sdc
	devid    3 size 931.51GiB used 366.00GiB path /dev/sdf
	devid    4 size 2.73TiB used 1.88TiB path /dev/sde
	devid    5 size 1.36TiB used 833.00GiB path /dev/sdd
	devid    6 size 931.51GiB used 364.03GiB path /dev/sdb

/tank is the filesystem giving the trouble. Here's the df for it:

Data, RAID1: total=1.88TiB, used=1.87TiB
System, RAID1: total=32.00MiB, used=276.00KiB
Metadata, RAID1: total=4.00GiB, used=2.84GiB
unknown, single: total=512.00MiB, used=0.00

It is just a raid 1, zlib-compressed. No encryption.

If I do any kind of large file transfers (large amounts OR many files, not sure what aspect causes it) with it, the following happens:

My load average shoots up to HUGE numbers, the filesystem becomes unusable although directories are still readable that do not have files that are being accessed in them, and the dmesg begins filling with:

Jun  5 06:55:40 maul kernel: [  361.276631] INFO: task kworker/u8:0:6
blocked for more than 120 seconds.
Jun  5 06:55:40 maul kernel: [  361.276640]       Not tainted 3.15.0-rc8 #1
Jun  5 06:55:40 maul kernel: [  361.276644] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun  5 06:55:40 maul kernel: [  361.276649] kworker/u8:0    D
0000000000000000     0     6      2 0x00000000
Jun  5 06:55:40 maul kernel: [  361.276665] Workqueue: writeback
bdi_writeback_workfn (flush-btrfs-2)
Jun  5 06:55:40 maul kernel: [  361.276671]  ffff8802331c79f8
0000000000000002 ffff8802331c8000 ffff8802331c7fd8
Jun  5 06:55:40 maul kernel: [  361.276679]  00000000000147c0
00000000000147c0 ffff880233226540 ffff8802331c8000
Jun  5 06:55:40 maul kernel: [  361.276686]  ffff88023ed150d8
ffff88023efdeb68 ffff8802331c7a80 0000000000000002
Jun  5 06:55:40 maul kernel: [  361.276693] Call Trace:
Jun  5 06:55:40 maul kernel: [  361.276706]  [<ffffffff8114a1d0>] ?
wait_on_page_read+0x60/0x60
Jun  5 06:55:40 maul kernel: [  361.276714]  [<ffffffff817aeb9f>]
io_schedule+0xaf/0x150
Jun  5 06:55:40 maul kernel: [  361.276721]  [<ffffffff8114a1de>]
sleep_on_page+0xe/0x20
Jun  5 06:55:40 maul kernel: [  361.276727]  [<ffffffff817af213>]
__wait_on_bit_lock+0x53/0xb0
Jun  5 06:55:40 maul kernel: [  361.276734]  [<ffffffff8114a2fa>]
__lock_page+0x6a/0x70
Jun  5 06:55:40 maul kernel: [  361.276741]  [<ffffffff810a4430>] ?
autoremove_wake_function+0x40/0x40
Jun  5 06:55:40 maul kernel: [  361.276749]  [<ffffffff8131579e>] ?
flush_write_bio+0xe/0x10
Jun  5 06:55:40 maul kernel: [  361.276756]  [<ffffffff81319d50>]
extent_write_cache_pages.isra.28.constprop.50+0x230/0x350
Jun  5 06:55:40 maul kernel: [  361.276763]  [<ffffffff8109cb33>] ?
find_busiest_group+0x133/0x830
Jun  5 06:55:40 maul kernel: [  361.276771]  [<ffffffff8131b06c>]
extent_writepages+0x4c/0x60
Jun  5 06:55:40 maul kernel: [  361.276779]  [<ffffffff812fecb0>] ?
btrfs_writepage_end_io_hook+0x190/0x190
Jun  5 06:55:40 maul kernel: [  361.276785]  [<ffffffff817b7134>] ?
preempt_count_add+0x54/0xa0
Jun  5 06:55:40 maul kernel: [  361.276791]  [<ffffffff812fc178>]
btrfs_writepages+0x28/0x30
Jun  5 06:55:40 maul kernel: [  361.276798]  [<ffffffff81157dfe>]
do_writepages+0x1e/0x40
Jun  5 06:55:40 maul kernel: [  361.276805]  [<ffffffff811ea2d0>]
__writeback_single_inode+0x40/0x2a0
Jun  5 06:55:40 maul kernel: [  361.276812]  [<ffffffff811ed4ff>]
writeback_sb_inodes+0x23f/0x3f0
Jun  5 06:55:40 maul kernel: [  361.276821]  [<ffffffff811ed747>]
__writeback_inodes_wb+0x97/0xd0
Jun  5 06:55:40 maul kernel: [  361.276828]  [<ffffffff811ed97b>]
wb_writeback+0x1fb/0x310
Jun  5 06:55:40 maul kernel: [  361.276836]  [<ffffffff811eddd6>]
bdi_writeback_workfn+0x1d6/0x490
Jun  5 06:55:40 maul kernel: [  361.276844]  [<ffffffff810779c8>]
process_one_work+0x178/0x4b0
Jun  5 06:55:40 maul kernel: [  361.276850]  [<ffffffff81078731>]
worker_thread+0x131/0x3d0
Jun  5 06:55:40 maul kernel: [  361.276856]  [<ffffffff81078600>] ?
manage_workers.isra.25+0x2c0/0x2c0
Jun  5 06:55:40 maul kernel: [  361.276863]  [<ffffffff8107eabb>]
kthread+0xdb/0x100
Jun  5 06:55:40 maul kernel: [  361.276871]  [<ffffffff8107e9e0>] ?
kthread_create_on_node+0x190/0x190
Jun  5 06:55:40 maul kernel: [  361.276878]  [<ffffffff817bb7fc>]
ret_from_fork+0x7c/0xb0
Jun  5 06:55:40 maul kernel: [  361.276884]  [<ffffffff8107e9e0>] ?
kthread_create_on_node+0x190/0x190
Jun  5 06:55:40 maul kernel: [  361.276896] INFO: task kworker/u8:1:55
blocked for more than 120 seconds.
Jun  5 06:55:40 maul kernel: [  361.276900]       Not tainted 3.15.0-rc8 #1
Jun  5 06:55:40 maul kernel: [  361.276903] "echo 0 >
/proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun  5 06:55:40 maul kernel: [  361.276906] kworker/u8:1    D
ffffffff814231d7     0    55      2 0x00000000
Jun  5 06:55:40 maul kernel: [  361.276916] Workqueue: btrfs-cache
normal_work_helper
Jun  5 06:55:40 maul kernel: [  361.276919]  ffff880232ed3c60
0000000000000002 ffff880232e11950 ffff880232ed3fd8
Jun  5 06:55:40 maul kernel: [  361.276927]  00000000000147c0
00000000000147c0 ffff88022def9950 ffff880232e11950
Jun  5 06:55:40 maul kernel: [  361.276933]  ffff880232e11950
ffff88022f75c680 ffff88022f75c688 0000000000000040
Jun  5 06:55:40 maul kernel: [  361.276940] Call Trace:
Jun  5 06:55:40 maul kernel: [  361.276949]  [<ffffffff817ae839>]
schedule+0x29/0x70
Jun  5 06:55:40 maul kernel: [  361.276955]  [<ffffffff817b19a5>]
rwsem_down_read_failed+0xc5/0x160
Jun  5 06:55:40 maul kernel: [  361.276962]  [<ffffffff812da77c>] ?
btrfs_next_old_leaf+0x1dc/0x4a0
Jun  5 06:55:40 maul kernel: [  361.276971]  [<ffffffff814191f4>]
call_rwsem_down_read_failed+0x14/0x30
Jun  5 06:55:40 maul kernel: [  361.276979]  [<ffffffff817b13b7>] ?
down_read+0x17/0x20
Jun  5 06:55:40 maul kernel: [  361.276985]  [<ffffffff812dfc5b>]
caching_thread+0xeb/0x490
Jun  5 06:55:40 maul kernel: [  361.276993]  [<ffffffff8132960f>]
normal_work_helper+0x12f/0x310
Jun  5 06:55:40 maul kernel: [  361.276999]  [<ffffffff810779c8>]
process_one_work+0x178/0x4b0
Jun  5 06:55:40 maul kernel: [  361.277005]  [<ffffffff81078731>]
worker_thread+0x131/0x3d0
Jun  5 06:55:40 maul kernel: [  361.277011]  [<ffffffff81078600>] ?
manage_workers.isra.25+0x2c0/0x2c0
Jun  5 06:55:40 maul kernel: [  361.277018]  [<ffffffff8107eabb>]
kthread+0xdb/0x100
Jun  5 06:55:40 maul kernel: [  361.277025]  [<ffffffff8107e9e0>] ?
kthread_create_on_node+0x190/0x190
Jun  5 06:55:40 maul kernel: [  361.277032]  [<ffffffff817bb7fc>]
ret_from_fork+0x7c/0xb0
Jun  5 06:55:40 maul kernel: [  361.277039]  [<ffffffff8107e9e0>] ?

kthread_create_on_node+0x190/0x190

This had all seemed to be fine in kernel 3.13.

Peace,
Gary