Groups | Search | Server Info | Keyboard shortcuts | Login | Register [http] [https] [nntp] [nntps]

Groups > linux.kernel > #1457328 > unrolled thread

Filesystem slow write performance

Back to article view | Back to linux.kernel

Contents

  Filesystem slow write performance Babu Moger <babu.moger@oracle.com> - 2016-08-06 22:30 +0200
    Re: Filesystem slow write performance Babu Moger <babu.moger@oracle.com> - 2016-08-09 06:30 +0200

#1457328 — Filesystem slow write performance

Hi,

Seeing some terrible write performance with ext3/4 writes.  Reads are fine.

I have a created loop device and mounted as ext3(tried ext4 also).

Here is iostat output. await time is pretty high most of the time.

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s 
avgrq-sz avgqu-sz   await  svctm  %util
loop0             0.00     0.00    0.00  133.00     0.00 1064.00     
8.00   124.14  835.61   7.52 100.00
dm-0              0.00     0.00    0.00  132.00     0.00 1056.00     
8.00     1.00    7.52   7.52  99.20

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s 
avgrq-sz avgqu-sz   await  svctm  %util
loop0             0.00     0.00    0.00   94.00     0.00 752.00     
8.00   124.18  901.02  10.64 100.00
dm-0              0.00     0.00    0.00   92.00     0.00 736.00     
8.00     1.02   11.09  10.87 100.00

Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s 
avgrq-sz avgqu-sz   await  svctm  %util
loop0             0.00     0.00    0.00  132.00     0.00 1056.00     
8.00   124.56 1329.30   7.58 100.00
dm-0              0.00     0.00    0.00  141.00     0.00 1128.00     
8.00     1.08    7.72   7.06  99.60

Tags output
[root@build-t7 0]# cat tags
nr_tags=128, reserved_tags=0, bits_per_word=5
nr_free=128, nr_reserved=0
active_queues=0

Here is the output of  "echo w > /proc/sysrq-trigger" when the problem 
happens.

Aug  3 12:18:55 build-t7 kernel: kworker/u512:0  D 00000000009defd4     
0     6      2 0x06000000
Aug  3 12:18:55 build-t7 kernel: Workqueue: writeback 
bdi_writeback_workfn (flush-7:0)
Aug  3 12:18:55 build-t7 kernel: Call Trace:
Aug  3 12:18:55 build-t7 kernel: [00000000009dc9e4] schedule+0x24/0xa0
Aug  3 12:18:55 build-t7 kernel: [00000000009defd4] 
schedule_timeout+0x134/0x220
Aug  3 12:18:55 build-t7 kernel: [00000000009dc044] 
io_schedule_timeout+0x84/0x100
Aug  3 12:18:55 build-t7 kernel: [00000000006be64c] bt_get+0x10c/0x1e0
Aug  3 12:18:55 build-t7 kernel: [00000000006be7f4] blk_mq_get_tag+0x74/0xe0
Aug  3 12:18:55 build-t7 kernel: [00000000006ba570] 
__blk_mq_alloc_request+0x10/0x180
Aug  3 12:18:55 build-t7 kernel: [00000000006bb9f4] 
blk_mq_map_request+0x1d4/0x260
Aug  3 12:18:55 build-t7 kernel: [00000000006bbd40] 
blk_sq_make_request+0x60/0x300
Aug  3 12:18:55 build-t7 kernel: [00000000006afa58] 
generic_make_request+0x78/0xe0
Aug  3 12:18:55 build-t7 kernel: [00000000006afb44] submit_bio+0x84/0x160
Aug  3 12:18:55 build-t7 kernel: [00000000005f7cb4] _submit_bh+0x174/0x200
Aug  3 12:18:55 build-t7 kernel: [00000000005f7d54] submit_bh+0x14/0x40
Aug  3 12:18:55 build-t7 kernel: [00000000005fc248] 
__block_write_full_page.clone.0+0x2c8/0x500
Aug  3 12:18:55 build-t7 kernel: [00000000005fc620] 
block_write_full_page+0xa0/0xe0
Aug  3 12:18:55 build-t7 kernel: [00000000100e7d94] 
ext3_writeback_writepage+0x134/0x200 [ext3]
Aug  3 12:18:55 build-t7 kernel: [0000000000562798] __writepage+0x18/0x60

