Crash: /proc/sys/kernel/hung_task_timeout_secs - Problem mit ZFS?

logics · Sep 8, 2019

Hi,

ich hatte heute Nacht einen heftigen Crash. Es ging gar nichts mehr.

Auswirkung des Problems:

Kein SSH Zugriff mehr möglich. Weder auf Host noch auf VM
Es läuft wohl gar nichts mehr; es wurden keine Logs mehr geschrieben etc.
Per IPMI über HTML5 KVM: Es zeigt sich folgender Screenshot. Ich hatte versucht mich als root einzuloggen, aber jegliche Eingaben werden nicht mehr angenommen. Auch das Senden von STRG ALT ENTF bewirkte nichts mehr.

Konnte die Situation nur durch das Senden eines RESET Signals über IPMI auflösen.

Meldungen:

"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message
INFO: task modprobe:30143 blocked for more than 120 seconds

Weitere Meldungen:

task txg_sync:547 blocked for more than 120 seconds
task zpool:30139 blocked for more than 120 seconds
task vdev_open:30141 blocked for more than 120 seconds
task modprobe:30143 blocked for more than 120 seconds
task zpool:30148 blocked for more than 120 seconds
task zvol:30163 blocked for more than 120 seconds
task zvol:30167 blocked for more than 120 seconds
task zvol:323 blocked for more than 120 seconds

Das sind wohl alles Prozesse, die mit ZFS zu tun haben. Jedoch weiß ich nicht, ob eine falsche ZFS Einstellung Schuld am Crash ist, oder was das Problem ist.

Zeitpunkt des Absturzes

Durch Betrachten von /var/log/syslog auf der VM:
Die VM zeigte die letzte normale Meldung um Sep 8 00:23:31
Um 00:25 Uhr war die VM schon nicht mehr funktionsfähig. Das zeigt sich am Ausbleiben einer Logmeldung um 00:25 Uhr eines Cronjobs.
Keine Infos bezüglich des Absturzes ersichtlich. Keine Logs bis zum Neustart.
Durch Betrachten von /var/log/syslog auf dem Host:
Der Host zeigte die letzte normale Meldung um Sep 8 00:23:50 (irgendein UFW BLOCK, nichts interessantes)
Keine Infos bezüglich des Absturzes ersichtlich. Keine Logs bis zum Neustart.
Zeitpunkte der Meldungen, die durch HTML5 KVM sichtbar sind: 30452 und 30572 Sekunden (ca. 8.5 Stunden) nach Start des Rechners.
- Der letzte Neustart erfolgte gemäß /var/log/syslog Sep 7 16:00:05
- 30452 Sekunden entspricht 08:27:32 (HH:MM:SS) --> Ausgabe erfolgte 00:27:37 Uhr
- 30572 Sekunden entspricht 08:29:32 (HH:MM:SS) --> Ausgabe erfolgte 00:29:37 Uhr

Infos zum System
Habe proxmox-ve_6.0-1.iso vorgestern frisch installiert. Es läuft momentan nur eine VM drauf, die sich max. 27 der 32 GB RAM schnappen darf. Die VM hatte die ganze Zeit 19.8 GB free memory, etwa 6.6 GB cached und 1.4 GB active (used).

uname -a
Linux XirraDedi 5.0.21-1-pve #1 SMP PVE 5.0.21-2 (Wed, 28 Aug 2019 15:12:18 +0200) x86_64 GNU/Linux

Es handelt sich um einen Server mit folgenden Specs:

Supermicro Super Server/X11SSL-F, BIOS 2.2 05/23/2018
Intel(R) Xeon(R) CPU E3-1230 v6 @ 3.50GHz
32 GB RAM
2x 500 GB SSDs in ZFS RAID0 (ist nicht der Hauptserver, daher kein RAID1)

Weitere Infos:

