xfstest269 causes deadlock on linux-3.9.0 (ext4)

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
  PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
    1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
    2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
    3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
 2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
   PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
     1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
     2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
     3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
  2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Hi,

Quoted 48 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
    PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
      1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
      2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
      3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
   2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Quoted 7 lines

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Thanks for reply.
I'll take that information when the deadlock happens again.

Hi Jan,

Quoted 59 lines · Akira Fujita

Hi,

Quoted 55 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
    PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
      1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
      2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
      3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
   2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Quoted 2 lines

Thanks for reply.
I'll take that information when the deadlock happens again.

Finally, I got the following messages on linux-3.9.0. Could you take a look?

#echo w > /proc/sysrq-trigger
/var/log/messages:
-----------------------

May 23 19:15:50 mcds1 kernel: [210728.230978] SysRq : Show Blocked State
May 23 19:15:50 mcds1 kernel: [210728.230985]   task                        PC stack   pid father
May 23 19:15:50 mcds1 kernel: [210728.230992] flush-8:0       D ffffffff81806d60  3192  2361      2 0x00000000
May 23 19:15:50 mcds1 kernel: [210728.230997]  ffff880214d27a08 0000000000000046 0000000000000282 ffff88021608d330
May 23 19:15:50 mcds1 kernel: [210728.231001]  0000000000000000 ffff880215d95ac0 0000000000012980 ffff880214d27fd8
May 23 19:15:50 mcds1 kernel: [210728.231005]  ffff880214d26010 0000000000012980 0000000000012980 ffff880214d27fd8
May 23 19:15:50 mcds1 kernel: [210728.231008] Call Trace:
May 23 19:15:50 mcds1 kernel: [210728.231018]  [<ffffffff81798ae4>] schedule+0x24/0x70
May 23 19:15:50 mcds1 kernel: [210728.231023]  [<ffffffff81204b95>] jbd2_log_wait_commit+0xb5/0x130
May 23 19:15:50 mcds1 kernel: [210728.231029]  [<ffffffff81060830>] ? wake_up_bit+0x40/0x40
May 23 19:15:50 mcds1 kernel: [210728.231033]  [<ffffffff81204cb4>] ? __jbd2_log_start_commit+0xa4/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231037]  [<ffffffff81204e4b>] jbd2_journal_force_commit_nested+0x5b/0xa0
May 23 19:15:50 mcds1 kernel: [210728.231041]  [<ffffffff811b75c8>] ext4_da_writepages+0x348/0x5a0
May 23 19:15:50 mcds1 kernel: [210728.231045]  [<ffffffff81074e77>] ? check_preempt_wakeup+0x1b7/0x2a0
May 23 19:15:50 mcds1 kernel: [210728.231051]  [<ffffffff810f0f5b>] do_writepages+0x1b/0x30
May 23 19:15:50 mcds1 kernel: [210728.231056]  [<ffffffff8115d9d4>] __writeback_single_inode+0x44/0x220
May 23 19:15:50 mcds1 kernel: [210728.231061]  [<ffffffff8115e93f>] writeback_sb_inodes+0x23f/0x430
May 23 19:15:50 mcds1 kernel: [210728.231065]  [<ffffffff8115ed6d>] wb_writeback+0xed/0x2b0
May 23 19:15:50 mcds1 kernel: [210728.231071]  [<ffffffff8104c537>] ? lock_timer_base+0x37/0x70
May 23 19:15:50 mcds1 kernel: [210728.231075]  [<ffffffff8115efcd>] wb_do_writeback+0x9d/0x240
May 23 19:15:50 mcds1 kernel: [210728.231079]  [<ffffffff8104c570>] ? lock_timer_base+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231084]  [<ffffffff8115f212>] bdi_writeback_thread+0xa2/0x230
May 23 19:15:50 mcds1 kernel: [210728.231088]  [<ffffffff8115f170>] ? wb_do_writeback+0x240/0x240
May 23 19:15:50 mcds1 kernel: [210728.231092]  [<ffffffff8115f170>] ? wb_do_writeback+0x240/0x240
May 23 19:15:50 mcds1 kernel: [210728.231095]  [<ffffffff81060136>] kthread+0xc6/0xd0
May 23 19:15:50 mcds1 kernel: [210728.231099]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231104]  [<ffffffff817a19ac>] ret_from_fork+0x7c/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231108]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231124] jbd2/sda12-8    D ffffffff81806d60  4736 25056      2 0x00000000
May 23 19:15:50 mcds1 kernel: [210728.231128]  ffff8801e436db78 0000000000000046 ffff880215c06f00 ffffffff81c10420
May 23 19:15:50 mcds1 kernel: [210728.231131]  ffff880200011200 ffff8801f8f296b0 0000000000012980 ffff8801e436dfd8
May 23 19:15:50 mcds1 kernel: [210728.231135]  ffff8801e436c010 0000000000012980 0000000000012980 ffff8801e436dfd8
May 23 19:15:50 mcds1 kernel: [210728.231138] Call Trace:
May 23 19:15:50 mcds1 kernel: [210728.231142]  [<ffffffff81166c50>] ? __wait_on_buffer+0x30/0x30
May 23 19:15:50 mcds1 kernel: [210728.231146]  [<ffffffff81798ae4>] schedule+0x24/0x70
May 23 19:15:50 mcds1 kernel: [210728.231150]  [<ffffffff81798bb7>] io_schedule+0x87/0xd0
May 23 19:15:50 mcds1 kernel: [210728.231154]  [<ffffffff81166c59>] sleep_on_buffer+0x9/0x10
May 23 19:15:50 mcds1 kernel: [210728.231157]  [<ffffffff817971d7>] __wait_on_bit+0x57/0x80
May 23 19:15:50 mcds1 kernel: [210728.231161]  [<ffffffff81165f7c>] ? submit_bh+0x13c/0x1f0
May 23 19:15:50 mcds1 kernel: [210728.231164]  [<ffffffff81166c50>] ? __wait_on_buffer+0x30/0x30
May 23 19:15:50 mcds1 kernel: [210728.231168]  [<ffffffff81797273>] out_of_line_wait_on_bit+0x73/0x90
May 23 19:15:50 mcds1 kernel: [210728.231172]  [<ffffffff81060870>] ? autoremove_wake_function+0x40/0x40
May 23 19:15:50 mcds1 kernel: [210728.231175]  [<ffffffff81166c46>] __wait_on_buffer+0x26/0x30
May 23 19:15:50 mcds1 kernel: [210728.231179]  [<ffffffff811ff130>] jbd2_journal_commit_transaction+0xee0/0x1960
May 23 19:15:50 mcds1 kernel: [210728.231183]  [<ffffffff817984fd>] ? __schedule+0x3ad/0x7a0
May 23 19:15:50 mcds1 kernel: [210728.231188]  [<ffffffff8104c537>] ? lock_timer_base+0x37/0x70
May 23 19:15:50 mcds1 kernel: [210728.231191]  [<ffffffff81204f62>] kjournald2+0xc2/0x240
May 23 19:15:50 mcds1 kernel: [210728.231195]  [<ffffffff81060830>] ? wake_up_bit+0x40/0x40
May 23 19:15:50 mcds1 kernel: [210728.231199]  [<ffffffff81204ea0>] ? commit_timeout+0x10/0x10
May 23 19:15:50 mcds1 kernel: [210728.231202]  [<ffffffff81060136>] kthread+0xc6/0xd0
May 23 19:15:50 mcds1 kernel: [210728.231206]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231210]  [<ffffffff817a19ac>] ret_from_fork+0x7c/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231213]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231216] umount          D ffffffff81806d60  5448 25241  24864 0x00000000
May 23 19:15:50 mcds1 kernel: [210728.231220]  ffff8801f3a89c28 0000000000000086 ffff88021fc929f0 ffff88021608cba0
May 23 19:15:50 mcds1 kernel: [210728.231223]  ffff8801f3a89bf8 ffff8801f84d8790 0000000000012980 ffff8801f3a89fd8
May 23 19:15:50 mcds1 kernel: [210728.231226]  ffff8801f3a88010 0000000000012980 0000000000012980 ffff8801f3a89fd8
May 23 19:15:50 mcds1 kernel: [210728.231230] Call Trace:
May 23 19:15:50 mcds1 kernel: [210728.231234]  [<ffffffff81798ae4>] schedule+0x24/0x70
May 23 19:15:50 mcds1 kernel: [210728.231237]  [<ffffffff81796f4d>] schedule_timeout+0x15d/0x1f0
May 23 19:15:50 mcds1 kernel: [210728.231241]  [<ffffffff8106f2b5>] ? __cond_resched+0x25/0x40
May 23 19:15:50 mcds1 kernel: [210728.231245]  [<ffffffff81798f64>] wait_for_completion+0x94/0x100
May 23 19:15:50 mcds1 kernel: [210728.231248]  [<ffffffff81070ca0>] ? try_to_wake_up+0x2a0/0x2a0
May 23 19:15:50 mcds1 kernel: [210728.231252]  [<ffffffff8115ddb1>] ? bdi_queue_work+0x81/0x110
May 23 19:15:50 mcds1 kernel: [210728.231256]  [<ffffffff8115dec3>] writeback_inodes_sb_nr+0x83/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231261]  [<ffffffff8115df4a>] writeback_inodes_sb+0x5a/0x70
May 23 19:15:50 mcds1 kernel: [210728.231264]  [<ffffffff8116463a>] __sync_filesystem+0x4a/0x50
May 23 19:15:50 mcds1 kernel: [210728.231267]  [<ffffffff81164672>] sync_filesystem+0x32/0x60
May 23 19:15:50 mcds1 kernel: [210728.231273]  [<ffffffff81137be6>] generic_shutdown_super+0x36/0xe0
May 23 19:15:50 mcds1 kernel: [210728.231277]  [<ffffffff81137cbc>] kill_block_super+0x2c/0x80
May 23 19:15:50 mcds1 kernel: [210728.231281]  [<ffffffff811381f5>] deactivate_locked_super+0x45/0x70
May 23 19:15:50 mcds1 kernel: [210728.231284]  [<ffffffff81139025>] deactivate_super+0x45/0x60
May 23 19:15:50 mcds1 kernel: [210728.231287]  [<ffffffff81152f63>] mntput_no_expire+0xf3/0x150
May 23 19:15:50 mcds1 kernel: [210728.231290]  [<ffffffff811537dd>] sys_umount+0xcd/0x3f0
May 23 19:15:50 mcds1 kernel: [210728.231294]  [<ffffffff817a1a52>] system_call_fastpath+0x16/0x1b