Aug  3 12:18:55 build-t7 kernel: loop0           D 00000000009deff4     
0 15632      2 0x01000400
Aug  3 12:18:55 build-t7 kernel: Call Trace:
Aug  3 12:18:55 build-t7 kernel: [00000000009dc9e4] schedule+0x24/0xa0
Aug  3 12:18:55 build-t7 kernel: [00000000009deff4] 
schedule_timeout+0x154/0x220
Aug  3 12:18:55 build-t7 kernel: [00000000009dc044] 
io_schedule_timeout+0x84/0x100
Aug  3 12:18:55 build-t7 kernel: [00000000009dcdbc] bit_wait_io+0x3c/0x80
Aug  3 12:18:55 build-t7 kernel: [00000000009dd1c4] __wait_on_bit+0x84/0x100
Aug  3 12:18:55 build-t7 kernel: [000000000055719c] 
wait_on_page_bit+0x7c/0xa0
Aug  3 12:18:55 build-t7 kernel: [00000000005586a8] 
filemap_fdatawait_range+0xc8/0x140
Aug  3 12:18:55 build-t7 kernel: [00000000005587fc] 
filemap_write_and_wait_range+0x3c/0x80
Aug  3 12:18:55 build-t7 kernel: [0000000000558a58] 
__generic_file_write_iter+0xb8/0x140
Aug  3 12:18:55 build-t7 kernel: [0000000000558bac] 
generic_file_write_iter+0xcc/0x1e0
Aug  3 12:18:55 build-t7 kernel: [00000000007ca000] lo_rw_aio+0x180/0x240
Aug  3 12:18:55 build-t7 kernel: [00000000007ca260] 
do_req_filebacked+0x1a0/0x1c0
Aug  3 12:18:55 build-t7 kernel: [00000000007ca2b4] 
loop_queue_work+0x34/0x80
Aug  3 12:18:55 build-t7 kernel: [0000000000491944] 
kthread_worker_fn+0x44/0x180
Aug  3 12:18:55 build-t7 kernel: [0000000000491c4c] kthread+0xac/0xe0
Aug  3 12:18:55 build-t7 kernel: [0000000000406184] ret_from_fork+0x1c/0x2c

Aug  3 12:18:55 build-t7 kernel: livecd-creator  D 00000000009deff4     
0 15627   2676 0x308000103000400
Aug  3 12:18:55 build-t7 kernel: Call Trace:
Aug  3 12:18:55 build-t7 kernel: [00000000009dc9e4] schedule+0x24/0xa0
Aug  3 12:18:55 build-t7 kernel: [00000000009deff4] 
schedule_timeout+0x154/0x220
Aug  3 12:18:55 build-t7 kernel: [00000000009dc044] 
io_schedule_timeout+0x84/0x100
Aug  3 12:18:55 build-t7 kernel: [00000000009dcdbc] bit_wait_io+0x3c/0x80
Aug  3 12:18:55 build-t7 kernel: [00000000009dd1c4] __wait_on_bit+0x84/0x100
Aug  3 12:18:55 build-t7 kernel: [000000000055719c] 
wait_on_page_bit+0x7c/0xa0
Aug  3 12:18:55 build-t7 kernel: [00000000005586a8] 
filemap_fdatawait_range+0xc8/0x140
Aug  3 12:18:55 build-t7 kernel: [00000000005587fc] 
filemap_write_and_wait_range+0x3c/0x80
Aug  3 12:18:55 build-t7 kernel: [00000000100e4258] 
ext3_sync_file+0x58/0x2c0 [ext3]
Aug  3 12:18:55 build-t7 kernel: [00000000005f54d8] 
vfs_fsync_range+0x38/0xa0
Aug  3 12:18:55 build-t7 kernel: [00000000005f555c] vfs_fsync+0x1c/0x40
Aug  3 12:18:55 build-t7 kernel: [00000000005f55a8] do_fsync+0x28/0x60
Aug  3 12:18:55 build-t7 kernel: [00000000005f55f0] SyS_fdatasync+0x10/0x40

I am not an expert on this area. Note that I am bit behind on the kernel 
version(but not a whole lot). Working on to recreate this
with latest upstream kernel. Looked at the upstream patches and tried 
most of the upstream patches which appear to be related
and nothing helped. Problem is fairly easy to reproduce. Let me know if 
you want me to try something.
Thanks
Babu Moger

[toc] | [next] | [standalone]

#1458396

I wasn't able to repro this with mainline. Sorry for the noise.