Benchmarks mit dd funktionieren problemlos:
dd if=/dev/zero of=/tmp/output conv=fdatasync bs=384k count=1k; rm -f /tmp/output402653184 bytes (403 MB, 384 MiB) copied, 0.219217 s, 1.8 GB/s
cd /homedd if=/dev/zero of=tempfile bs=1M count=2048 conv=fdatasync,notrunc
2147483648 bytes (2.1 GB, 2.0 GiB) copied, 0.649029 s, 3.3 GB/s
echo 3 | tee /proc/sys/vm/drop_caches
dd if=tempfile of=/dev/null bs=1M count=2048
2147483648 bytes (2.1 GB, 2.0 GiB) copied, 0.178295 s, 12.0 GB/s
dd if=tempfile of=/dev/null bs=1M count=2048
2147483648 bytes (2.1 GB, 2.0 GiB) copied, 0.175239 s, 12.3 GB/s
rm tempfile

Benchmarks mit fio funktionieren problemlos:

Code:

apt-get install fiofio --name=writefile --size=10G --filesize=10G --filename=/tmp/test --bs=1M --nrfiles=1 --sync=0 --randrepeat=0 --rw=write --refill_buffers --end_fsync=1 --iodepth=200 --ioengine=libaio
writefile: (g=0): rw=write, bs=(R) 1024KiB-1024KiB, (W) 1024KiB-1024KiB, (T) 1024KiB-1024KiB, ioengine=libaio, iodepth=200

fio-3.12
Starting 1 process
writefile: Laying out IO file (1 file / 10240MiB)
Jobs: 1 (f=1): [W(1)][100.0%][w=511MiB/s][w=511 IOPS][eta 00m:00s]
writefile: (groupid=0, jobs=1): err= 0: pid=3374: Sun Sep 8 17:13:43 2019
write: IOPS=485, BW=486MiB/s (509MB/s)(10.0GiB/21086msec); 0 zone resets
slat (usec): min=120, max=826765, avg=1909.76, stdev=36099.92
clat (usec): min=2, max=998823, avg=408482.22, stdev=385219.14
lat (usec): min=145, max=999119, avg=410392.19, stdev=385480.75
clat percentiles (msec):
| 1.00th=[ 68], 5.00th=[ 70], 10.00th=[ 72], 20.00th=[ 74],
| 30.00th=[ 74], 40.00th=[ 75], 50.00th=[ 178], 60.00th=[ 288],
| 70.00th=[ 877], 80.00th=[ 885], 90.00th=[ 894], 95.00th=[ 894],
| 99.00th=[ 986], 99.50th=[ 986], 99.90th=[ 995], 99.95th=[ 995],
| 99.99th=[ 1003]
bw ( KiB/s): min=129024, max=1048576, per=100.00%, avg=789316.23, stdev=312970.36, samples=26
iops : min= 126, max= 1024, avg=770.69, stdev=305.56, samples=26
lat (usec) : 4=0.01%, 500=0.01%, 750=0.01%, 1000=0.01%
lat (msec) : 2=0.03%, 4=0.06%, 10=0.04%, 100=46.41%, 250=11.66%
lat (msec) : 500=2.90%, 1000=38.87%
cpu : usr=7.30%, sys=8.29%, ctx=8516, majf=7, minf=11
IO depths : 1=0.1%, 2=0.1%, 4=0.1%, 8=0.1%, 16=0.2%, 32=0.3%, >=64=99.4%
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.1%
issued rwts: total=0,10240,0,1 short=0,0,0,0 dropped=0,0,0,0
latency : target=0, window=0, percentile=100.00%, depth=200

Run status group 0 (all jobs):
WRITE: bw=486MiB/s (509MB/s), 486MiB/s-486MiB/s (509MB/s-509MB/s), io=10.0GiB (10.7GB), run=21086-21086msec

zpool iostat: siehe Anlage "zpool iostat.txt"

Code:

 # df -h