Regards,
Akira Fujita
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Quoted 62 lines · Akira Fujita

Hi Jan,

Quoted 59 lines · Akira Fujita

Hi,

Quoted 55 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
    PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
      1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
      2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
      3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
   2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Quoted 5 lines

Quoted 2 lines

Thanks for reply.
I'll take that information when the deadlock happens again.

Finally, I got the following messages on linux-3.9.0. Could you take a look?

Is it a real deadlock?
umount wait for flush-8:0
flush wait for jbd2
jbd2 wait for bh.
All buffer-heads will be written at sooner or later.
It probably will require significant amount of time, because fs is too fragmented(that is what this test all about), but it is not a deadlock.

Quoted 85 lines

#echo w > /proc/sysrq-trigger
/var/log/messages:
-----------------------

May 23 19:15:50 mcds1 kernel: [210728.230978] SysRq : Show Blocked State
May 23 19:15:50 mcds1 kernel: [210728.230985]   task                        PC stack   pid father
May 23 19:15:50 mcds1 kernel: [210728.230992] flush-8:0       D ffffffff81806d60  3192  2361      2 0x00000000
May 23 19:15:50 mcds1 kernel: [210728.230997]  ffff880214d27a08 0000000000000046 0000000000000282 ffff88021608d330
May 23 19:15:50 mcds1 kernel: [210728.231001]  0000000000000000 ffff880215d95ac0 0000000000012980 ffff880214d27fd8
May 23 19:15:50 mcds1 kernel: [210728.231005]  ffff880214d26010 0000000000012980 0000000000012980 ffff880214d27fd8
May 23 19:15:50 mcds1 kernel: [210728.231008] Call Trace:
May 23 19:15:50 mcds1 kernel: [210728.231018]  [<ffffffff81798ae4>] schedule+0x24/0x70
May 23 19:15:50 mcds1 kernel: [210728.231023]  [<ffffffff81204b95>] jbd2_log_wait_commit+0xb5/0x130
May 23 19:15:50 mcds1 kernel: [210728.231029]  [<ffffffff81060830>] ? wake_up_bit+0x40/0x40
May 23 19:15:50 mcds1 kernel: [210728.231033]  [<ffffffff81204cb4>] ? __jbd2_log_start_commit+0xa4/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231037]  [<ffffffff81204e4b>] jbd2_journal_force_commit_nested+0x5b/0xa0
May 23 19:15:50 mcds1 kernel: [210728.231041]  [<ffffffff811b75c8>] ext4_da_writepages+0x348/0x5a0
May 23 19:15:50 mcds1 kernel: [210728.231045]  [<ffffffff81074e77>] ? check_preempt_wakeup+0x1b7/0x2a0
May 23 19:15:50 mcds1 kernel: [210728.231051]  [<ffffffff810f0f5b>] do_writepages+0x1b/0x30
May 23 19:15:50 mcds1 kernel: [210728.231056]  [<ffffffff8115d9d4>] __writeback_single_inode+0x44/0x220
May 23 19:15:50 mcds1 kernel: [210728.231061]  [<ffffffff8115e93f>] writeback_sb_inodes+0x23f/0x430
May 23 19:15:50 mcds1 kernel: [210728.231065]  [<ffffffff8115ed6d>] wb_writeback+0xed/0x2b0
May 23 19:15:50 mcds1 kernel: [210728.231071]  [<ffffffff8104c537>] ? lock_timer_base+0x37/0x70
May 23 19:15:50 mcds1 kernel: [210728.231075]  [<ffffffff8115efcd>] wb_do_writeback+0x9d/0x240
May 23 19:15:50 mcds1 kernel: [210728.231079]  [<ffffffff8104c570>] ? lock_timer_base+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231084]  [<ffffffff8115f212>] bdi_writeback_thread+0xa2/0x230
May 23 19:15:50 mcds1 kernel: [210728.231088]  [<ffffffff8115f170>] ? wb_do_writeback+0x240/0x240
May 23 19:15:50 mcds1 kernel: [210728.231092]  [<ffffffff8115f170>] ? wb_do_writeback+0x240/0x240
May 23 19:15:50 mcds1 kernel: [210728.231095]  [<ffffffff81060136>] kthread+0xc6/0xd0
May 23 19:15:50 mcds1 kernel: [210728.231099]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231104]  [<ffffffff817a19ac>] ret_from_fork+0x7c/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231108]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231124] jbd2/sda12-8    D ffffffff81806d60  4736 25056      2 0x00000000
May 23 19:15:50 mcds1 kernel: [210728.231128]  ffff8801e436db78 0000000000000046 ffff880215c06f00 ffffffff81c10420
May 23 19:15:50 mcds1 kernel: [210728.231131]  ffff880200011200 ffff8801f8f296b0 0000000000012980 ffff8801e436dfd8
May 23 19:15:50 mcds1 kernel: [210728.231135]  ffff8801e436c010 0000000000012980 0000000000012980 ffff8801e436dfd8
May 23 19:15:50 mcds1 kernel: [210728.231138] Call Trace:
May 23 19:15:50 mcds1 kernel: [210728.231142]  [<ffffffff81166c50>] ? __wait_on_buffer+0x30/0x30
May 23 19:15:50 mcds1 kernel: [210728.231146]  [<ffffffff81798ae4>] schedule+0x24/0x70
May 23 19:15:50 mcds1 kernel: [210728.231150]  [<ffffffff81798bb7>] io_schedule+0x87/0xd0
May 23 19:15:50 mcds1 kernel: [210728.231154]  [<ffffffff81166c59>] sleep_on_buffer+0x9/0x10
May 23 19:15:50 mcds1 kernel: [210728.231157]  [<ffffffff817971d7>] __wait_on_bit+0x57/0x80
May 23 19:15:50 mcds1 kernel: [210728.231161]  [<ffffffff81165f7c>] ? submit_bh+0x13c/0x1f0
May 23 19:15:50 mcds1 kernel: [210728.231164]  [<ffffffff81166c50>] ? __wait_on_buffer+0x30/0x30
May 23 19:15:50 mcds1 kernel: [210728.231168]  [<ffffffff81797273>] out_of_line_wait_on_bit+0x73/0x90
May 23 19:15:50 mcds1 kernel: [210728.231172]  [<ffffffff81060870>] ? autoremove_wake_function+0x40/0x40
May 23 19:15:50 mcds1 kernel: [210728.231175]  [<ffffffff81166c46>] __wait_on_buffer+0x26/0x30
May 23 19:15:50 mcds1 kernel: [210728.231179]  [<ffffffff811ff130>] jbd2_journal_commit_transaction+0xee0/0x1960
May 23 19:15:50 mcds1 kernel: [210728.231183]  [<ffffffff817984fd>] ? __schedule+0x3ad/0x7a0
May 23 19:15:50 mcds1 kernel: [210728.231188]  [<ffffffff8104c537>] ? lock_timer_base+0x37/0x70
May 23 19:15:50 mcds1 kernel: [210728.231191]  [<ffffffff81204f62>] kjournald2+0xc2/0x240
May 23 19:15:50 mcds1 kernel: [210728.231195]  [<ffffffff81060830>] ? wake_up_bit+0x40/0x40
May 23 19:15:50 mcds1 kernel: [210728.231199]  [<ffffffff81204ea0>] ? commit_timeout+0x10/0x10
May 23 19:15:50 mcds1 kernel: [210728.231202]  [<ffffffff81060136>] kthread+0xc6/0xd0
May 23 19:15:50 mcds1 kernel: [210728.231206]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231210]  [<ffffffff817a19ac>] ret_from_fork+0x7c/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231213]  [<ffffffff81060070>] ? kthread_freezable_should_stop+0x70/0x70
May 23 19:15:50 mcds1 kernel: [210728.231216] umount          D ffffffff81806d60  5448 25241  24864 0x00000000
May 23 19:15:50 mcds1 kernel: [210728.231220]  ffff8801f3a89c28 0000000000000086 ffff88021fc929f0 ffff88021608cba0
May 23 19:15:50 mcds1 kernel: [210728.231223]  ffff8801f3a89bf8 ffff8801f84d8790 0000000000012980 ffff8801f3a89fd8
May 23 19:15:50 mcds1 kernel: [210728.231226]  ffff8801f3a88010 0000000000012980 0000000000012980 ffff8801f3a89fd8
May 23 19:15:50 mcds1 kernel: [210728.231230] Call Trace:
May 23 19:15:50 mcds1 kernel: [210728.231234]  [<ffffffff81798ae4>] schedule+0x24/0x70
May 23 19:15:50 mcds1 kernel: [210728.231237]  [<ffffffff81796f4d>] schedule_timeout+0x15d/0x1f0
May 23 19:15:50 mcds1 kernel: [210728.231241]  [<ffffffff8106f2b5>] ? __cond_resched+0x25/0x40
May 23 19:15:50 mcds1 kernel: [210728.231245]  [<ffffffff81798f64>] wait_for_completion+0x94/0x100
May 23 19:15:50 mcds1 kernel: [210728.231248]  [<ffffffff81070ca0>] ? try_to_wake_up+0x2a0/0x2a0
May 23 19:15:50 mcds1 kernel: [210728.231252]  [<ffffffff8115ddb1>] ? bdi_queue_work+0x81/0x110
May 23 19:15:50 mcds1 kernel: [210728.231256]  [<ffffffff8115dec3>] writeback_inodes_sb_nr+0x83/0xb0
May 23 19:15:50 mcds1 kernel: [210728.231261]  [<ffffffff8115df4a>] writeback_inodes_sb+0x5a/0x70
May 23 19:15:50 mcds1 kernel: [210728.231264]  [<ffffffff8116463a>] __sync_filesystem+0x4a/0x50
May 23 19:15:50 mcds1 kernel: [210728.231267]  [<ffffffff81164672>] sync_filesystem+0x32/0x60
May 23 19:15:50 mcds1 kernel: [210728.231273]  [<ffffffff81137be6>] generic_shutdown_super+0x36/0xe0
May 23 19:15:50 mcds1 kernel: [210728.231277]  [<ffffffff81137cbc>] kill_block_super+0x2c/0x80
May 23 19:15:50 mcds1 kernel: [210728.231281]  [<ffffffff811381f5>] deactivate_locked_super+0x45/0x70
May 23 19:15:50 mcds1 kernel: [210728.231284]  [<ffffffff81139025>] deactivate_super+0x45/0x60
May 23 19:15:50 mcds1 kernel: [210728.231287]  [<ffffffff81152f63>] mntput_no_expire+0xf3/0x150
May 23 19:15:50 mcds1 kernel: [210728.231290]  [<ffffffff811537dd>] sys_umount+0xcd/0x3f0
May 23 19:15:50 mcds1 kernel: [210728.231294]  [<ffffffff817a1a52>] system_call_fastpath+0x16/0x1b

