Slow Disk write inside the VM

[khaled.j.hussein]

Hi,

I am using Proxmox 6.4, and I have Dell MD3280 storage connected over ISCSI, I have 3 groups 2 of 1.6 TB 15K disks, and 1 of 5TB 7.2K disk speed, I configured the storage as LVM ISCSI and all working fine with me

I noticed lately that some of my VMs are slow for some actions, and I deep dive to investigate the issue, I used this command to test the disk speed

dd if=/dev/zero of=/tmp/test12.img bs=1G count=1 oflag=dsync

on the slow VMs the result looks like this

4000+0 records in
4000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 712.065 s, 5.9 MB/s

I did the test on another VM on the same node and the result was

1+0 records in
1+0 records out
1073741824 bytes (1.1 GB) copied, 5.46651 s, 196 MB/s

to do more tests I created many VMs with different disk setup, using LVM and using one and two partitions from different storage SRs, all new VMs created was fast in write and all of them above 150 MB/s

also I tried to use iscsi and virtio bus types but same results, no new VM has slow

I am using LVM in disk partitioning inside my debian installation


so I am really confused and don't know what is the problem and the cause of slowness, and where should I look to catch the problem

Thanks in advance

 

[mira]

The output of the slow VM doesn't match the one from the faster VM.

4000+0 records in
4000+0 records out
4194304000 bytes (4.2 GB, 3.9 GiB) copied, 712.065 s, 5.9 MB/s

This implies that you did the test with a block size of 1M and a count of 4000.

For benchmarking your storage, we recommend using fio.
You can find a sample command line below which will benchmark the worst case for IOPS (4K). For bandwidth tests you probably want to change `bs` to `1M` or `4M`.

fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4K --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 60G --filename=/path/to/testfile

 

[khaled.j.hussein]

Hi Mira,

Thanks for your reply, please find the below results on both servers using fio


SLOW SERVER

root@devl:~# fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4K --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 5G --filename=/data/testfile
write_4k: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.12
Starting 1 process
write_4k: Laying out IO file (1 file / 5120MiB)
Jobs: 1 (f=1): [W(1)][100.0%][w=564KiB/s][w=141 IOPS][eta 00m:00s]
write_4k: (groupid=0, jobs=1): err= 0: pid=5067: Sun Dec 5 11:49:27 2021
write: IOPS=128, BW=513KiB/s (525kB/s)(301MiB/600002msec); 0 zone resets
clat (msec): min=3, max=287, avg= 7.78, stdev= 4.16
lat (msec): min=3, max=287, avg= 7.78, stdev= 4.16
clat percentiles (msec):
| 1.00th=[ 5], 5.00th=[ 5], 10.00th=[ 5], 20.00th=[ 6],
| 30.00th=[ 6], 40.00th=[ 6], 50.00th=[ 6], 60.00th=[ 8],
| 70.00th=[ 10], 80.00th=[ 11], 90.00th=[ 13], 95.00th=[ 15],
| 99.00th=[ 20], 99.50th=[ 22], 99.90th=[ 34], 99.95th=[ 49],
| 99.99th=[ 131]
bw ( KiB/s): min= 40, max= 776, per=100.00%, avg=512.65, stdev=85.65, samples=1200
iops : min= 10, max= 194, avg=128.09, stdev=21.43, samples=1200
lat (msec) : 4=0.01%, 10=76.37%, 20=22.81%, 50=0.77%, 100=0.03%
lat (msec) : 250=0.01%, 500=0.01%
cpu : usr=0.42%, sys=2.55%, ctx=154935, majf=0, minf=11
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,76941,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
WRITE: bw=513KiB/s (525kB/s), 513KiB/s-513KiB/s (525kB/s-525kB/s), io=301MiB (315MB), run=600002-600002msec

Disk stats (read/write):
dm-2: ios=1/464962, merge=0/0, ticks=4/568688, in_queue=568688, util=63.54%, aggrios=1/310297, aggrmerge=0/154772, aggrticks=4/384828, aggrin_queue=380008, aggrutil=63.17%
sdb: ios=1/310297, merge=0/154772, ticks=4/384828, in_queue=380008, util=63.17%


FAST SERVER