On 8/6/2016 1:49 PM, Babu Moger wrote:
> Hi,
>
> Seeing some terrible write performance with ext3/4 writes.  Reads are 
> fine.
>
> I have a created loop device and mounted as ext3(tried ext4 also).
>
> Here is iostat output. await time is pretty high most of the time.
>
> Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s 
> avgrq-sz avgqu-sz   await  svctm  %util
> loop0             0.00     0.00    0.00  133.00     0.00 1064.00     
> 8.00   124.14  835.61   7.52 100.00
> dm-0              0.00     0.00    0.00  132.00     0.00 1056.00     
> 8.00     1.00    7.52   7.52  99.20
>
> Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s 
> avgrq-sz avgqu-sz   await  svctm  %util
> loop0             0.00     0.00    0.00   94.00     0.00 752.00     
> 8.00   124.18  901.02  10.64 100.00
> dm-0              0.00     0.00    0.00   92.00     0.00 736.00     
> 8.00     1.02   11.09  10.87 100.00
>
> Device:         rrqm/s   wrqm/s     r/s     w/s   rsec/s   wsec/s 
> avgrq-sz avgqu-sz   await  svctm  %util
> loop0             0.00     0.00    0.00  132.00     0.00 1056.00     
> 8.00   124.56 1329.30   7.58 100.00
> dm-0              0.00     0.00    0.00  141.00     0.00 1128.00     
> 8.00     1.08    7.72   7.06  99.60
>
> Tags output
> [root@build-t7 0]# cat tags
> nr_tags=128, reserved_tags=0, bits_per_word=5
> nr_free=128, nr_reserved=0
> active_queues=0
>
> Here is the output of  "echo w > /proc/sysrq-trigger" when the problem 
> happens.
>
> Aug  3 12:18:55 build-t7 kernel: kworker/u512:0  D 
> 00000000009defd4     0     6      2 0x06000000
> Aug  3 12:18:55 build-t7 kernel: Workqueue: writeback 
> bdi_writeback_workfn (flush-7:0)
> Aug  3 12:18:55 build-t7 kernel: Call Trace:
> Aug  3 12:18:55 build-t7 kernel: [00000000009dc9e4] schedule+0x24/0xa0
> Aug  3 12:18:55 build-t7 kernel: [00000000009defd4] 
> schedule_timeout+0x134/0x220
> Aug  3 12:18:55 build-t7 kernel: [00000000009dc044] 
> io_schedule_timeout+0x84/0x100
> Aug  3 12:18:55 build-t7 kernel: [00000000006be64c] bt_get+0x10c/0x1e0
> Aug  3 12:18:55 build-t7 kernel: [00000000006be7f4] 
> blk_mq_get_tag+0x74/0xe0
> Aug  3 12:18:55 build-t7 kernel: [00000000006ba570] 
> __blk_mq_alloc_request+0x10/0x180
> Aug  3 12:18:55 build-t7 kernel: [00000000006bb9f4] 
> blk_mq_map_request+0x1d4/0x260
> Aug  3 12:18:55 build-t7 kernel: [00000000006bbd40] 
> blk_sq_make_request+0x60/0x300
> Aug  3 12:18:55 build-t7 kernel: [00000000006afa58] 
> generic_make_request+0x78/0xe0
> Aug  3 12:18:55 build-t7 kernel: [00000000006afb44] submit_bio+0x84/0x160
> Aug  3 12:18:55 build-t7 kernel: [00000000005f7cb4] 
> _submit_bh+0x174/0x200
> Aug  3 12:18:55 build-t7 kernel: [00000000005f7d54] submit_bh+0x14/0x40
> Aug  3 12:18:55 build-t7 kernel: [00000000005fc248] 
> __block_write_full_page.clone.0+0x2c8/0x500
> Aug  3 12:18:55 build-t7 kernel: [00000000005fc620] 
> block_write_full_page+0xa0/0xe0
> Aug  3 12:18:55 build-t7 kernel: [00000000100e7d94] 
> ext3_writeback_writepage+0x134/0x200 [ext3]
> Aug  3 12:18:55 build-t7 kernel: [0000000000562798] __writepage+0x18/0x60
>
> Aug  3 12:18:55 build-t7 kernel: loop0           D 
> 00000000009deff4     0 15632      2 0x01000400
> Aug  3 12:18:55 build-t7 kernel: Call Trace:
> Aug  3 12:18:55 build-t7 kernel: [00000000009dc9e4] schedule+0x24/0xa0
> Aug  3 12:18:55 build-t7 kernel: [00000000009deff4] 
> schedule_timeout+0x154/0x220
> Aug  3 12:18:55 build-t7 kernel: [00000000009dc044] 
> io_schedule_timeout+0x84/0x100
> Aug  3 12:18:55 build-t7 kernel: [00000000009dcdbc] bit_wait_io+0x3c/0x80
> Aug  3 12:18:55 build-t7 kernel: [00000000009dd1c4] 
> __wait_on_bit+0x84/0x100
> Aug  3 12:18:55 build-t7 kernel: [000000000055719c] 
> wait_on_page_bit+0x7c/0xa0
> Aug  3 12:18:55 build-t7 kernel: [00000000005586a8] 
> filemap_fdatawait_range+0xc8/0x140
> Aug  3 12:18:55 build-t7 kernel: [00000000005587fc] 
> filemap_write_and_wait_range+0x3c/0x80
> Aug  3 12:18:55 build-t7 kernel: [0000000000558a58] 
> __generic_file_write_iter+0xb8/0x140
> Aug  3 12:18:55 build-t7 kernel: [0000000000558bac] 
> generic_file_write_iter+0xcc/0x1e0
> Aug  3 12:18:55 build-t7 kernel: [00000000007ca000] lo_rw_aio+0x180/0x240
> Aug  3 12:18:55 build-t7 kernel: [00000000007ca260] 
> do_req_filebacked+0x1a0/0x1c0
> Aug  3 12:18:55 build-t7 kernel: [00000000007ca2b4] 
> loop_queue_work+0x34/0x80
> Aug  3 12:18:55 build-t7 kernel: [0000000000491944] 
> kthread_worker_fn+0x44/0x180
> Aug  3 12:18:55 build-t7 kernel: [0000000000491c4c] kthread+0xac/0xe0
> Aug  3 12:18:55 build-t7 kernel: [0000000000406184] 
> ret_from_fork+0x1c/0x2c
>
> Aug  3 12:18:55 build-t7 kernel: livecd-creator  D 
> 00000000009deff4     0 15627   2676 0x308000103000400
> Aug  3 12:18:55 build-t7 kernel: Call Trace:
> Aug  3 12:18:55 build-t7 kernel: [00000000009dc9e4] schedule+0x24/0xa0
> Aug  3 12:18:55 build-t7 kernel: [00000000009deff4] 
> schedule_timeout+0x154/0x220
> Aug  3 12:18:55 build-t7 kernel: [00000000009dc044] 
> io_schedule_timeout+0x84/0x100
> Aug  3 12:18:55 build-t7 kernel: [00000000009dcdbc] bit_wait_io+0x3c/0x80
> Aug  3 12:18:55 build-t7 kernel: [00000000009dd1c4] 
> __wait_on_bit+0x84/0x100
> Aug  3 12:18:55 build-t7 kernel: [000000000055719c] 
> wait_on_page_bit+0x7c/0xa0
> Aug  3 12:18:55 build-t7 kernel: [00000000005586a8] 
> filemap_fdatawait_range+0xc8/0x140
> Aug  3 12:18:55 build-t7 kernel: [00000000005587fc] 
> filemap_write_and_wait_range+0x3c/0x80
> Aug  3 12:18:55 build-t7 kernel: [00000000100e4258] 
> ext3_sync_file+0x58/0x2c0 [ext3]
> Aug  3 12:18:55 build-t7 kernel: [00000000005f54d8] 
> vfs_fsync_range+0x38/0xa0
> Aug  3 12:18:55 build-t7 kernel: [00000000005f555c] vfs_fsync+0x1c/0x40
> Aug  3 12:18:55 build-t7 kernel: [00000000005f55a8] do_fsync+0x28/0x60
> Aug  3 12:18:55 build-t7 kernel: [00000000005f55f0] 
> SyS_fdatasync+0x10/0x40
>
> I am not an expert on this area. Note that I am bit behind on the 
> kernel version(but not a whole lot). Working on to recreate this
> with latest upstream kernel. Looked at the upstream patches and tried 
> most of the upstream patches which appear to be related
> and nothing helped. Problem is fairly easy to reproduce. Let me know 
> if you want me to try something.
> Thanks
> Babu Moger

[toc] | [prev] | [standalone]

Back to top | Article view | linux.kernel

csiph-web