zfs list timeout

[uibmz]

Bei uns fallen diverse Operationen, die sich des zfs-Systems bedienen auf die Nase, da das `zfs list -o name,volsize,origin,type,refquota -t volume,filesystem -Hrp` in einen Timeout läuft.
Wenn man den Befehl allerdings per Watch -n 10 regelmäßig ausführen lässt, so kommt es nicht mehr zu solchen Problemen.
Wir haben dieses Verhalten auf zwei Nodes mit unterschiedlichen Auslastungen. Auf dem einen haben wir 200 Volumes, auf dem anderen lediglich 70.

Es handelt sich bei beiden Nodes um je zwei Pools mit striped-mirrored vdevs

root@prodnode1:~# zpool status -v
  pool: pool_spinning
 state: ONLINE
  scan: scrub repaired 0B in 0 days 01:24:06 with 0 errors on Sun Aug  9 01:48:07 2020
config:

        NAME           STATE     READ WRITE CKSUM
        pool_spinning  ONLINE       0     0     0
          mirror-0     ONLINE       0     0     0
            sdm        ONLINE       0     0     0
            sdn        ONLINE       0     0     0
          mirror-1     ONLINE       0     0     0
            sdo        ONLINE       0     0     0
            sdp        ONLINE       0     0     0
          mirror-2     ONLINE       0     0     0
            sdq        ONLINE       0     0     0
            sdr        ONLINE       0     0     0
          mirror-3     ONLINE       0     0     0
            sds        ONLINE       0     0     0
            sdt        ONLINE       0     0     0

errors: No known data errors

  pool: pool_ssd
 state: ONLINE
  scan: scrub repaired 0B in 0 days 00:33:32 with 0 errors on Sun Aug  9 00:57:35 2020
config:

        NAME        STATE     READ WRITE CKSUM
        pool_ssd    ONLINE       0     0     0
          mirror-0  ONLINE       0     0     0
            sda     ONLINE       0     0     0
            sdb     ONLINE       0     0     0
          mirror-1  ONLINE       0     0     0
            sdc     ONLINE       0     0     0
            sdd     ONLINE       0     0     0
          mirror-2  ONLINE       0     0     0
            sde     ONLINE       0     0     0
            sdf     ONLINE       0     0     0
          mirror-3  ONLINE       0     0     0
            sdg     ONLINE       0     0     0
            sdh     ONLINE       0     0     0
          mirror-4  ONLINE       0     0     0
            sdi     ONLINE       0     0     0
            sdj     ONLINE       0     0     0
          mirror-5  ONLINE       0     0     0
            sdk     ONLINE       0     0     0
            sdl     ONLINE       0     0     0

 

[Alwin]

Bei uns fallen diverse Operationen, die sich des zfs-Systems bedienen auf die Nase, da das `zfs list -o name,volsize,origin,type,refquota -t volume,filesystem -Hrp` in einen Timeout läuft.

Was für eine Meldung kommt den? Und ist in den VMs auch ein ZFS?

 

[uibmz]

Als Fehlermeldung in der GUI kommt etwas wie bereits in diesem Thread gepostet: https://forum.proxmox.com/threads/zfs-connection-error-timeout.65458/
Also sprich "got timeout 500".

Das Problem ist hier, dass die WebGUI die Anfrage nicht beliebig lange laufen lassen kann, da damit Threads/Prozesse/Sessions/? blockiert werden, der Timeout liegt halt nunmal bei 5sec.

Auf der Konsole gibt ein time zfs.... eine Laufzeit von 0,2 sec aus, wenn es denn regelmäßig wie oben beschrieben ausgeführt wird.
Wenn das zfs list mal für einige Zeit nicht ausgeführt wurde und "initial" neu ausgeführt wird, so dauert es länger als 5 Sekunden.


Nein in den VMs läuft ein ganz normales ext4.

 

[Alwin]

Auf der Konsole gibt ein time zfs.... eine Laufzeit von 0,2 sec aus, wenn es denn regelmäßig wie oben beschrieben ausgeführt wird.
Wenn das zfs list mal für einige Zeit nicht ausgeführt wurde und "initial" neu ausgeführt wird, so dauert es länger als 5 Sekunden.

Ist da System vielleicht im idle? Dann könnte es bei Spinnern zu Anfang etwas länger dauern.

 

[uibmz]

Auf beiden Pools finden sich volumes die auch aktiv in Benutzung sind, ich gehe daher nicht davon aus, dass die Disks runterdrehen.
Das APM ist bei den Spinning auf 254, also