root@debian4:/home/khaled# fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4K --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 5G --filename=/tmp/testfile
write_4k: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.25
Starting 1 process
write_4k: Laying out IO file (1 file / 5120MiB)
Jobs: 1 (f=1): [W(1)][100.0%][w=932KiB/s][w=233 IOPS][eta 00m:00s]
write_4k: (groupid=0, jobs=1): err= 0: pid=1224: Sun Dec 5 13:54:29 2021
write: IOPS=234, BW=940KiB/s (962kB/s)(551MiB/600004msec); 0 zone resets
clat (msec): min=3, max=263, avg= 4.25, stdev= 1.26
lat (msec): min=3, max=263, avg= 4.25, stdev= 1.26
clat percentiles (usec):
| 1.00th=[ 3621], 5.00th=[ 3785], 10.00th=[ 3851], 20.00th=[ 3949],
| 30.00th=[ 4015], 40.00th=[ 4080], 50.00th=[ 4146], 60.00th=[ 4228],
| 70.00th=[ 4293], 80.00th=[ 4359], 90.00th=[ 4555], 95.00th=[ 4752],
| 99.00th=[ 6783], 99.50th=[ 9110], 99.90th=[14746], 99.95th=[16581],
| 99.99th=[29754]
bw ( KiB/s): min= 456, max= 1064, per=100.00%, avg=940.65, stdev=32.70, samples=1199
iops : min= 114, max= 266, avg=235.08, stdev= 8.17, samples=1199
lat (msec) : 4=27.34%, 10=72.26%, 20=0.37%, 50=0.02%, 250=0.01%
lat (msec) : 500=0.01%
cpu : usr=0.41%, sys=3.34%, ctx=375803, majf=0, minf=13
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,140965,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
WRITE: bw=940KiB/s (962kB/s), 940KiB/s-940KiB/s (962kB/s-962kB/s), io=551MiB (577MB), run=600004-600004msec

Disk stats (read/write):
sda: ios=2/423616, merge=0/282212, ticks=6/566528, in_queue=751873, util=100.00%


Thanks

 

[mira]

For bandwidth tests you probably want to change `bs` to `1M` or `4M`.

Please run the benchmarks with a blocksize of 1M or 4M as well. In this case I'd recommend increasing the size of the file to 60G though.

 

[khaled.j.hussein]

Please check new results as recommended by you, with 60GB and 4M bs


############### Fast Server 60GB with 4K bs ########################################

root@debian4:/home/khaled# fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4K --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 60G --filename=/data/testfile
write_4k: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.25
Starting 1 process
write_4k: Laying out IO file (1 file / 61440MiB)
Jobs: 1 (f=1): [W(1)][100.0%][w=900KiB/s][w=225 IOPS][eta 00m:00s]
write_4k: (groupid=0, jobs=1): err= 0: pid=5871: Wed Dec 8 09:20:00 2021
write: IOPS=224, BW=897KiB/s (919kB/s)(526MiB/600003msec); 0 zone resets
clat (msec): min=3, max=226, avg= 4.45, stdev= 2.24
lat (msec): min=3, max=226, avg= 4.45, stdev= 2.24
clat percentiles (usec):
| 1.00th=[ 3752], 5.00th=[ 3916], 10.00th=[ 3982], 20.00th=[ 4080],
| 30.00th=[ 4178], 40.00th=[ 4228], 50.00th=[ 4293], 60.00th=[ 4359],
| 70.00th=[ 4490], 80.00th=[ 4621], 90.00th=[ 4817], 95.00th=[ 5080],
| 99.00th=[ 6980], 99.50th=[10421], 99.90th=[15270], 99.95th=[20841],
| 99.99th=[67634]
bw ( KiB/s): min= 472, max= 1042, per=100.00%, avg=897.87, stdev=49.66, samples=1199
iops : min= 118, max= 260, avg=224.35, stdev=12.42, samples=1199
lat (msec) : 4=11.36%, 10=88.09%, 20=0.49%, 50=0.05%, 100=0.01%
lat (msec) : 250=0.01%
cpu : usr=0.54%, sys=3.55%, ctx=269123, majf=0, minf=13
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,134557,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
WRITE: bw=897KiB/s (919kB/s), 897KiB/s-897KiB/s (919kB/s-919kB/s), io=526MiB (551MB), run=600003-600003msec

Disk stats (read/write):
sdb: ios=0/403585, merge=0/269970, ticks=0/557364, in_queue=742538, util=100.00%

