KVM wird ca. 1x in der Woche beendet

[B4c4rd1]

Hallo Leute,

ich hatte früher schon das Problem in Verbindung mit ZFS und habe es nach einen erneuten Anlauf wieder.

Komischerweise dritt das Problem auch nur bei ZFS als Dateisystem auf. Installiert habe ich es mit dem Proxmox image.

Derzeit läuft folgende Version:

proxmox-ve: 4.4-92 (running kernel: 4.4.67-1-pve)
pve-manager: 4.4-15 (running version: 4.4-15/7599e35a)
pve-kernel-4.4.35-1-pve: 4.4.35-77
pve-kernel-4.4.67-1-pve: 4.4.67-92
pve-kernel-4.4.62-1-pve: 4.4.62-88
lvm2: 2.02.116-pve3
corosync-pve: 2.4.2-2~pve4+1
libqb0: 1.0.1-1
pve-cluster: 4.0-52
qemu-server: 4.0-110
pve-firmware: 1.1-11
libpve-common-perl: 4.0-95
libpve-access-control: 4.0-23
libpve-storage-perl: 4.0-76
pve-libspice-server1: 0.12.8-2
vncterm: 1.3-2
pve-docs: 4.4-4
pve-qemu-kvm: 2.7.1-4
pve-container: 1.0-101
pve-firewall: 2.0-33
pve-ha-manager: 1.0-41
ksm-control-daemon: 1.2-1
glusterfs-client: 3.5.2-2+deb8u3
lxc-pve: 2.0.7-4
lxcfs: 2.0.6-pve1
criu: 1.6.0-1
novnc-pve: 0.5-9
smartmontools: 6.5+svn4324-1~pve80
zfsutils: 0.6.5.9-pve15~bpo80

Nach ca. einer Woche wird meine KVM Maschine einfach gekillt und neugestartet.

Syslog Proxmox Host:

Sep 12 04:05:46 XXXX systemd-timesyncd[1816]: interval/delta/delay/jitter/drift 2048s/+0.000s/0.000s/0.000s/+44ppm
Sep 12 04:07:46 XXXX kernel: [1845484.579050] INFO: task txg_sync:1417 blocked for more than 120 seconds.
Sep 12 04:07:46 XXXX kernel: [1845484.579313]       Tainted: P           O    4.4.67-1-pve #1
Sep 12 04:07:46 XXXX kernel: [1845484.579560] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Sep 12 04:07:46 XXXX kernel: [1845484.579822] txg_sync        D ffff881fd6ac7ad8     0  1417      2 0x00000000
Sep 12 04:07:46 XXXX kernel: [1845484.579825]  ffff881fd6ac7ad8 ffff881fd6ac7ad0 ffff881ff2180e00 ffff881fd9e2e200
Sep 12 04:07:46 XXXX kernel: [1845484.579827]  ffff881fd6ac8000 ffff881fff497300 7fffffffffffffff ffff880853a47d00
Sep 12 04:07:46 XXXX kernel: [1845484.579828]  0000000000000001 ffff881fd6ac7af0 ffffffff818605d5 0000000000000000
Sep 12 04:07:46 XXXX kernel: [1845484.579829] Call Trace:
Sep 12 04:07:46 XXXX kernel: [1845484.579835]  [<ffffffff818605d5>] schedule+0x35/0x80
Sep 12 04:07:46 XXXX kernel: [1845484.579837]  [<ffffffff81863825>] schedule_timeout+0x235/0x2d0
Sep 12 04:07:46 XXXX kernel: [1845484.579882]  [<ffffffffc031d822>] ? zio_taskq_dispatch+0x92/0xa0 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.579905]  [<ffffffffc031d842>] ? zio_issue_async+0x12/0x20 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.579927]  [<ffffffffc0321309>] ? zio_nowait+0x79/0xf0 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.579929]  [<ffffffff8185facb>] io_schedule_timeout+0xbb/0x140
Sep 12 04:07:46 XXXX kernel: [1845484.579934]  [<ffffffffc01c0cb3>] cv_wait_common+0xb3/0x130 [spl]
Sep 12 04:07:46 XXXX kernel: [1845484.579938]  [<ffffffff810c46e0>] ? wait_woken+0x90/0x90
Sep 12 04:07:46 XXXX kernel: [1845484.579941]  [<ffffffffc01c0d88>] __cv_wait_io+0x18/0x20 [spl]
Sep 12 04:07:46 XXXX kernel: [1845484.579964]  [<ffffffffc032111c>] zio_wait+0xbc/0x140 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.579982]  [<ffffffffc02ad1c8>] dsl_pool_sync+0xb8/0x450 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.580002]  [<ffffffffc02c56e9>] spa_sync+0x369/0xb20 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.580004]  [<ffffffff810acf32>] ? default_wake_function+0x12/0x20
Sep 12 04:07:46 XXXX kernel: [1845484.580025]  [<ffffffffc02d8404>] txg_sync_thread+0x3c4/0x610 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.580027]  [<ffffffff810acad9>] ? try_to_wake_up+0x49/0x400
Sep 12 04:07:46 XXXX kernel: [1845484.580047]  [<ffffffffc02d8040>] ? txg_sync_stop+0xe0/0xe0 [zfs]
Sep 12 04:07:46 XXXX kernel: [1845484.580050]  [<ffffffffc01bbe9a>] thread_generic_wrapper+0x7a/0x90 [spl]
Sep 12 04:07:46 XXXX kernel: [1845484.580053]  [<ffffffffc01bbe20>] ? __thread_exit+0x20/0x20 [spl]
Sep 12 04:07:46 XXXX kernel: [1845484.580055]  [<ffffffff810a134a>] kthread+0xfa/0x110
Sep 12 04:07:46 XXXX kernel: [1845484.580056]  [<ffffffff810a1250>] ? kthread_park+0x60/0x60
Sep 12 04:07:46 XXXX kernel: [1845484.580058]  [<ffffffff81864a8f>] ret_from_fork+0x3f/0x70
Sep 12 04:07:46 XXXX kernel: [1845484.580059]  [<ffffffff810a1250>] ? kthread_park+0x60/0x60
Sep 12 04:08:16 XXXX pve-firewall[2468]: firewall update time (129.003 seconds)
Sep 12 04:08:16 XXXX pvestatd[2467]: status update time (129.529 seconds)
Sep 12 04:08:16 XXXX pmxcfs[2414]: [status] notice: RRDC update error /var/lib/rrdcached/db/pve2-storage/XXXX/local-zfs: -1
Sep 12 04:08:16 XXXX pmxcfs[2414]: [status] notice: RRDC update error /var/lib/rrdcached/db/pve2-storage/XXXX/local: -1
Sep 12 04:08:21 XXXX pve-ha-lrm[2492]: loop take too long (142 seconds)
Sep 12 04:08:24 XXXX kernel: [1845522.609659] kvm_get_msr_common: 2 callbacks suppressed
Sep 12 04:08:24 XXXX kernel: [1845522.609661] kvm [2873]: vcpu0 unhandled rdmsr: 0x1c9
Sep 12 04:08:24 XXXX kernel: [1845522.609932] kvm [2873]: vcpu0 unhandled rdmsr: 0x1a6
Sep 12 04:08:24 XXXX kernel: [1845522.610188] kvm [2873]: vcpu0 unhandled rdmsr: 0x1a7
Sep 12 04:08:24 XXXX kernel: [1845522.610443] kvm [2873]: vcpu0 unhandled rdmsr: 0x3f6
Sep 12 04:08:25 XXXX kernel: [1845523.432826] kvm [2873]: vcpu0 unhandled rdmsr: 0x34
Sep 12 04:08:25 XXXX kernel: [1845523.433119] kvm [2873]: vcpu0 unhandled rdmsr: 0x606
Sep 12 04:08:36 XXXX rrdcached[2310]: queue_thread_main: rrd_update_r (/var/lib/rrdcached/db/pve2-storage/XXXX/local) failed with status -1. (/var/lib/rrdcached/db/pve2-storage/XXXX/local: illegal attempt to update using time 1505181826 when last update time is 1505182096 (minimum one second step))
Sep 12 04:08:36 XXXX rrdcached[2310]: queue_thread_main: rrd_update_r (/var/lib/rrdcached/db/pve2-storage/XXXX/local-zfs) failed with status -1. (/var/lib/rrdcached/db/pve2-storage/XXXX/local-zfs: illegal attempt to update using time 1505181826 when last update time is 1505182096 (minimum one second step))
Sep 12 04:08:40 XXXX kernel: [1845539.103656] kvm [2873]: vcpu0 unhandled rdmsr: 0x611
Sep 12 04:08:40 XXXX kernel: [1845539.103948] kvm [2873]: vcpu0 unhandled rdmsr: 0x639
Sep 12 04:08:40 XXXX kernel: [1845539.104220] kvm [2873]: vcpu0 unhandled rdmsr: 0x641
Sep 12 04:08:40 XXXX kernel: [1845539.104496] kvm [2873]: vcpu0 unhandled rdmsr: 0x619
Sep 12 04:08:42 XXXX kernel: [1845541.373856] kvm [2873]: vcpu0 unhandled rdmsr: 0x611
Sep 12 04:08:42 XXXX kernel: [1845541.374152] kvm [2873]: vcpu0 unhandled rdmsr: 0x639
Sep 12 04:08:42 XXXX kernel: [1845541.374473] kvm [2873]: vcpu0 unhandled rdmsr: 0x641
Sep 12 04:08:42 XXXX kernel: [1845541.374757] kvm [2873]: vcpu0 unhandled rdmsr: 0x619

Syslog KVM gast System:
- Keine Einträge dazu, die einen Neustart rechtfertigen -

