On Thu, Sep 25, 2014 at 1:58 PM, Andrei Mikhailovsky <andrei at arhont.com> wrote:
> Guys,
>
> Have done some testing with 3.16.3-031603-generic downloaded from Ubuntu
> utopic branch. The hang task problem is gone when using large block size
> (tested with 1M and 4M) and I could no longer preproduce the hang tasks
> while doing 100 dd tests in a for loop.
>
>
>
> However, I can confirm that I am still getting hang tasks while working with
> a 4K block size. The hang tasks start after about an hour, but they do not
> cause the server crash. After a while the dd test times out and continues
> with the loop. This is what I was running:
>
> for i in {1..100} ; do time dd if=/dev/zero of=/tmp/mount/1G bs=4K count=25K
> oflag=direct ; done
>
> The following test definately produces the hang tasks like these:
>
> [23160.549785] INFO: task dd:2033 blocked for more than 120 seconds.
> [23160.588364] Tainted: G OE 3.16.3-031603-generic
> #201409171435
> [23160.627998] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [23160.706856] dd D 000000000000000b 0 2033 23859
> 0x00000000
> [23160.706861] ffff88011cec78c8 0000000000000082 ffff88011cec78d8
> ffff88011cec7fd8
> [23160.706865] 00000000000143c0 00000000000143c0 ffff88048661bcc0
> ffff880113441440
> [23160.706868] ffff88011cec7898 ffff88067fd54cc0 ffff880113441440
> ffff880113441440
> [23160.706871] Call Trace:
> [23160.706883] [<ffffffff81791f69>] schedule+0x29/0x70
> [23160.706887] [<ffffffff8179203f>] io_schedule+0x8f/0xd0
> [23160.706893] [<ffffffff81219e74>] dio_await_completion+0x54/0xd0
> [23160.706897] [<ffffffff8121c6a8>] do_blockdev_direct_IO+0x958/0xcc0
> [23160.706903] [<ffffffff810ba81e>] ? wake_up_bit+0x2e/0x40
> [23160.706908] [<ffffffff812aa865>] ?
> jbd2_journal_dirty_metadata+0xc5/0x260
> [23160.706914] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23160.706919] [<ffffffff8121ca5c>] __blockdev_direct_IO+0x4c/0x50
> [23160.706922] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23160.706928] [<ffffffff8129f44e>] ext4_ind_direct_IO+0xce/0x410
> [23160.706931] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23160.706935] [<ffffffff81261fbb>] ext4_ext_direct_IO+0x1bb/0x2a0
> [23160.706938] [<ffffffff81290158>] ? __ext4_journal_stop+0x78/0xa0
> [23160.706942] [<ffffffff812627fc>] ext4_direct_IO+0xec/0x1e0
> [23160.706946] [<ffffffff8120a003>] ? __mark_inode_dirty+0x53/0x2d0
> [23160.706952] [<ffffffff8116d39b>] generic_file_direct_write+0xbb/0x180
> [23160.706957] [<ffffffff811ffbe2>] ? mnt_clone_write+0x12/0x30
> [23160.706960] [<ffffffff8116d707>] __generic_file_write_iter+0x2a7/0x350
> [23160.706963] [<ffffffff8125c2b1>] ext4_file_write_iter+0x111/0x3d0
> [23160.706969] [<ffffffff81192fd4>] ? iov_iter_init+0x14/0x40
> [23160.706976] [<ffffffff811e0c8b>] new_sync_write+0x7b/0xb0
> [23160.706978] [<ffffffff811e19a7>] vfs_write+0xc7/0x1f0
> [23160.706980] [<ffffffff811e1eaf>] SyS_write+0x4f/0xb0
> [23160.706985] [<ffffffff81795ded>] system_call_fastpath+0x1a/0x1f
> [23280.705400] INFO: task dd:2033 blocked for more than 120 seconds.
> [23280.745358] Tainted: G OE 3.16.3-031603-generic
> #201409171435
> [23280.785069] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [23280.864158] dd D 000000000000000b 0 2033 23859
> 0x00000000
> [23280.864164] ffff88011cec78c8 0000000000000082 ffff88011cec78d8
> ffff88011cec7fd8
> [23280.864167] 00000000000143c0 00000000000143c0 ffff88048661bcc0
> ffff880113441440
> [23280.864170] ffff88011cec7898 ffff88067fd54cc0 ffff880113441440
> ffff880113441440
> [23280.864173] Call Trace:
> [23280.864185] [<ffffffff81791f69>] schedule+0x29/0x70
> [23280.864197] [<ffffffff8179203f>] io_schedule+0x8f/0xd0
> [23280.864203] [<ffffffff81219e74>] dio_await_completion+0x54/0xd0
> [23280.864207] [<ffffffff8121c6a8>] do_blockdev_direct_IO+0x958/0xcc0
> [23280.864213] [<ffffffff810ba81e>] ? wake_up_bit+0x2e/0x40
> [23280.864218] [<ffffffff812aa865>] ?
> jbd2_journal_dirty_metadata+0xc5/0x260
> [23280.864224] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23280.864229] [<ffffffff8121ca5c>] __blockdev_direct_IO+0x4c/0x50
> [23280.864239] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23280.864244] [<ffffffff8129f44e>] ext4_ind_direct_IO+0xce/0x410
> [23280.864247] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23280.864251] [<ffffffff81261fbb>] ext4_ext_direct_IO+0x1bb/0x2a0
> [23280.864254] [<ffffffff81290158>] ? __ext4_journal_stop+0x78/0xa0
> [23280.864258] [<ffffffff812627fc>] ext4_direct_IO+0xec/0x1e0
> [23280.864263] [<ffffffff8120a003>] ? __mark_inode_dirty+0x53/0x2d0
> [23280.864268] [<ffffffff8116d39b>] generic_file_direct_write+0xbb/0x180
> [23280.864273] [<ffffffff811ffbe2>] ? mnt_clone_write+0x12/0x30
> [23280.864284] [<ffffffff8116d707>] __generic_file_write_iter+0x2a7/0x350
> [23280.864289] [<ffffffff8125c2b1>] ext4_file_write_iter+0x111/0x3d0
> [23280.864295] [<ffffffff81192fd4>] ? iov_iter_init+0x14/0x40
> [23280.864300] [<ffffffff811e0c8b>] new_sync_write+0x7b/0xb0
> [23280.864302] [<ffffffff811e19a7>] vfs_write+0xc7/0x1f0
> [23280.864307] [<ffffffff811e1eaf>] SyS_write+0x4f/0xb0
> [23280.864314] [<ffffffff81795ded>] system_call_fastpath+0x1a/0x1f
> [23400.861043] INFO: task dd:2033 blocked for more than 120 seconds.
> [23400.901529] Tainted: G OE 3.16.3-031603-generic
> #201409171435
> [23400.942255] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [23401.020985] dd D 000000000000000b 0 2033 23859
> 0x00000000
> [23401.020991] ffff88011cec78c8 0000000000000082 ffff88011cec78d8
> ffff88011cec7fd8
> [23401.020995] 00000000000143c0 00000000000143c0 ffff88048661bcc0
> ffff880113441440
> [23401.020997] ffff88011cec7898 ffff88067fd54cc0 ffff880113441440
> ffff880113441440
> [23401.021001] Call Trace:
> [23401.021014] [<ffffffff81791f69>] schedule+0x29/0x70
> [23401.021025] [<ffffffff8179203f>] io_schedule+0x8f/0xd0
> [23401.021031] [<ffffffff81219e74>] dio_await_completion+0x54/0xd0
> [23401.021035] [<ffffffff8121c6a8>] do_blockdev_direct_IO+0x958/0xcc0
> [23401.021041] [<ffffffff810ba81e>] ? wake_up_bit+0x2e/0x40
> [23401.021046] [<ffffffff812aa865>] ?
> jbd2_journal_dirty_metadata+0xc5/0x260
> [23401.021052] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23401.021057] [<ffffffff8121ca5c>] __blockdev_direct_IO+0x4c/0x50
> [23401.021067] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23401.021072] [<ffffffff8129f44e>] ext4_ind_direct_IO+0xce/0x410
> [23401.021075] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23401.021079] [<ffffffff81261fbb>] ext4_ext_direct_IO+0x1bb/0x2a0
> [23401.021082] [<ffffffff81290158>] ? __ext4_journal_stop+0x78/0xa0
> [23401.021086] [<ffffffff812627fc>] ext4_direct_IO+0xec/0x1e0
> [23401.021091] [<ffffffff8120a003>] ? __mark_inode_dirty+0x53/0x2d0
> [23401.021096] [<ffffffff8116d39b>] generic_file_direct_write+0xbb/0x180
> [23401.021101] [<ffffffff811ffbe2>] ? mnt_clone_write+0x12/0x30
> [23401.021112] [<ffffffff8116d707>] __generic_file_write_iter+0x2a7/0x350
> [23401.021116] [<ffffffff8125c2b1>] ext4_file_write_iter+0x111/0x3d0
> [23401.021122] [<ffffffff81192fd4>] ? iov_iter_init+0x14/0x40
> [23401.021129] [<ffffffff811e0c8b>] new_sync_write+0x7b/0xb0
> [23401.021134] [<ffffffff811e19a7>] vfs_write+0xc7/0x1f0
> [23401.021137] [<ffffffff811e1eaf>] SyS_write+0x4f/0xb0
> [23401.021141] [<ffffffff81795ded>] system_call_fastpath+0x1a/0x1f
> [23521.020639] INFO: task dd:2033 blocked for more than 120 seconds.
> [23521.060586] Tainted: G OE 3.16.3-031603-generic
> #201409171435
> [23521.101349] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables
> this message.
> [23521.182678] dd D 000000000000000b 0 2033 23859
> 0x00000000
> [23521.182684] ffff88011cec78c8 0000000000000082 ffff88011cec78d8
> ffff88011cec7fd8
> [23521.182690] 00000000000143c0 00000000000143c0 ffff88048661bcc0
> ffff880113441440
> [23521.182693] ffff88011cec7898 ffff88067fd54cc0 ffff880113441440
> ffff880113441440
> [23521.182703] Call Trace:
> [23521.182715] [<ffffffff81791f69>] schedule+0x29/0x70
> [23521.182718] [<ffffffff8179203f>] io_schedule+0x8f/0xd0
> [23521.182731] [<ffffffff81219e74>] dio_await_completion+0x54/0xd0
> [23521.182734] [<ffffffff8121c6a8>] do_blockdev_direct_IO+0x958/0xcc0
> [23521.182741] [<ffffffff810ba81e>] ? wake_up_bit+0x2e/0x40
> [23521.182749] [<ffffffff812aa865>] ?
> jbd2_journal_dirty_metadata+0xc5/0x260
> [23521.182762] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23521.182767] [<ffffffff8121ca5c>] __blockdev_direct_IO+0x4c/0x50
> [23521.182770] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23521.182775] [<ffffffff8129f44e>] ext4_ind_direct_IO+0xce/0x410
> [23521.182778] [<ffffffff81265320>] ? ext4_get_block_write+0x20/0x20
> [23521.182788] [<ffffffff81261fbb>] ext4_ext_direct_IO+0x1bb/0x2a0
> [23521.182791] [<ffffffff81290158>] ? __ext4_journal_stop+0x78/0xa0
> [23521.182794] [<ffffffff812627fc>] ext4_direct_IO+0xec/0x1e0
> [23521.182803] [<ffffffff8120a003>] ? __mark_inode_dirty+0x53/0x2d0
> [23521.182808] [<ffffffff8116d39b>] generic_file_direct_write+0xbb/0x180
> [23521.182816] [<ffffffff811ffbe2>] ? mnt_clone_write+0x12/0x30
> [23521.182819] [<ffffffff8116d707>] __generic_file_write_iter+0x2a7/0x350
> [23521.182822] [<ffffffff8125c2b1>] ext4_file_write_iter+0x111/0x3d0
> [23521.182828] [<ffffffff81192fd4>] ? iov_iter_init+0x14/0x40
> [23521.182835] [<ffffffff811e0c8b>] new_sync_write+0x7b/0xb0
> [23521.182838] [<ffffffff811e19a7>] vfs_write+0xc7/0x1f0
> [23521.182840] [<ffffffff811e1eaf>] SyS_write+0x4f/0xb0
> [23521.182844] [<ffffffff81795ded>] system_call_fastpath+0x1a/0x1f
>
>
>
> According to syslog, two dd processes produced hang tasks from the total of
> 100 runs. Overall, the latest kernels tend to perform very poorly with rbd
> mounted volumes. The single dd process with block size of 1M or 4M was only
> producing on average 16MB/s, while the 4K block size was not even getting
> past 900KB/s. From the client side, rbd caching was enabled. I will now try
> to run the same test without rbd caching to see if the results are
> different.
>
> But from what i've seen so far, there seems to be a big performance
> regression with the latest Ubuntu kernels.
Well, since this slowdown issue is the only thing that reproduces for
me, I'll bump the priority and try to investigate. Maybe that will
uncover the nfs gateway problems as well..
Andrei, what's the last kernel you didn't have any issues on?
Thanks,
Ilya
