Univention Bugzilla – Bug 23258
Probleme mit kvm-clock
Last modified: 2011-09-14 10:56:12 CEST
linux-image-2.6.32-ucs44-amd64 2.6.32-35~ucs1.44.201107011448 qemu-kvm 0.14.0+dfsg-1~tls.7.201103170827 Der reboot eines UCS-Gasts bleibt beim starten von portmap hängen. Wird die Instanz heruntergefahren und gestartet gibt es keine Probleme, allerdings reproduzierbar bei einem Reboot. Auffällig ist dass beim reboot die immer Clocksource tsc deaktiviert wird ("Clocksource tsc unstable (delta = 137303562 ns)"). Setzt man per Kernel cmd eine Clocksource != kvm-clock (z.B. mit "clocksource=hpet") gibt es auch beim Reboot keine Probleme. Ein ähnliches Verhalten wurde hier beschrieben: <http://www.spinics.net/lists/kvm/msg59716.html> der dort angeforderte Trace liegt unter <http://download.univention.de/download/temp/kvm-clock/kvm-clock.tar.bz2> (Philipp schickt das auf die Liste).
Das trat jetzt öfters auf, sowohl bei uns alsauch auf der qemu/kvm-ML. Von der ML bisher keine Reaktion. Könnte eine Regression aus qemu-0.14.1 sein.
Falls Du das anhand der Logs noch auf einem System prüfen willst, das trat heute zweimal auf dimma auf.
Kurzes Update: Das Problem lässt sich 100% reproduzieren: VM starten und in den Grub-Boot-Optionen (UCR: grub/append) "nosplash verbose vga=ext" setzen. Anschließend von dort "reboot"en. In den darauffolgenden Bootmeldungen stimmen die Zeiten dann nicht mehr: In Realzeit vergeht viel mehr Zeit als vom Kernel angezeigt wird: In den Kernel-Meldungen steht zwar z.B. 10 Sekunden, in Real-Zeit sind es aber eher 42 s: [ 9.915707] ide_generic: please use "probe_mask=0x3f" module parameter for probing all legacy ISA IDE ports Wenn man es bis zu einer Kommandozeile schafft, dort ein "sleep 1" ausführen; das dauert deutlich länger. Ein "cat /proc/uptime" zeigt auch zu wenig Realzeit an. 1. Mit einem neueren Gast-Kernel (3.0.0) tritt das Problem immer noch auf. 2. Mit einem älteren (2.6.32-ucs37) bzw. neueren Wirt-Kernel (3.0.0) tritt das Problem nicht auf. 3. Mit Qemu-kvm-0.15.0{,-rc2,-rc1} tritt das Problem mehr auf.
(In reply to comment #3) > 3. Mit Qemu-kvm-0.15.0{,-rc2,-rc1} tritt das Problem nicht auf.
In 2.6.32.40 <http://www.kernel.org/pub/linux/kernel/v2.6/longterm/v2.6.32/ChangeLog-2.6.32.40> sind 2 Patches für KVM eingeflossen: <http://git.kernel.org/?p=linux/kernel/git/longterm/linux-2.6.32.y.git;a=commitdiff;h=f413fc28a1db54519b75f731a6e57d1ef0269d78> KVM: x86: Fix kvmclock bug <http://git.kernel.org/?p=linux/kernel/git/longterm/linux-2.6.32.y.git;a=commitdiff;h=ad2088cabe0fd7f633f38ba106025d33ed9a2105> KVM: x86: Fix a possible backwards warp of kvmclock Reverted man beide (der 1. korrigiert einen Fehler im 2.), so tritt das Problem nicht mehr auf. Next-Step: diff linux-{2.6.32.40,3.0.0}/arch/x86/kvm/x86.c PS: Zum Lesen empfolen: <http://www.mail-archive.com/kvm@vger.kernel.org/msg42118.html> zum Thema "Sinnvolle Commit-Kommentare"
Nach dem Reboot DER VM macht vcpu->last_guest_tsc einen großen Rückwärtssprung, so daß dann max_kernel_ns einen großen Vorwärtssprung macht: [9333.197080] vcpu->last_guest_tsc =209_328_760_015 ← vcpu->hv_clock.tsc_timestamp=209_328_708_109 vcpu->last_kernel_ns =9_333_179_830_643 kernel_ns =9_333_197_073_429 max_kernel_ns =9_333_179_847_943 ← [9336.910995] vcpu->last_guest_tsc =9_438_510_584 ← vcpu->hv_clock.tsc_timestamp=211_080_593_143 vcpu->last_kernel_ns =9_333_763_732_907 kernel_ns =9_336_910_990_771 max_kernel_nsn =6_148_296_831_006_663_830 ← Für eine 3 GHz-CPU wunde folgendes berechnet: vcpu->hv_clock.tsc_shift =-1 vcpu->hv_clock.tsc_to_system_mul =2_863_019_502 Vermutung: 1. Beim Reset wird der guest_tsc auf 0 zurückgesetzt. 2. Dann benötigt das SeaBIOS 3 Sekunden zum Booten von Linux. 3. Linux schaltet dann auf PV-Clock um und startet dort mit einem guest_tsc=(3s*6GHz)~=3e9. Das könnte erklären, warum sowohl ein Host-Kernel-Update alsauch ein KVM-Update das Problem lösen: Ersteres korrigiert vermutlich den an den Gast exportierten TSC, letzteres korrigiert die Reset-Logik beim Reboot. Fehlerursache: 1. Beim Reset setzt das BIOS das Gast.TSC=0 zurück. 2. Im Wirk-Kernel wird vergessen, vcpu->arch.hv_clock.tsc_timestamp=0 zurückzusetzen, weshalb dann beim nächsten Aufruf von kvm_write_guest_time() das TSC rückwärts geht und last_kernel_ns überkompensiert wird.
Created attachment 3498 [details] Reset vcpu->hv_clock.tsc_timestamp on TSC write
Bei einem testweise gebauten Kernel war das Problem mit Einspielen des Patches behoben. Dieser enthält neben dem angehängten Patch auch noch einige andere Backports vom aktuellen Kernel, die Eng mit der KVM-Clock-Implementierung zusammen hängen und durchaus auch noch relevant sein können. svn9661, svn9662, linux-2.6.32_2.6.32-35~ucs1.48.201109051614 ChangeLog (svn9827) (da defekter Kernel auch Bestandteil von sec4 ist): \item Im Kernel wurde ein Fehler korrigiert, der bei Verwendung der Virtualisierungstechnologie KVM dazu geführt hat, das nach dem Neustart einer virtuellen UCS-Instanz diese sehr langsam war (\ucsBug{23258}).
svn26616, svn26617 univention-kernel-image-2.6.32_1.0.15-5.41.201109060855 univention-kernel-modules-2.6.32_1.0.1-3.30.201109060900
OK, reboot funktioniert mit KVM (i386 und amd64). Changelog Eintrag vorhanden.
Patch considered for 2.6.32.x: <http://marc.info/?l=kvm&m=131583003223870>
UCS 2.4-3 wurde veröffentlicht. Sollte der hier beschriebene Bug mit einer neueren Version von UCS erneut auftreten, so sollte der Bug dupliziert werden: "Clone This Bug".