hdparm -I /dev/sdo | grep level
        Advanced power management level: 254

 

[Alwin]

Sind ansonsten genug Ressourcen auf der Node frei?

 

[uibmz]

RAM is zu 60% belegt und die load liegt bei etwa 8 bei 40 Kernen...iowait ist 1% im Schnitt

 

[Alwin]

Gute Frage, warum es beim ersten mal länger dauert. Am besten mal mit strace nach verfolgen.

 

[uibmz]

Ich hab mal einen "schnellen" Lauf mit strace analysiert. Einen langsamen reiche ich nach sobald ich einen hab ;-)

 

[uibmz]

Und jetzt habe ich einmal schnell und einmal langsam zusammen mit timestamps ;-)

 

[Alwin]

Und was zu sehen?

 

[uibmz]

Die Strace sind praktisch identisch, lediglich die Dauer der einzelnen Aufrufe unterscheidet sich.
So sind im Langsamen Fall folgende Aufrufe etwa Faktor 10 langsamer:

14:39:29.414191 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = -1 ENOMEM (Cannot allocate memory) <0.000177>
14:39:29.414426 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.000135>
14:39:29.414646 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.420885>
14:39:29.835694 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <1.562472>
14:39:31.398410 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = -1 ENOMEM (Cannot allocate memory) <1.006513>
14:39:32.405076 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.000805>
14:39:32.406046 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.599721>
14:39:33.005940 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.105662>
14:39:33.111820 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.328114>
14:39:33.440133 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.091866>
14:39:33.532203 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.149452>
14:39:33.681868 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.073880>
14:39:33.755946 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.109587>
14:39:33.865758 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = 0 <0.172167>
14:39:34.038146 ioctl(3, _IOC(_IOC_NONE, 0x5a, 0x14, 0), 0x7ffe3f2b5e30) = -1 ENOMEM (Cannot allocate memory) <0.142600>

Diese Zeilen finden sich im Übrigen auch im schnellen Fall, nur dass die Zeiten eben kürzer sind.
Die Node ist RAM-technisch nicht ausgelastet, die üblichen 50% für zfs sind unverändert...

 

[Alwin]

Schätze mal, ZFS lädt beim ersten mal alles in den Cache und dann passt's beim zweiten Aufruf. Das wird sich wohl leider nicht umgehen lassen.

 

[uibmz]

Erstmal vielen Dank für die vielen hilfreichen Antworten und Hinweise.

Ich frag mich nur wieso es "nur" vereinzelt dazu kommt, also nicht nur bei uns, wenn man nach proxmox zfs timeout googlet findet man schon so ein paar Fälle...
Ich hätte noch den SWAP der verschiedenen VMs als Ansatzpunkt, da sich dieser bei uns ( entgegen der Doku ) noch auf der Systemplatte der VM befindet...Mit RAM sind die VMs allerdings ausreichend ausgerüstet, sodass es eigentlich kaum zu swap kommen sollte...

 

[Alwin]

Das sollte dabei nichts ausmachen, da ZFS die Properties erstmal vom zpool liest. Was ich spannend finde ist das ENOMEM wenn es mehrere Datasets auf einem Pool gibt. Ob es da einen Zusammenhang gibt kann ich aber leider nicht sagen.

Ich frag mich nur wieso es "nur" vereinzelt dazu kommt, also nicht nur bei uns, wenn man nach proxmox zfs timeout googlet findet man schon so ein paar Fälle...

Natürlich kann das immer mal vorkommen und hat sicherlich so viele Ursachen wie Einträge.

 

[uibmz]

Das sollte dabei nichts ausmachen, da ZFS die Properties erstmal vom zpool liest. Was ich spannend finde ist das ENOMEM wenn es mehrere Datasets auf einem Pool gibt. Ob es da einen Zusammenhang gibt kann ich aber leider nicht sagen.

Ich grabe hier gerne noch tiefer, die Frage ist nur in welche Richtung...
Die Nodes bekommen in Kürze auch noch ein slog Device und mehr RAM....

 

[Alwin]

Ich grabe hier gerne noch tiefer, die Frage ist nur in welche Richtung...

Da ich dazu nicht wirklich was finde, könnte das ENOMEM auch vom strace kommen, der evtl. die Datenstruktur nicht auslesen kann.

Die Nodes bekommen in Kürze auch noch ein slog Device und mehr RAM....

Vermutlich wird sich damit die Problematik nur ein wenig verschieben. Zum ZIL, die Performance sollte vorher und nachher getestet werden, da bei einem 4x/6x Mirror das ZIL zum Flaschenhals werden kann.