Filesystem                            Size  Used Avail Use% Mounted on
udev                                   16G     0   16G   0% /dev
tmpfs                                 3.2G   25M  3.1G   1% /run
rpool/ROOT/pve-1                      546G  1.5G  544G   1% /
tmpfs                                  16G   52M   16G   1% /dev/shm
tmpfs                                 5.0M     0  5.0M   0% /run/lock
tmpfs                                  16G     0   16G   0% /sys/fs/cgroup
rpool                                 544G  128K  544G   1% /rpool
rpool/data                            544G  128K  544G   1% /rpool/data
rpool/ROOT                            544G  128K  544G   1% /rpool/ROOT
XXX@XXX.your-storagebox.de:/  2.0T  544G  1.5T  28% /mnt/pve/HetznerStorageBoxXXXXXX
/dev/fuse                              30M   16K   30M   1% /etc/pve
tmpfs                                 3.2G     0  3.2G   0% /run/user/0

ZFS RAID0 hatte ich bei der Proxmox Installation wie folgt eingerichtet:
ZFS Arc habe ich auf 2 GiB begrenzt gemäß https://pve.proxmox.com/wiki/ZFS_on_Linux#_limit_zfs_memory_usage
Ansonsten habe ich keinerlei spezielle ZFS Einstellungen vorgenommen.

nano /etc/modprobe.d/zfs.conf options zfs zfs_arc_max=2147483648 update-initramfs -u reboot

Die 2 GB werden auch gerne ausgenutzt. Hier ein Screenshot der letzten paar Stunden (ist leider einige Stunden nach dem Crash; zum Crash-Zeitpunkt hatte ich noch kein Monitoring)
zpool events -v liefert keine Hinweise oder Errors; nur Messages nach dem letzten Start des Systems
zpool list
NAME SIZE ALLOC FREE CKPOINT EXPANDSZ FRAG CAP DEDUP HEALTH ALTROOT
rpool 928G 355G 573G - - 0% 38% 1.00x ONLINE -
-> Zeigt dass Dedup nicht aktiv ist. Daher sollten 2GB ZFS ARC Cache doch eigentlich ausreichend sein?? Es sind maximal ein knappes TB an Daten zu verwalten.
Ausschnitt aus /var/log/syslog: Siehe Anhang "syslog-Ausschnitt.txt"
Mehr Statistiken (CPU Last usw.) habe ich vom Host zu diesem Zeitpunkt leider nicht.
Die VM zeigte eine sehr hohe CPU-Last ab etwa 00:23 Uhr, die dann um 00:38 Uhr noch anwuchs:
Disk Auslastung der VM (reads/writes) sieht gering aus:
Memory Auslastung der VM war ebenfalls sehr gering (habe noch einen Screenshot, aber der Post ist auf 10 Anhänge begrenzt).
Die CPU Last (habe nur den Graphen der VM dazu) ist dabei nur durch I/O verursacht:
VM: Bis auf einen CPU Kern waren alle voll ausgelastet mit I/O ????
Die Prozesse dagegen verbrauchen kaum CPU-Last:

(ftranspas ist ein Filetransfer Programm; ist allerdings nur am idlen, hat 0 Dateien zu übertragen, da der Server zu diesem Zeitpunkt nicht produktiv ist)
Netzwerklast dagegen ist minimal zu dem Zeitpunkt.

Ich weiß leider nicht, was die VM um 00:25 Uhr plötzlich zu so einer gigantischen I/O CPU-Last bewegte. Da hat sich wohl etwas rapide angestaut.

Vielleicht konnte ZFS nichts mehr auf Platte schreiben?

Bin mit meinem Latein echt am Ende, bitte um Hilfe.

pongraczi · Sep 8, 2019

Es ist genau das gleiche:
https://forum.proxmox.com/threads/proxmox-v6-servers-freeze-zvol-blocked-for-more-than-120s.57765/

Michael Kocum · Sep 11, 2019

Das Problem habe ich auch, aber nicht auf allen Maschinen.
Komischerweise ist alte Hardware davon nicht betroffen, neue Hardware schon.

Um die Zeit läuft ein Cron der ein "zpool scrub rpool" anstößt und danach friert die Maschine ein, ist aber noch pingbar.

Ich konnte das Verhalten manuell nachvollziehen indem ich nach ein paar Tagen Laufzeit ein "zpool scrub rpool" angestoßen habe.

Mein derzeitiger Workaround ist den cronjob abzuschalten.

Stoiko Ivanov · Sep 11, 2019

