[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]

Re: [dm-devel] kpartx mounted vmdk images and bad write performance



On 11 December 2012 00:09, James Robertson <j mesrobertson com> wrote:
> It would appear related to USB, although tests to local storage were
> not that great. As a test I ran dd to create a file on the mounted
> partiton on a USB2 attached disk as follows:
>
>> kpartx -av /mnt/backup/FITZVICVDP01/FITZVICVDP01_2-flat.vmdk
> add map loop0p1 (254:4): 0 536860169 linear /dev/loop0 1
>> mount /dev/mapper/loop0p1 /mnt/loop0p1
>> dd if=/dev/zero of=/mnt/loop0p1/zerofile.tst bs=1k count=1700000
>
> In another terminal I monitored it's progress, it got to 763M and
> simply stopped increasing.  dd was still running in the other
> terminal.  You can see the date is 10 minutes since the last mod time.
>
>> date
> Monday 10 December  23:28:09 EST 2012
>> ls -lh /mnt/loop0p1/zerofile.tst
> -rw-r--r-- 1 root root 763M Dec 10 23:18 /mnt/loop0p1/zerofile.tst
>
> In dmesg these started being logged every 2 minutes.
>
> [ 1680.648037] INFO: task kworker/3:0:3139 blocked for more than 120 seconds.
> [ 1680.648086] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 1680.648140] kworker/3:0     D ffff88012fd93780     0  3139      2 0x00000000
> [ 1680.648144]  ffff88012706e300 0000000000000046 0000000700000000
> ffff88012af5cf60
> [ 1680.648149]  0000000000013780 ffff8801275effd8 ffff8801275effd8
> ffff88012706e300
> [ 1680.648153]  ffff880129f5e000 00000001810709c1 0000000000000202
> ffff880129d62e80
> [ 1680.648157] Call Trace:
> [ 1680.648180]  [<ffffffffa0319a43>] ? xlog_wait+0x51/0x67 [xfs]
> [ 1680.648186]  [<ffffffff8103f411>] ? try_to_wake_up+0x197/0x197
> [ 1680.648200]  [<ffffffffa031c1e0>] ? _xfs_log_force_lsn+0x1cd/0x205 [xfs]
> [ 1680.648215]  [<ffffffffa03194b6>] ? xfs_trans_commit+0x10a/0x205 [xfs]
> [ 1680.648227]  [<ffffffffa02e6736>] ? xfs_reclaim_inode+0x22d/0x22d [xfs]
> [ 1680.648239]  [<ffffffffa02e6770>] ? xfs_sync_worker+0x3a/0x6a [xfs]
> [ 1680.648243]  [<ffffffff8105b04d>] ? process_one_work+0x163/0x284
> [ 1680.648246]  [<ffffffff8105c022>] ? worker_thread+0xc2/0x145
> [ 1680.648249]  [<ffffffff8105bf60>] ? manage_workers.isra.25+0x15b/0x15b
> [ 1680.648253]  [<ffffffff8105f155>] ? kthread+0x76/0x7e
> [ 1680.648258]  [<ffffffff81353c34>] ? kernel_thread_helper+0x4/0x10
> [ 1680.648261]  [<ffffffff8105f0df>] ? kthread_worker_fn+0x139/0x139
> [ 1680.648264]  [<ffffffff81353c30>] ? gs_change+0x13/0x13
>
> ---
>
> More info was logged later on before dd finally completed.
>
> [ 2400.648039] INFO: task kworker/3:0:3139 blocked for more than 120 seconds.
> [ 2400.648063] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 2400.648100] kworker/3:0     D ffff88012fd93780     0  3139      2 0x00000000
> [ 2400.648105]  ffff88012706e300 0000000000000046 0000000700000000
> ffff88012af5cf60
> [ 2400.648111]  0000000000013780 ffff8801275effd8 ffff8801275effd8
> ffff88012706e300
> [ 2400.648115]  ffff880129f5e000 00000001810709c1 0000000000000202
> ffff880129d62e80
> [ 2400.648120] Call Trace:
> [ 2400.648145]  [<ffffffffa0319a43>] ? xlog_wait+0x51/0x67 [xfs]
> [ 2400.648151]  [<ffffffff8103f411>] ? try_to_wake_up+0x197/0x197
> [ 2400.648168]  [<ffffffffa031c1e0>] ? _xfs_log_force_lsn+0x1cd/0x205 [xfs]
> [ 2400.648185]  [<ffffffffa03194b6>] ? xfs_trans_commit+0x10a/0x205 [xfs]
> [ 2400.648199]  [<ffffffffa02e6736>] ? xfs_reclaim_inode+0x22d/0x22d [xfs]
> [ 2400.648213]  [<ffffffffa02e6770>] ? xfs_sync_worker+0x3a/0x6a [xfs]
> [ 2400.648218]  [<ffffffff8105b04d>] ? process_one_work+0x163/0x284
> [ 2400.648221]  [<ffffffff8105c022>] ? worker_thread+0xc2/0x145
> [ 2400.648225]  [<ffffffff8105bf60>] ? manage_workers.isra.25+0x15b/0x15b
> [ 2400.648229]  [<ffffffff8105f155>] ? kthread+0x76/0x7e
> [ 2400.648234]  [<ffffffff81353c34>] ? kernel_thread_helper+0x4/0x10
> [ 2400.648238]  [<ffffffff8105f0df>] ? kthread_worker_fn+0x139/0x139
> [ 2400.648241]  [<ffffffff81353c30>] ? gs_change+0x13/0x13
> [ 2400.648250] INFO: task dd:3376 blocked for more than 120 seconds.
> [ 2400.648282] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 2400.648334] dd              D ffff88012fd93780     0  3376   2715 0x00000000
> [ 2400.648337]  ffff88012755aa70 0000000000000082 ffff880100000000
> ffff88012af5cf60
> [ 2400.648342]  0000000000013780 ffff8801290dffd8 ffff8801290dffd8
> ffff88012755aa70
> [ 2400.648346]  ffffffff8101361a 0000000181065d11 ffff8801294d5c90
> ffff88012fd93fd0
> [ 2400.648349] Call Trace:
> [ 2400.648353]  [<ffffffff8101361a>] ? read_tsc+0x5/0x14
> [ 2400.648357]  [<ffffffff810b41eb>] ? lock_page+0x20/0x20
> [ 2400.648362]  [<ffffffff8134ba54>] ? io_schedule+0x59/0x71
> [ 2400.648365]  [<ffffffff810b41f1>] ? sleep_on_page+0x6/0xa
> [ 2400.648368]  [<ffffffff8134be97>] ? __wait_on_bit+0x3e/0x71
> [ 2400.648371]  [<ffffffff810b432d>] ? wait_on_page_bit+0x6e/0x73
> [ 2400.648374]  [<ffffffff810363d8>] ? should_resched+0x5/0x23
> [ 2400.648377]  [<ffffffff8105f7d1>] ? autoremove_wake_function+0x2a/0x2a
> [ 2400.648381]  [<ffffffff810b4ba6>] ? grab_cache_page_write_begin+0x9c/0xae
> [ 2400.648385]  [<ffffffff8111dc1f>] ? block_write_end+0x57/0x62
> [ 2400.648388]  [<ffffffff8111e22c>] ? block_write_begin+0x22/0x72
> [ 2400.648397]  [<ffffffffa02d79d9>] ? xfs_get_blocks_direct+0xb/0xb [xfs]
> [ 2400.648406]  [<ffffffffa02d8398>] ? xfs_vm_write_begin+0x30/0x51 [xfs]
> [ 2400.648410]  [<ffffffff810b467b>] ? generic_file_buffered_write+0x10f/0x259
> [ 2400.648421]  [<ffffffffa02dcb67>] ?
> xfs_file_buffered_aio_write+0x10b/0x15c [xfs]
> [ 2400.648431]  [<ffffffffa02dcd28>] ? xfs_file_aio_write+0x170/0x20c [xfs]
> [ 2400.648435]  [<ffffffff810f9450>] ? do_sync_write+0xb4/0xec
> [ 2400.648438]  [<ffffffff810363d8>] ? should_resched+0x5/0x23
> [ 2400.648442]  [<ffffffff8134b7ff>] ? _cond_resched+0x7/0x1c
> [ 2400.648446]  [<ffffffff81163719>] ? security_file_permission+0x16/0x2d
> [ 2400.648449]  [<ffffffff810f9b41>] ? vfs_write+0xa2/0xe9
> [ 2400.648452]  [<ffffffff810f9d1e>] ? sys_write+0x45/0x6b
> [ 2400.648456]  [<ffffffff81351ad2>] ? system_call_fastpath+0x16/0x1b
> [ 2520.648039] INFO: task kworker/3:0:3139 blocked for more than 120 seconds.
> [ 2520.648076] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [ 2520.648128] kworker/3:0     D ffff88012fd93780     0  3139      2 0x00000000
> [ 2520.648134]  ffff88012706e300 0000000000000046 0000000700000000
> ffff88012af5cf60
> [ 2520.648139]  0000000000013780 ffff8801275effd8 ffff8801275effd8
> ffff88012706e300
> [ 2520.648144]  ffff880129f5e000 00000001810709c1 0000000000000202
> ffff880129d62e80
> [ 2520.648149] Call Trace:
> [ 2520.648173]  [<ffffffffa0319a43>] ? xlog_wait+0x51/0x67 [xfs]
> [ 2520.648179]  [<ffffffff8103f411>] ? try_to_wake_up+0x197/0x197
> [ 2520.648196]  [<ffffffffa031c1e0>] ? _xfs_log_force_lsn+0x1cd/0x205 [xfs]
> [ 2520.648216]  [<ffffffffa03194b6>] ? xfs_trans_commit+0x10a/0x205 [xfs]
> [ 2520.648226]  [<ffffffffa02e6736>] ? xfs_reclaim_inode+0x22d/0x22d [xfs]
> [ 2520.648236]  [<ffffffffa02e6770>] ? xfs_sync_worker+0x3a/0x6a [xfs]
> [ 2520.648240]  [<ffffffff8105b04d>] ? process_one_work+0x163/0x284
> [ 2520.648243]  [<ffffffff8105c022>] ? worker_thread+0xc2/0x145
> [ 2520.648245]  [<ffffffff8105bf60>] ? manage_workers.isra.25+0x15b/0x15b
> [ 2520.648248]  [<ffffffff8105f155>] ? kthread+0x76/0x7e
> [ 2520.648253]  [<ffffffff81353c34>] ? kernel_thread_helper+0x4/0x10
> [ 2520.648256]  [<ffffffff8105f0df>] ? kthread_worker_fn+0x139/0x139
> [ 2520.648258]  [<ffffffff81353c30>] ? gs_change+0x13/0x13
>
>
> I let dd continue to run and eventually it finished with abysmal
> results (this is the output of the command at the top):
>
>> dd if=/dev/zero of=/mnt/loop0p1/zerofile.tst bs=1k count=1700000
> 1700000+0 records in
> 1700000+0 records out
> 1740800000 bytes (1.7 GB) copied, 1362.68 s, 1.3 MB/s
>
>> ls -lh /mnt/loop0p1/zerofile.tst
> -rw-r--r-- 1 root root 1.7G Dec 10 23:41 /mnt/loop0p1/zerofile.tst
>
> I had already copied the same vmdk to the local server file system and
> repeated the tests.  No errors were logged to dmesg.
>
>> kpartx -av /var/data/FITZVICVDP01_2-flat.vmdk
> add map loop0p1 (254:4): 0 536860169 linear /dev/loop0 1
>> mount /dev/mapper/loop0p1 /mnt/loop0p1
>> dd if=/dev/zero of=/mnt/loop0p1/zerofile.tst bs=1k count=1700000
> 1700000+0 records in
> 1700000+0 records out
> 1740800000 bytes (1.7 GB) copied, 31.867 s, 54.6 MB/s
>
> As a comparison...
>
> Writing direct to the USB disk is about right for USB2.
>
>> dd if=/dev/zero of=/mnt/backup/zerofile.tst bs=1k count=1700000
> 1700000+0 records in
> 1700000+0 records out
> 1740800000 bytes (1.7 GB) copied, 67.1975 s, 25.9 MB/s
>
> And to the servers disk - I should note that this is alot faster than
> the test to the mounted vmdk on the servers disk above - not sure what
> to make of that.
>
>> dd if=/dev/zero of=/var/data/zerofile.tst bs=1k count=1700000
> 1700000+0 records in
> 1700000+0 records out
> 1740800000 bytes (1.7 GB) copied, 5.61148 s, 310 MB/s
>
> Thanks

These are the results with losetup (no errors or hang ups)

> losetup /dev/loop0 /var/data/FITZVICVDP01_2-flat.vmdk
> losetup -o 512 /dev/loop1 /dev/loop0
> mount /dev/loop1 /mnt/loop0p1/
> dd if=/dev/zero of=/mnt/loop0p1/zerofile.tst bs=1k count=1700000
1700000+0 records in
1700000+0 records out
1740800000 bytes (1.7 GB) copied, 25.36 s, 68.6 MB/s

> losetup /dev/loop0 /mnt/backup/FITZVICVDP01/FITZVICVDP01_2-flat.vmdk
> losetup -o 512 /dev/loop1 /dev/loop0
> mount /dev/loop1 /mnt/loop0p1/
> dd if=/dev/zero of=/mnt/loop0p1/zerofile.tst bs=1k count=1700000
1700000+0 records in
1700000+0 records out
1740800000 bytes (1.7 GB) copied, 81.9595 s, 21.2 MB/s


[Date Prev][Date Next]   [Thread Prev][Thread Next]   [Thread Index] [Date Index] [Author Index]