IT-Tagebuch: Linux – Was sind “CPU-Lockups”?

Avatar

View this post in English

Kurze Antwort

A 'softlockup' is defined as a bug that causes the kernel to loop in kernel mode for more than 20 seconds [...], without giving other tasks a chance to run.

A 'hardlockup' is defined as a bug that causes the CPU to loop in kernel mode for more than 10 seconds [...], without letting other interrupts have a chance to run.

Sprich, ein Kernel-Task gibt bei einem Softlockup wie in den guten alten DOS-Zeiten eine CPU nicht mehr frei. "Irgendwas" "hängt" also. Bei einem Hardlockup werden noch nicht einmal mehr Interrupts behandelt, was dann wesentlich deutlicher auf einen Bug hindeutet: Irgendwas hat Interrupts maskiert und nicht mehr freigegeben.

Ist das schlimm? Ist das System abgestürzt?

Allgemein

Wir können konfigurieren, ob ein Panic getriggert wird, wenn irgendein Lockup erkannt wird:

$ sysctl kernel.softlockup_panic kernel.hardlockup_panic
kernel.softlockup_panic = 0
kernel.hardlockup_panic = 0

Standardmäßig scheint das aber bei Ubuntu deaktiviert zu sein. Das System läuft also erst einmal weiter und kann sich theoretisch auch wieder fangen.

Bei XenServer sieht es anders aus:

$ cat /proc/sys/kernel/softlockup_panic
1

Einen Hardlockup-Watchdog gibt es hier nicht. So erklärt sich dann, dass ein XenServer-Host stehenbleibt, sobald es einen Softlockup gegeben hat:

[41819967.871466]  EMERG: BUG: soft lockup - CPU#3 stuck for 23s! [tapdisk:23395]
[41819967.872648]  EMERG: Kernel panic - not syncing: softlockup: hung tasks

Softlockups

Bei einem Softlockup weiß man nur, dass da irgend ein Kernel-Task läuft, der einen Kern nicht mehr freigibt. Möglicherweise geht’s weiter. Vielleicht auch nicht.

Ein typisches Szenario ist angeblich dieses:

  • Task 1 lockt eine Ressource mittels eines Spinlock.
  • Task 2 will den Spinlock auch haben.
  • Task 1 gibt ihn ziemlich lange nicht frei.

Da es eben ein Spinlock ist, wartet Task 2 "aktiv", guckt also immer wieder nach, ob er jetzt darf. Das kann dann dazu führen, dass hier ein Softlockup gemeldet wird. Erkennen können wir das wohl daran, dass der RIP in der Debug-Meldung auf der Konsole auf irgendeine Funktion mit acquire_spinlock im Namen zeigt.

Hardlockups

Dazu habe ich bis jetzt keine Informationen gefunden. Wenn keine Interrupts mehr bearbeitet werden, ist das aber vermutlich ein ziemlich schlechtes Zeichen.

Ursachen

Lockups können nie von Prozessen im Userspace ausgelöst werden, da diese immer zuverlässig gescheduled und zur Seite geschoben werden können. Wenn so ein Lockup auftritt, dann gab es ein Problem im Kernel.

Die einfachste Ursache bilden natürlich schlichtweg Bugs. Das ignorieren wir jetzt mal, weil es langweilig ist und wir wenig Einfluss darauf haben.

Vermutlich kann man hiervon ausgehen: Kernel-Code hat erwartet, dass eine Aktion schnell vorüber ist; diese Annahme hat sich dann aber als falsch herausgestellt. Der Kernel braucht also länger als er dachte.

Wie bei Redhat beschrieben, kann schlichtweg eine sehr hohe Systemlast verantwortlich sein. An dieser Stelle muss man aber unterscheiden: Hat man es mit einem "echten" System zu tun oder ist es virtualisiert? Bei uns ist so gut wie alles virtualisiert. VMware spricht hier von high levels of overcommitment als möglicher Ursache, wobei mir in diesem Zusammenhang nicht ganz klar ist, auf wen sich das bezieht – vermutlich auf den Host.

Es liegt in der Natur der Sache, dass man hier keine allgemeingültige Aussage treffen kann. Die Watchdogs stellen lediglich fest, dass bestimmte CPUs nur noch einen Task ausführen und dieser die CPU nicht mehr freigibt. Das war’s. Warum das so ist, kann man dann mit Glück aus den Stack-Traces rausklamüsern, die für die hängende CPU angezeigt werden.

Welche Daten können im Falle eines Lockups gesammelt werden?