Angepasste Konfig (/etc/modprobe.d/zfs.conf):

# Immer 1/4 der gesamtmenge an Speicher

# ZFS tuning for a proxmox machine that reserves 32GB for ZFS
#
# Don't let ZFS use less than 4GB and more than 32GB
options zfs zfs_arc_min=4294967296
options zfs zfs_arc_max=34359738368
#
# disabling prefetch is no longer required
options zfs l2arc_noprefetch=0

Weiß einer von euch wieso das passieren kann?

Vielen Dank für eure Hilfe

 

[Alwin]

Wie ist dein Storage aufgebaut? Könnte an einem langsamen ZFS storage liegen.

 

[B4c4rd1]

Eigentlich sehr simple, zwei HDDs im mirror verfahren. Ohne LOG oder Write-cache platte:

        NAME                                                  STATE     READ WRITE CKSUM
        rpool                                                 ONLINE       0     0     0
          mirror-0                                            ONLINE       0     0     0
            ata-WDC_WD2000FYYZ-01UL1B2_WD-WMC1P0HAPNV1-part2  ONLINE       0     0     0
            ata-WDC_WD2000FYYZ-01UL1B2_WD-WMC1P0H8ZSZE-part2  ONLINE       0     0     0

Die KVM Maschine nutzt auch nur den Ram abzüglich der 32GB die für ZFS reserviert wurden.

Lustigerweise zeigt Proxmox auch nicht an, dass die KVM gecrasht ist. Aber ich sehe es in der KVM.

In Proxmox steht: XXXXX (Uptime: 21 days 20:58:22)
In der KVM: up 10 hours, 25 minutes

 

[Alwin]

Proxmox zeigt die Uptime des KVM Prozesses selbst, diese muss nicht mit der Uptime des OS in der VM übereinstimmen (zB. reboot). Der KVM Prozess läuft also weiter, während das OS in der VM einen Reset vornimmt. Das würde jetzt meine Aussage von vorhin bestätigen. Wie ist die IO Last, wenn die VM einen Reset macht (iostat / zfs iostat, ...)? Auch könnte (vermute Swap auf ZFS) der PVE host zu diesem Zeitpunkt auch zu swappen beginnen.

 

[B4c4rd1]

Wie kann ich das messen ohne zufällig dabei zu sein?

Aber laut Proxmox schaut das alles im Grünen Bereich aus. In der Zeit gab es zwar einen kleinen Ausschlag aber an sich schaut das doch gut aus:



Edit:
Ach, die Maxwerte zählen ja hier sorry:



Die sehen schon anders aus. Wie kann ich denn verhindern, dass es dann zu einem Crash kommt?

 

[Alwin]

Noch muss ja erst heraus gefunden werden, ob es tatsächlich das Storage ist. Eine Möglichkeit ist sicherlich die diversen Linux tool in ein Script packen und per cronjob ausführen lassen. Die Uhrzeit der Spitze könnte gut zu einem Backup passen.

Sollte es am Swap (auf ZFS) liegen, dann könnte folgendes helfen.
https://pve.proxmox.com/wiki/ZFS_on_Linux#_limit_zfs_memory_usage

 

[B4c4rd1]

Also Backups kann ich um die Zeit ausschließen. Die werden ab 1 Uhr durchgeführt. Proxmox macht an sich keine Backups.

Ich habe mal die Option vm.swappines auf 0 gestellt.

Ich melde mich hier nochmal, falls das Problem nochmal auftreten sollte. Danke!

 

[B4c4rd1]

Heute ist das Problem wieder aufgetreten.

Wir haben in der Zeit raus gefunden, dass in der Nach um 04:00 Uhr ein Kunde ein DropBox Backup macht, dass anscheinend den Neustart durchführt. In der VM haben wir in der Sysctl folgendes eingetragen:

# Reboot 1 second after kernel panic, oops or BUG
kernel.panic = 1
kernel.panic_on_oops = 1

Daher kommen die Neustarts.

In der Zeit geht die IO Time nach oben. Ich kann aber nicht nachvollziehen wieso es zum kernal panic kommt.

Dieses mal hatten wir in der Proxmox syslog nichts stehen.

 

[Alwin]

Sep 12 04:07:46 XXXX kernel: [1845484.579050] INFO: task txg_sync:1417 blocked for more than 120 seconds.

Der PVE Server steht vermutlich unter Memory pressure (overcommitment) oder ein langsames Storage und das wirkt sich so auf die VM aus.

 

[B4c4rd1]

Vielen Dank für dein Antwort!

Das mit dem Speicher habe ich mir auch schon gedacht. Wir haben der VM 8GB zum Test entzogen. Das Backup in die DropBox wurde aus der VM gestartet.

Der Server hat 128GB Ram.
Wobei 32GB für ZFS abgezogen wurde.
Der VM haben wir jetzt 85GB zugeordnet.