Den workaround in dem thread von @pongraczi ausprobiert?
set zfs_vdev_scheduler=none für das zfs kernel-modul und dann einen scrub anstoßen?

Michael Kocum · Sep 12, 2019

Ich habe den Workaround gestern eingebaut und 24 Std später einen scrub angestoßen und es hat funktioniert.

Werde nun 48 Std warten und dann nochmals einen scrub anstoßen.
Wenn das auch funktioniert, dann würde ich sagen dass der Workaround passt.

pongraczi · Sep 12, 2019

FYI:
https://github.com/zfsonlinux/zfs/issues/8664

logics · Sep 14, 2019

Seltsamerweise kann ich nun ohne Freeze scrubben, obwohl ich noch nicht den Workaround ausprobiert hatte.

https://forum.proxmox.com/threads/p...-blocked-for-more-than-120s.57765/post-267351

Habe nun (14.09.2019 15:40) allerdings den Workaround trotzdem implementiert, weil ich nicht will, dass der Host bei der nächsten Cronjob Ausführung vielleicht doch wieder hängt.

root@XirraDedi:~# cat /sys/module/zfs/parameters/zfs_vdev_scheduler
noop
root@XirraDedi:~# nano /etc/modprobe.d/zfs.conf
Meine Datei habe ich nun auf folgendes geändert:
options zfs zfs_arc_max=2147483648 zfs_prefetch_disable=1 zfs_vdev_scheduler=none
Save it
root@XirraDedi:~# update-initramfs -u -k `uname -r`
update-initramfs: Generating /boot/initrd.img-5.0.21-1-pve
Running hook script 'zz-pve-efiboot'..
Re-executing '/etc/kernel/postinst.d/zz-pve-efiboot' in new private mount namespace..
Copying and configuring kernels on /dev/disk/by-uuid/30D2-4626
Copying kernel and creating boot-entry for 5.0.15-1-pve
Copying kernel and creating boot-entry for 5.0.21-1-pve
Reboot
root@XirraDedi:~# cat /sys/module/zfs/parameters/zfs_vdev_scheduler
none

Der Scrub kann nach dem Workaround problemlos durchgeführt werden.

Code:

root@XirraDedi:~# zpool status
  pool: rpool
state: ONLINE
  scan: scrub in progress since Sat Sep 14 15:41:52 2019
        189G scanned at 1.11G/s, 120G issued at 720M/s, 320G total
        0B repaired, 37.34% done, 0 days 00:04:45 to go
config:

        NAME                                                   STATE     READ WRITE CKSUM
        rpool                                                  ONLINE       0     0     0
          ata-Samsung_SSD_860_EVO_500GB_S3Z2NB0M501745A-part3  ONLINE       0     0     0
          sdb                                                  ONLINE       0     0     0

errors: No known data errors

(2x Samsung 860 EVO SSD, in zfs RAID0)

Michael Kocum · Sep 14, 2019

Nach 48 Std ein neues scrub und es funktioniert noch immer.

Matthias Mayr · Nov 4, 2019

Hallo zusammen,

eine meiner Maschinen war auch von dem Problem betroffen. Da die Maschine der einzige Node ist und Produktiv eingesetzt wird, habe ich keine Experimente mit den Optionen gemacht, sondern einfach das Scrubbing deaktiviert. Läuft seither stabil, ist aber natürlich keine tolle Lösung.

Aktuell schiebe ich mehrere Upgrades deswegen auf, daher die Fragen:
Gibt es hierzu neue Erkenntnisse? Wird der ZFS Patch in PVE integriert?
Gibt es Feedback von anderen Kunden oder Anhaltspunkte wer alles davon betroffen ist (bestimmte Hardware, etc.)?

Vielen Dank und viele Grüße
Matthias Mayr

Search

Search

Crash: /proc/sys/kernel/hung_task_timeout_secs - Problem mit ZFS?

logics

Member

Attachments

pongraczi

Renowned Member

Michael Kocum

Active Member

Stoiko Ivanov

Proxmox Staff Member

Michael Kocum

Active Member

pongraczi

Renowned Member

logics

Member

Michael Kocum

Active Member

Matthias Mayr

Member