Wenn ein Lockup auftritt, gibt es mehrere Handlungsoptionen, die bei der Analyse helfen:

  • Wenn noch ein Login per SSH möglich ist: Screenshots von htop, dmesg und Syslog/Journal sammeln.
  • Wenn nur die Konsole mit den Lockup-Meldungen zu sehen ist: davon Screenshots machen.
    • Interessant sind die Angabe des Prozesses, die Zeile mit RIP und der Stack-Trace.
    • Abwarten, ob sich die Ausgabe verändert.
    • Es muss nicht unbedingt den einen Lockup geben, sondern es kann mehrere CPUs betreffen. Hier bleibt dann, darauf zu hoffen, dass irgendwann nochmal die CPU gemeldet wird, die das Problem ursprünglich verursacht hat.
    • Wenn dort zum Beispiel etwas mit Java steht, ist die Chance hoch, dass es nur ein Folgefehler ist.

Ein bisschen umgucken: Watchdogs

Man beachte hier die CPU-Affinität:

$ for pid in 12 15 21 27 33 39 45 51; do taskset -a -p $pid; done
pid 12's current affinity mask: 1       # Die Angaben sind hexadezimal.
pid 15's current affinity mask: 2
pid 21's current affinity mask: 4
pid 27's current affinity mask: 8
pid 33's current affinity mask: 10
pid 39's current affinity mask: 20
pid 45's current affinity mask: 40
pid 51's current affinity mask: 80

Lockups mit eigenem Kernel-Modul provozieren

Softlockups

# apt install build-essential linux-headers-generic

hog.c:

#include <linux/init.h>
#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/kthread.h>
 
MODULE_LICENSE("GPL");
 
static int
hog_thread(void *data)
{
    printk(KERN_INFO "Hogging a CPU now\n");
    while (1);
 
    /* unreached */
    return 0;
}
 
static int __init
hog_init(void)
{
    kthread_run(hog_thread, NULL, "hog");
    return 0;
}
 
module_init(hog_init);

Makefile:

obj-m += hog.o
 
all:
    make -C /lib/modules/$(shell uname -r)/build/ M=$(PWD) modules
clean:
    make -C /lib/modules/$(shell uname -r)/build/ M=$(PWD) clean

root@ubuntu1604lts:~/thread# make
make -C /lib/modules/4.4.0-83-generic/build/ M=/root/thread modules
make[1]: Entering directory '/usr/src/linux-headers-4.4.0-83-generic'
  CC [M]  /root/thread/hog.o
  Building modules, stage 2.
  MODPOST 1 modules
  LD [M]  /root/thread/hog.ko
make[1]: Leaving directory '/usr/src/linux-headers-4.4.0-83-generic'
 
root@ubuntu1604lts:~/thread# insmod hog.ko

Und warten. Nach etwa 20 Sekunden kommt auf der ersten Konsole die Meldung und im dmesg der Stack-Trace:

[  355.900698] NMI watchdog: BUG: soft lockup - CPU#0 stuck for 22s! [hog:6885]
[  355.900735] Modules linked in: hog(OE) ppdev joydev input_leds parport_pc serio_raw parport i2c_piix4 8250_fintek mac_hid ib_iser rdma_cm iw_cm ib_cm ib_sa ib_mad ib_core ib_addr iscsi_tcp libiscsi_tcp libiscsi scsi_transport_iscsi autofs4 btrfs raid10 raid456 async_raid6_recov async_memcpy async_pq async_xor async_tx xor raid6_pq libcrc32c raid1 raid0 multipath linear hid_generic usbhid hid crct10dif_pclmul crc32_pclmul ghash_clmulni_intel aesni_intel aes_x86_64 lrw gf128mul glue_helper ablk_helper cryptd floppy pata_acpi psmouse
[  355.900761] CPU: 0 PID: 6885 Comm: hog Tainted: G           OEL  4.4.0-83-generic #106-Ubuntu
[  355.900762] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.10.2-20170228_101828-anatol 04/01/2014
[  355.900764] task: ffff88007bef1c00 ti: ffff88007b7a8000 task.ti: ffff88007b7a8000
[  355.900765] RIP: 0010:[<ffffffffc0351015>]  [<ffffffffc0351015>] hog_thread+0x15/0x1000 [hog]
[  355.900769] RSP: 0018:ffff88007b7abeb8  EFLAGS: 00000286
[  355.900770] RAX: 0000000000000011 RBX: ffff88007b580500 RCX: 0000000000000006
[  355.900772] RDX: 0000000000000000 RSI: 0000000000000246 RDI: ffff88007fc0dd50
[  355.900773] RBP: ffff88007b7abeb8 R08: 000000000000000a R09: 000000000000022f
[  355.900774] R10: ffff880035596a00 R11: 000000000000022f R12: ffff88007bef1c00
[  355.900775] R13: 0000000000000000 R14: ffffffffc0351000 R15: 0000000000000000
[  355.900777] FS:  0000000000000000(0000) GS:ffff88007fc00000(0000) knlGS:0000000000000000
[  355.900778] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[  355.900779] CR2: ffffffffc0350fea CR3: 0000000001e0a000 CR4: 00000000001406f0
[  355.900783] Stack:
[  355.900784]  ffff88007b7abf48 ffffffff810a0c25 0000000000000000 0000000000000000
[  355.900786]  0000000000000000 ffff880000000000 ffff880000000000 ffff88007b7abef0
[  355.900789]  ffff88007b7abef0 ffffffff00000000 ffff880000000000 ffff88007b7abf10
[  355.900791] Call Trace:
[  355.900796]  [<ffffffff810a0c25>] kthread+0xe5/0x100
[  355.900799]  [<ffffffff810a0b40>] ? kthread_create_on_node+0x1e0/0x1e0
[  355.900802]  [<ffffffff81840f0f>] ret_from_fork+0x3f/0x70
[  355.900803]  [<ffffffff810a0b40>] ? kthread_create_on_node+0x1e0/0x1e0
[  355.900804] Code: <eb> fe 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00