Regards,
Akira Fujita
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in the body of a message to [email protected]
More majordomo info at http://vger.kernel.org/majordomo-info.html

Hello,

Quoted 83 lines · Jan Kara

Quoted 68 lines · Dmitry Monakhov

Quoted 62 lines · Akira Fujita

Hi Jan,

Quoted 59 lines · Akira Fujita

Hi,

Quoted 55 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
     PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
       1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
       2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
       3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
    2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Quoted 5 lines

Quoted 2 lines

Thanks for reply.
I'll take that information when the deadlock happens again.

Finally, I got the following messages on linux-3.9.0. Could you take a look?

Quoted 7 lines

Is it a real deadlock?
umount wait for flush-8:0
flush wait for jbd2
jbd2 wait for bh.
All buffer-heads will be written at sooner or later.
It probably will require significant amount of time, because fs is too fragmented(that is what this test all about), but it is not a deadlock.

Yeah, that is my analysis as well. I was only thinking whether we
couldn't forget some buffer locked on some error recovery path (we are getting ENOSPC) but it's not obvious where it would be. Akira-san, could you also send us disassembly of your jbd2_journal_commit_transaction() function so that we can check where exactly offset 0xee0 is in the function?

Quoted 1 line

Honza

I attached disasemble code of jbd2_journal_commit_tnrasaction, please check it.

