Very slow write to external disk occasionally

stra4d

Well-Known Member
Mar 1, 2012
80
0
46
We occasionally experience a backup to disk (not a vzdump - a copy of the vzdump files, after the vzdump backup has finished) that is very slow. The syslog is full of:

Code:
pvestatd[1387]: status update time (286.687 seconds)

It is not always the same disk (there is a rotation). And after a reboot, the disk will work fine (the next time it comes up in rotation).

Looking at this thread I did the following:

Code:
# time pvesm status
drive2-backups    dir 1       720915496       318580432       365691644 47.06%
drive2-vm         dir 1       720915496       318580432       365691644 47.06%
local             dir 1        41153856         2377108        36663212 6.59%
local-lvm       lvmthin 1       225697792       120996586       104701205 54.11%

real    5m41.645s
user    0m0.492s
sys     0m0.076s
which took quite a while.

Info:
Code:
# pveversion --verbose
proxmox-ve: 4.4-78 (running kernel: 4.4.35-2-pve)
pve-manager: 4.4-5 (running version: 4.4-5/c43015a5)
pve-kernel-4.4.35-2-pve: 4.4.35-78
pve-kernel-4.4.19-1-pve: 4.4.19-66
lvm2: 2.02.116-pve3
corosync-pve: 2.4.0-1
libqb0: 1.0-1
pve-cluster: 4.0-48
qemu-server: 4.0-102
pve-firmware: 1.1-10
libpve-common-perl: 4.0-85
libpve-access-control: 4.0-19
libpve-storage-perl: 4.0-71
pve-libspice-server1: 0.12.8-1
vncterm: 1.2-1
pve-docs: 4.4-1
pve-qemu-kvm: 2.7.1-1
pve-container: 1.0-90
pve-firewall: 2.0-33
pve-ha-manager: 1.0-38
ksm-control-daemon: 1.2-1
glusterfs-client: 3.5.2-2+deb8u3
lxc-pve: 2.0.6-5
lxcfs: 2.0.5-pve2
criu: 1.6.0-1
novnc-pve: 0.5-8
smartmontools: 6.5+svn4324-1~pve80
zfsutils: 0.6.5.8-pve13~bpo80

Any ideas?
 
No. I had to reboot to get the backup to actually finish. Just says:

Code:
(Nothing has been logged yet.)
 
I had the same experience again on Friday. Extremely slow backup - after a reboot it worked fine. Same results in the /var/log/syslog:
Code:
Oct 29 06:32:03 servername pvestatd[1394]: status update time (194.423 seconds)
Oct 29 06:32:05 servername systemd-timesyncd[907]: interval/delta/delay/jitter/drift 2048s/+0.002s/0.067s/0.002s/+10ppm
Oct 29 06:32:26 servername pvestatd[1394]: status update time (23.270 seconds)
Oct 29 06:37:46 servername pvestatd[1394]: status update time (310.438 seconds)
Oct 29 06:45:22 servername pvestatd[1394]: status update time (455.849 seconds)
Oct 29 06:47:01 servername CRON[31409]: (root) CMD (test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly ))
Oct 29 06:49:55 servername pvestatd[1394]: status update time (272.526 seconds)
Oct 29 06:50:42 servername pvestatd[1394]: status update time (47.528 seconds)
Oct 29 06:50:48 servername pvestatd[1394]: status update time (6.271 seconds)
Oct 29 06:56:03 servername pvestatd[1394]: status update time (310.406 seconds)
Oct 29 07:01:48 servername pvestatd[1394]: status update time (345.026 seconds)
Oct 29 07:05:57 servername pvestatd[1394]: status update time (248.939 seconds)
Oct 29 07:06:14 servername systemd-timesyncd[907]: interval/delta/delay/jitter/drift 2048s/-0.001s/0.066s/0.002s/+10ppm
Oct 29 07:08:44 servername pvestatd[1394]: status update time (167.049 seconds)
Oct 29 07:09:07 servername pvestatd[1394]: status update time (22.955 seconds)
Oct 29 07:09:25 servername rrdcached[1222]: flushing old values
Oct 29 07:09:25 servername rrdcached[1222]: rotating journals
Oct 29 07:09:25 servername rrdcached[1222]: started new journal /var/lib/rrdcached/journal/rrd.journal.1509275365.412940
Oct 29 07:09:25 servername rrdcached[1222]: removing old journal /var/lib/rrdcached/journal/rrd.journal.1509268165.412944
Oct 29 07:16:04 servername pvestatd[1394]: status update time (406.676 seconds)
Oct 29 07:17:01 servername CRON[395]: (root) CMD (   cd / && run-parts --report /etc/cron.hourly)
Oct 29 07:21:28 servername pvestatd[1394]: status update time (324.158 seconds)
Oct 29 07:25:17 servername pvestatd[1394]: status update time (228.702 seconds)
Oct 29 07:27:24 servername pvestatd[1394]: status update time (127.463 seconds)
Oct 29 07:27:30 servername pvestatd[1394]: status update time (6.291 seconds)
Oct 29 07:31:22 servername pvestatd[1394]: status update time (227.744 seconds)
Oct 29 07:37:02 servername pvestatd[1394]: status update time (340.074 seconds)
Oct 29 07:40:22 servername systemd-timesyncd[907]: interval/delta/delay/jitter/drift 2048s/+0.001s/0.066s/0.002s/+10ppm
Oct 29 07:43:48 servername pvestatd[1394]: status update time (406.091 seconds)
Oct 29 07:45:44 servername pvestatd[1394]: status update time (115.827 seconds)
Oct 29 07:45:51 servername pvestatd[1394]: status update time (6.461 seconds)
Oct 29 07:46:30 servername pvestatd[1394]: status update time (36.744 seconds)
Oct 29 07:52:55 servername pvestatd[1394]: status update time (385.053 seconds)
Oct 29 07:57:59 servername pvestatd[1394]: status update time (304.176 seconds)
Oct 29 08:02:14 servername pvestatd[1394]: status update time (254.243 seconds)
Oct 29 08:03:51 servername pvestatd[1394]: status update time (96.835 seconds)
 