############### Fast Server 60GB with 4M bs ########################################
root@debian4:/home/khaled# fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4M --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 60G --filename=/data/testfile
write_4k: (g=0): rw=write, bs=(R) 4096KiB-4096KiB, (W) 4096KiB-4096KiB, (T) 4096KiB-4096KiB, ioengine=psync, iodepth=1
fio-3.25
Starting 1 process
Jobs: 1 (f=1): [W(1)][100.0%][w=68.1MiB/s][w=17 IOPS][eta 00m:00s]
write_4k: (groupid=0, jobs=1): err= 0: pid=6383: Wed Dec 8 16:55:59 2021
write: IOPS=16, BW=64.6MiB/s (67.8MB/s)(37.9GiB/600017msec); 0 zone resets
clat (msec): min=27, max=512, avg=61.67, stdev=46.80
lat (msec): min=27, max=512, avg=61.90, stdev=46.80
clat percentiles (msec):
| 1.00th=[ 28], 5.00th=[ 29], 10.00th=[ 29], 20.00th=[ 29],
| 30.00th=[ 29], 40.00th=[ 30], 50.00th=[ 43], 60.00th=[ 65],
| 70.00th=[ 74], 80.00th=[ 87], 90.00th=[ 112], 95.00th=[ 142],
| 99.00th=[ 266], 99.50th=[ 288], 99.90th=[ 355], 99.95th=[ 439],
| 99.99th=[ 514]
bw ( KiB/s): min= 8192, max=147751, per=100.00%, avg=66210.78, stdev=37905.81, samples=1199
iops : min= 2, max= 36, avg=16.14, stdev= 9.24, samples=1199
lat (msec) : 50=52.02%, 100=34.76%, 250=12.03%, 500=1.18%, 750=0.01%
cpu : usr=0.44%, sys=0.51%, ctx=28827, majf=0, minf=14
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,9692,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
WRITE: bw=64.6MiB/s (67.8MB/s), 64.6MiB/s-64.6MiB/s (67.8MB/s-67.8MB/s), io=37.9GiB (40.7GB), run=600017-600017msec

Disk stats (read/write):
sdb: ios=0/58125, merge=0/19241, ticks=0/1535738, in_queue=1552562, util=100.00%

############### Slow Server 60GB with 4K bs ########################################

root@devl2:/home/khaled# fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4K --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 60G --filename=/data/testfile
write_4k: (g=0): rw=write, bs=(R) 4096B-4096B, (W) 4096B-4096B, (T) 4096B-4096B, ioengine=psync, iodepth=1
fio-3.25
Starting 1 process
write_4k: Laying out IO file (1 file / 61440MiB)
Jobs: 1 (f=1): [W(1)][100.0%][w=848KiB/s][w=212 IOPS][eta 00m:00s]
write_4k: (groupid=0, jobs=1): err= 0: pid=13636: Thu Dec 9 08:58:45 2021
write: IOPS=196, BW=785KiB/s (803kB/s)(460MiB/600005msec); 0 zone resets
clat (msec): min=3, max=1039, avg= 5.09, stdev= 5.72
lat (msec): min=3, max=1039, avg= 5.09, stdev= 5.72
clat percentiles (msec):
| 1.00th=[ 4], 5.00th=[ 5], 10.00th=[ 5], 20.00th=[ 5],
| 30.00th=[ 5], 40.00th=[ 5], 50.00th=[ 5], 60.00th=[ 5],
| 70.00th=[ 5], 80.00th=[ 5], 90.00th=[ 6], 95.00th=[ 9],
| 99.00th=[ 15], 99.50th=[ 20], 99.90th=[ 33], 99.95th=[ 43],
| 99.99th=[ 234]
bw ( KiB/s): min= 15, max= 992, per=100.00%, avg=786.12, stdev=104.90, samples=1197
iops : min= 3, max= 248, avg=196.41, stdev=26.24, samples=1197
lat (msec) : 4=2.05%, 10=94.26%, 20=3.25%, 50=0.41%, 100=0.01%
lat (msec) : 250=0.02%, 500=0.01%, 1000=0.01%, 2000=0.01%
cpu : usr=0.52%, sys=3.40%, ctx=235414, majf=0, minf=12
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,117694,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
WRITE: bw=785KiB/s (803kB/s), 785KiB/s-785KiB/s (803kB/s-803kB/s), io=460MiB (482MB), run=600005-600005msec