Quoted 86 lines · Akira Fujita

Hello,

Quoted 83 lines · Jan Kara

Quoted 68 lines · Dmitry Monakhov

Quoted 62 lines · Akira Fujita

Hi Jan,

Quoted 59 lines · Akira Fujita

Hi,

Quoted 55 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
      PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
        1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
        2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
        3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
     2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Quoted 5 lines

Quoted 2 lines

Thanks for reply.
I'll take that information when the deadlock happens again.

Finally, I got the following messages on linux-3.9.0. Could you take a look?

Quoted 7 lines

Is it a real deadlock?
umount wait for flush-8:0
flush wait for jbd2
jbd2 wait for bh.
All buffer-heads will be written at sooner or later.
It probably will require significant amount of time, because fs is too fragmented(that is what this test all about), but it is not a deadlock.

Yeah, that is my analysis as well. I was only thinking whether we
couldn't forget some buffer locked on some error recovery path (we are getting ENOSPC) but it's not obvious where it would be. Akira-san, could you also send us disassembly of your jbd2_journal_commit_transaction() function so that we can check where exactly offset 0xee0 is in the function?

Quoted 4 lines

Quoted 1 line

Honza

I attached disasemble code of jbd2_journal_commit_tnrasaction, please check it.

Thanks. I've looked into the disassembly now and we are waiting for the
write of commit record to finish. We have submitted the buffer just before so it can hardly be some issue like forgotten locked buffer. Really strange. It looks like some problem in block layer, device driver, or HW itself... I'm thinking how to debug this further - it would be good if we had blktrace data just before the moment when the hang happens but given how hard this is to reproduce the traces would be extremly large...

