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

Sep 8, 2019
10
0
1
29
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.
ausgabe.PNG

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:
    install.png
  • 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)
    zfs_arc.png
  • 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:
    vm_cpu.PNG
  • Disk Auslastung der VM (reads/writes) sieht gering aus:
    vm_disk.PNG
  • 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_cpu_detail.PNG
  • VM: Bis auf einen CPU Kern waren alle voll ausgelastet mit I/O ????
    vm_cpu_detail_cores.PNG
  • Die Prozesse dagegen verbrauchen kaum CPU-Last:
    vm_cpu_detail_procs.PNG
    (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.
 

Attachments

Michael Kocum

New Member
Oct 3, 2018
3
1
3
58
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

Proxmox Staff Member
Staff member
May 2, 2018
2,030
205
63
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

New Member
Oct 3, 2018
3
1
3
58
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.
 
Sep 8, 2019
10
0
1
29
Seltsamerweise kann ich nun ohne Freeze scrubben, obwohl ich noch nicht den Workaround ausprobiert hatte.

https://forum.proxmox.com/threads/proxmox-v6-servers-freeze-zvol-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)
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE and Proxmox Mail Gateway. We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get your own in 60 seconds.

Buy now!