In diesem exemplarischen Beispiel sieht man nun schön, dass mein hog_thread als Übeltäter erkannt wurde.

Hier müssen wir Folgendes beachten:

  • Hat das System mehr als eine CPU, ist es weiterhin benutzbar.
  • Startet man genügend Kernel-Threads, sodass alle CPUs ausgelastet sind, geht fast nichts mehr. Die Meldungen über den Softlockup erscheinen weiterhin auf der Konsole, aber mit SSH hat man keine Chance mehr.

Hardlockups

Man braucht nur eine kleine Variation des obigen Codes:

#include <linux/init.h>
#include <linux/module.h>
#include <linux/kernel.h>
#include <linux/kthread.h>
#include <linux/spinlock.h>
 
MODULE_LICENSE("GPL");
 
static int
hog_thread(void *data)
{
    static DEFINE_SPINLOCK(lock);
    unsigned long flags;
 
    printk(KERN_INFO "Hogging a CPU now\n");
    spin_lock_irqsave(&lock, flags);
    while (1);
 
    /* unreached */
    return 0;
}
 
static int __init
hog_init(void)
{
    kthread_run(hog_thread, NULL, "hog");
    return 0;
}
 
module_init(hog_init);

Das Kompilieren und Benutzen geht genauso.

Was sehen wir? Sobald das Modul geladen ist, geht gar nichts mehr. Das erscheint schlüssig, denn mit maskierten Interrupts kann (zumindest nach meinem Verständnis) auch der Scheduler nicht mehr funktionieren.

Nach einigen Sekunden sieht man auf der ersten Konsole dann die Meldung über einen Hardlockup. Falls wir das in einer VM testen, die mit KVM virtualisiert wird, müssen wir erst den NMI-Watchdog mit folgendem Kernel-Parameter aktivieren:

nmi_watchdog=1

Zum Weiterlesen

https://www.kernel.org/doc/Documentation/lockup-watchdogs.txt
http://www.inetservicescloud.com/knowledgebase/what-is-a-cpu-soft-lockup/
https://lists.kernelnewbies.org/pipermail/kernelnewbies/2012-January/004480.html
https://access.redhat.com/articles/17187
https://kb.vmware.com/selfservice/microsites/search.do?language=en_US&cmd=displayKC&externalId=1009996
http://derekmolloy.ie/writing-a-linux-kernel-module-part-1-introduction/
https://stackoverflow.com/questions/12974110/simple-kernel-multithreading
https://www.kernel.org/doc/Documentation/locking/spinlocks.txt

Im IT-Tagebuch schreibt ein Kollege aus unserem IT-Team in loser Folge über Themen, Probleme und Lösungen, die ihm im Arbeitsalltag begegnen.


Mehr über die Creative-Commons-Lizenz erfahren

ACHTUNG!
Unsere Blogartikel sind echte Zeitdokumente und werden nicht aktualisiert. Es ist daher möglich, dass die Inhalte veraltet sind und nicht mehr dem neuesten Stand entsprechen. Dafür übernehmen wir keinerlei Gewähr.

Schreibe einen Kommentar