One idea - can you try whether the problem reproduces with 'nobarrier' mount option? It could be some problem with flush / fua handling.

Quoted 99 lines · Jan Kara

Quoted 86 lines · Akira Fujita

Hello,

Quoted 83 lines · Jan Kara

Quoted 68 lines · Dmitry Monakhov

Quoted 62 lines · Akira Fujita

Hi Jan,

Quoted 59 lines · Akira Fujita

Hi,

Quoted 55 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
      PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
        1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
        2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
        3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
     2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Quoted 5 lines

Quoted 2 lines

Thanks for reply.
I'll take that information when the deadlock happens again.

Finally, I got the following messages on linux-3.9.0. Could you take a look?

Quoted 7 lines

Is it a real deadlock?
umount wait for flush-8:0
flush wait for jbd2
jbd2 wait for bh.
All buffer-heads will be written at sooner or later.
It probably will require significant amount of time, because fs is too fragmented(that is what this test all about), but it is not a deadlock.

Yeah, that is my analysis as well. I was only thinking whether we
couldn't forget some buffer locked on some error recovery path (we are getting ENOSPC) but it's not obvious where it would be. Akira-san, could you also send us disassembly of your jbd2_journal_commit_transaction() function so that we can check where exactly offset 0xee0 is in the function?

Quoted 4 lines