Disk stats (read/write):
dm-2: ios=0/706888, merge=0/0, ticks=0/891948, in_queue=891948, util=99.20%, aggrios=0/470830, aggrmerge=0/236342, aggrticks=0/534487, aggrin_queue=714798, aggrutil=99.19%
sda: ios=0/470830, merge=0/236342, ticks=0/534487, in_queue=714798, util=99.19%

############### Slow Server 60GB with 4M bs ########################################

root@devl2:/home/khaled# fio --ioengine=psync --direct=1 --sync=1 --rw=write --bs=4M --numjobs=1 --iodepth=1 --runtime=600 --time_based --name write_4k --size 60G --filename=/data/testfile
write_4k: (g=0): rw=write, bs=(R) 4096KiB-4096KiB, (W) 4096KiB-4096KiB, (T) 4096KiB-4096KiB, ioengine=psync, iodepth=1
fio-3.25
Starting 1 process
Jobs: 1 (f=1): [W(1)][100.0%][w=100MiB/s][w=25 IOPS][eta 00m:00s]
write_4k: (groupid=0, jobs=1): err= 0: pid=13682: Thu Dec 9 09:48:14 2021
write: IOPS=15, BW=62.6MiB/s (65.7MB/s)(36.7GiB/600008msec); 0 zone resets
clat (msec): min=27, max=1639, avg=63.62, stdev=60.63
lat (msec): min=27, max=1639, avg=63.86, stdev=60.63
clat percentiles (msec):
| 1.00th=[ 29], 5.00th=[ 29], 10.00th=[ 29], 20.00th=[ 29],
| 30.00th=[ 30], 40.00th=[ 31], 50.00th=[ 33], 60.00th=[ 40],
| 70.00th=[ 69], 80.00th=[ 95], 90.00th=[ 136], 95.00th=[ 186],
| 99.00th=[ 292], 99.50th=[ 330], 99.90th=[ 430], 99.95th=[ 460],
| 99.99th=[ 1636]
bw ( KiB/s): min= 8192, max=147456, per=100.00%, avg=64332.79, stdev=41317.20, samples=1195
iops : min= 2, max= 36, avg=15.45, stdev=10.06, samples=1195
lat (msec) : 50=65.19%, 100=16.40%, 250=16.35%, 500=2.03%, 750=0.01%
lat (msec) : 2000=0.01%
cpu : usr=0.50%, sys=0.48%, ctx=26704, majf=0, minf=13
IO depths : 1=100.0%, 2=0.0%, 4=0.0%, 8=0.0%, 16=0.0%, 32=0.0%, >=64=0.0%
submit : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
complete : 0=0.0%, 4=100.0%, 8=0.0%, 16=0.0%, 32=0.0%, 64=0.0%, >=64=0.0%
issued rwts: total=0,9394,0,0 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=1

Run status group 0 (all jobs):
WRITE: bw=62.6MiB/s (65.7MB/s), 62.6MiB/s-62.6MiB/s (65.7MB/s-65.7MB/s), io=36.7GiB (39.4GB), run=600008-600008msec

Disk stats (read/write):
dm-2: ios=0/56219, merge=0/0, ticks=0/631104, in_queue=631104, util=99.85%, aggrios=0/65761, aggrmerge=0/18674, aggrticks=0/1485997, aggrin_queue=1508018, aggrutil=99.85%
sda: ios=0/65761, merge=0/18674, ticks=0/1485997, in_queue=1508018, util=99.85%

 

[mira]

Thanks for the fio output.

There's not that much of a difference when it comes to bandwidth (62MB/s vs 65MB/s), and even IOPS aren't that bad it seems.
Could you provide some more information about your storage?
What are the exact disks you're using?
How are they set up?
How is the storage connected to your PVE host? (NIC, speed)

 

[khaled.j.hussein]

Thanks Mira for your reply,

we are using Dell MD 3820, disks are two types, 15K and 7.2K , I did the test on both and it was the same, I am using RAID 10 for all groups,
strorage connection to my Proxmox nodes is 1GB Ethernet

but the weird thing as I mentioned before is the difference between two VMs running on the same enviroment, one of them is fast and the other is slow

I am using debian OS and using LVM setup for disk partitions

Thanks

 

[mira]

The issue might be something else entirely then.
Could you provide the VM configs of a fast one and a slow one? You can get the config by running qm config <VMID>.

Please also provide the journal/syslog that covers the start of the VM and at least a few minutes of slow operation.