After the reboot, the times were much shorter:
Code:
Oct 30 09:36:16 servername systemd-timesyncd[906]: interval/delta/delay/jitter/drift 2048s/+0.002s/0.016s/0.004s/+9ppm
Oct 30 09:36:18 servername pvestatd[1399]: status update time (5.212 seconds)
Oct 30 09:36:29 servername pvestatd[1399]: status update time (5.428 seconds)
Oct 30 09:36:41 servername pvestatd[1399]: status update time (8.649 seconds)
Oct 30 09:36:51 servername pvestatd[1399]: status update time (7.346 seconds)
Oct 30 09:36:59 servername pvestatd[1399]: status update time (6.057 seconds)
Oct 30 09:37:10 servername pvestatd[1399]: status update time (7.352 seconds)
Oct 30 09:37:30 servername pvestatd[1399]: status update time (6.794 seconds)
Oct 30 09:37:40 servername pvestatd[1399]: status update time (7.185 seconds)
Oct 30 09:38:10 servername pvestatd[1399]: status update time (6.422 seconds)
Oct 30 09:38:20 servername pvestatd[1399]: status update time (6.851 seconds)
Oct 30 09:38:39 servername pvestatd[1399]: status update time (5.467 seconds)
Oct 30 09:38:51 servername pvestatd[1399]: status update time (8.224 seconds)
Oct 30 09:39:00 servername pvestatd[1399]: status update time (7.351 seconds)
Oct 30 09:39:09 servername pvestatd[1399]: status update time (5.837 seconds)
Oct 30 09:39:21 servername pvestatd[1399]: status update time (8.214 seconds)
Oct 30 09:39:31 servername pvestatd[1399]: status update time (8.069 seconds)
Oct 30 09:39:41 servername pvestatd[1399]: status update time (7.186 seconds)
Oct 30 09:39:48 servername pvestatd[1399]: status update time (5.660 seconds)
Oct 30 09:39:58 servername pvestatd[1399]: status update time (5.092 seconds)
Oct 30 09:40:20 servername pvestatd[1399]: status update time (7.199 seconds)
Oct 30 09:40:30 servername pvestatd[1399]: status update time (7.110 seconds)
Oct 30 09:40:48 servername pvestatd[1399]: status update time (5.663 seconds)
Oct 30 09:41:01 servername pvestatd[1399]: status update time (7.822 seconds)
Oct 30 09:41:10 servername pvestatd[1399]: status update time (6.978 seconds)
Oct 30 09:41:30 servername pvestatd[1399]: status update time (7.619 seconds)
Oct 30 09:41:40 servername pvestatd[1399]: status update time (7.000 seconds)
Oct 30 09:41:51 servername pvestatd[1399]: status update time (7.222 seconds)
Oct 30 09:42:00 servername pvestatd[1399]: status update time (6.938 seconds)
Oct 30 09:42:30 servername pvestatd[1399]: status update time (6.562 seconds)
Oct 30 09:42:40 servername pvestatd[1399]: status update time (7.150 seconds)
Oct 30 09:42:59 servername pvestatd[1399]: status update time (6.131 seconds)
Oct 30 09:43:11 servername pvestatd[1399]: status update time (7.704 seconds)
Oct 30 09:43:20 servername pvestatd[1399]: status update time (7.159 seconds)
Oct 30 09:43:29 servername pvestatd[1399]: status update time (5.842 seconds)
Oct 30 09:43:40 servername pvestatd[1399]: status update time (7.156 seconds)
Oct 30 09:44:00 servername pvestatd[1399]: status update time (6.559 seconds)
Oct 30 09:44:10 servername pvestatd[1399]: status update time (6.855 seconds)
Oct 30 09:44:40 servername pvestatd[1399]: status update time (6.897 seconds)
Oct 30 09:44:49 servername pvestatd[1399]: status update time (6.707 seconds)
Oct 30 09:45:10 servername pvestatd[1399]: status update time (7.400 seconds)