Quoted 1 line

Honza

I attached disasemble code of jbd2_journal_commit_tnrasaction, please check it.

Thanks. I've looked into the disassembly now and we are waiting for the
write of commit record to finish. We have submitted the buffer just before so it can hardly be some issue like forgotten locked buffer. Really strange. It looks like some problem in block layer, device driver, or HW itself... I'm thinking how to debug this further - it would be good if we had blktrace data just before the moment when the hang happens but given how hard this is to reproduce the traces would be extremly large...

Quoted 3 lines

One idea - can you try whether the problem reproduces with 'nobarrier' mount option? It could be some problem with flush / fua handling.

OK, I'll try to reproduce this issue with 'nobarrier' (and take blktrace log if I can).

Quoted 106 lines · Akira Fujita

Quoted 102 lines · Jan Kara

Quoted 86 lines · Akira Fujita

Hello,

Quoted 83 lines · Jan Kara

Quoted 68 lines · Dmitry Monakhov

Quoted 62 lines · Akira Fujita

Hi Jan,

Quoted 59 lines · Akira Fujita

Hi,

Quoted 55 lines · Jan Kara

Hello,

Quoted 41 lines · Akira Fujita

I ran into the deaclock with xfs_test 269 on linux-3.9.0. It seems happen between jbd2_log_wait_commit, sleep_on_buffer and writeback_indoes (Please see ps log below). Once it occurs we can't touch FS anymore.
In my case 300 - 1000 trials to occur. Is this known issue?

The following kernels seems to have same problem:
- linux-3.5-rc5
- linux-3.8.5
- linux-3.9-rc7
And now I'm trying it on linux-3.10-rc1.

# ./check generic/269
FSTYP         -- ext4
PLATFORM      -- Linux/x86_64 mcds1 3.9.0
MKFS_OPTIONS  -- /dev/sda12
MOUNT_OPTIONS -- -o acl,user_xattr /dev/sda12 /mnt/mp2

# ps -eo pid,tid,class,rtprio,ni,pri,psr,pcpu,stat,wchan:16,comm
       PID   TID CLS RTPRIO  NI PRI PSR %CPU STAT WCHAN            COMMAND
         1     1 TS       -   0  19   0  0.0 Ss   poll_schedule_ti init
         2     2 TS       -   0  19   0  0.0 S    kthreadd         kthreadd
         3     3 TS       -   0  19   0  0.0 S    smpboot_thread_f ksoftirqd/0
...
      2391  2391 TS       -   0  19   2  0.1 D    jbd2_log_wait_co flush-8:0
...
22647 22647 TS       -   0  19   3  0.0 S    worker_thread    kworker/3:1
22655 22655 TS       -   0  19   0  0.0 S    hrtimer_nanoslee sleep
22657 22657 TS       -   0  19   2  0.0 R+   -                ps
25330 25330 TS       -   0  19   0  0.0 S    worker_thread    kworker/0:0
28963 28963 TS       -   0  19   1  0.0 S+   wait             loop_xfstests.s
28964 28964 TS       -   0  19   1  0.0 S+   wait             check
29180 29180 TS       -   0  19   3  0.0 S    kjournald2       jbd2/sda11-8
29181 29181 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29199 29199 TS       -   0  19   3  0.0 S+   wait             269
29391 29391 TS       -   0  19   0  0.6 D    sleep_on_buffer  jbd2/sda12-8
29392 29392 TS       - -20  39   3  0.0 S<   rescuer_thread   ext4-dio-unwrit
29394 29394 TS       -   0  19   0  0.0 S    wait             fsstress
29505 29505 TS       -   0  19   3  0.0 D    writeback_inodes fsstress

Quoted 4 lines

# df -T /dev/sda11 /dev/sda12
Filesystem    Type   1K-blocks      Used Available Use% Mounted on
/dev/sda11    ext4     9857264     22308   9327564   1% /mnt/mp1
/dev/sda12    ext4      499656    499656         0 100% /mnt/mp2

Thanks for report. No I don't think this problem has been reported
before. Seeing that sda12 is out of space and fsstress hangs in writeback_inodes(), I suspect we have some deadlock in ENOSPC recovery path when we want to flush data to disk to reduce delalloc uncertainty. Can you run 'echo w >/proc/sysrq-trigger' when the deadlock happens and post your dmesg here? Thanks!

Quoted 5 lines

Quoted 2 lines

Thanks for reply.
I'll take that information when the deadlock happens again.

Finally, I got the following messages on linux-3.9.0. Could you take a look?

Quoted 7 lines

Is it a real deadlock?
umount wait for flush-8:0
flush wait for jbd2
jbd2 wait for bh.
All buffer-heads will be written at sooner or later.
It probably will require significant amount of time, because fs is too fragmented(that is what this test all about), but it is not a deadlock.

Yeah, that is my analysis as well. I was only thinking whether we
couldn't forget some buffer locked on some error recovery path (we are getting ENOSPC) but it's not obvious where it would be. Akira-san, could you also send us disassembly of your jbd2_journal_commit_transaction() function so that we can check where exactly offset 0xee0 is in the function?

Quoted 4 lines

Quoted 1 line

Honza

I attached disasemble code of jbd2_journal_commit_tnrasaction, please check it.

Thanks. I've looked into the disassembly now and we are waiting for the
write of commit record to finish. We have submitted the buffer just before so it can hardly be some issue like forgotten locked buffer. Really strange. It looks like some problem in block layer, device driver, or HW itself... I'm thinking how to debug this further - it would be good if we had blktrace data just before the moment when the hang happens but given how hard this is to reproduce the traces would be extremly large...

One idea - can you try whether the problem reproduces with 'nobarrier' mount option? It could be some problem with flush / fua handling.

Quoted 2 lines

OK, I'll try to reproduce this issue with 'nobarrier' (and take blktrace log if I can).

You can restart the blktrace every 5 minutes or so, so that trace files
don't get too big. If we have a trace for a minute before the machine crashes it should be enough for debugging.