pixelgeist
ich hoffe ich bin hier nicht deplaziert... jedenfalls hatte ich gerade eine pdf mit okular offen. als ich das programm beende, bleibt die oberfläche (kde 4.4.5) plötzlich stehen, nichts geht mehr. sämtliche versuche den rechner sauber herunterzufahren bleiben erfolglos... reset.
nach dem neustart überprüfe ich die logfiles und werden (denke ich zumindest) fündig. allerdings hoffe ich hier auf ein paar expertenmeinungen, die mir helfen können, die fehlerursache einzugrenzen.
der systemabsturz war um 17:22:?? und im log sind auch noch einträge von den folgenden 2 minuten enthalten, die der rechner noch lief. für mich bedeutet es, das lediglich die grafische oberfläche abgestürzt ist, der kernel aber noch munter weiterlief. im call stack sind funktionsaufrufe enthalten, die auf "radeon" (mein grafiktreiber: xf86-video-ati) hindeuten. aber sicher bin ich mir nicht. was ist jetzt eigentlich schiefgelaufen?
[/var/log/kernel.log]
Jul 28 17:22:57 hive kernel: general protection fault: 0000 [#1] PREEMPT SMP
Jul 28 17:22:57 hive kernel: last sysfs file: /sys/devices/pci0000:00/0000:00:11.0/host2/target2:0:0/2:0:0:0/block/sdc/uevent
Jul 28 17:22:57 hive kernel: CPU 2
Jul 28 17:22:57 hive kernel: Modules linked in: fuse ipv6 ext3 jbd joydev usbhid hid snd_hda_codec_atihdmi snd_hda_codec_realtek snd$
Jul 28 17:22:57 hive kernel:
Jul 28 17:22:57 hive kernel: Pid: 7085, comm: X Not tainted 2.6.34-ARCH #1 GA-MA785GT-UD3H/GA-MA785GT-UD3H
Jul 28 17:22:57 hive kernel: RIP: 0010:[<ffffffffa005b430>] [<ffffffffa005b430>] ttm_bo_release_list+0xa0/0xf0 [ttm]
Jul 28 17:22:57 hive kernel: RSP: 0018:ffff8801981c7bd8 EFLAGS: 00010282
Jul 28 17:22:57 hive kernel: RAX: f7ffffffa009d520 RBX: ffff88016127f848 RCX: ffffffffa005a878
Jul 28 17:22:57 hive kernel: RDX: 0000000000000012 RSI: ffffea0006750e28 RDI: ffff88016127f848
Jul 28 17:22:57 hive kernel: RBP: ffff8801981c7bf8 R08: 0000000000000004 R09: 0000000000000000
Jul 28 17:22:57 hive kernel: R10: ffff8800000192c0 R11: 0000000000000000 R12: ffff88016127f88c
Jul 28 17:22:57 hive kernel: R13: ffff880226bd04e0 R14: 0000000000001cec R15: 0000000040086409
Jul 28 17:22:57 hive kernel: FS: 00007f235c292840(0000) GS:ffff880001900000(0000) knlGS:0000000000000000
Jul 28 17:22:57 hive kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Jul 28 17:22:57 hive kernel: CR2: 00007f235c112000 CR3: 0000000226d69000 CR4: 00000000000006e0
Jul 28 17:22:57 hive kernel: DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
Jul 28 17:22:57 hive kernel: DR3: 0000000000000000 DR6: 00000000ffff0ff0 DR7: 0000000000000400
Jul 28 17:22:57 hive kernel: Process X (pid: 7085, threadinfo ffff8801981c6000, task ffff88019dbe9c80)
Jul 28 17:22:57 hive kernel: Stack:
Jul 28 17:22:57 hive kernel: ffff8801981c7c18 ffff88016127f88c ffffffffa005b390 ffff880226a33820
Jul 28 17:22:57 hive kernel: <0> ffff8801981c7c18 ffffffff811ccb47 ffff88016127f848 ffff880226bd0500
Jul 28 17:22:57 hive kernel: <0> ffff8801981c7c38 ffffffffa005c43a ffff88016127f888 ffffffffa005c3d0
Jul 28 17:22:57 hive kernel: Call Trace:
Jul 28 17:22:57 hive kernel: [<ffffffffa005b390>] ? ttm_bo_release_list+0x0/0xf0 [ttm]
Jul 28 17:22:57 hive kernel: [<ffffffff811ccb47>] kref_put+0x37/0x70
Jul 28 17:22:57 hive kernel: [<ffffffffa005c43a>] ttm_bo_release+0x6a/0x80 [ttm]
Jul 28 17:22:57 hive kernel: [<ffffffffa005c3d0>] ? ttm_bo_release+0x0/0x80 [ttm]
Jul 28 17:22:57 hive kernel: [<ffffffff811ccb47>] kref_put+0x37/0x70
Jul 28 17:22:57 hive kernel: [<ffffffffa005b97d>] ttm_bo_unref+0x3d/0x50 [ttm]
Jul 28 17:22:57 hive kernel: [<ffffffffa009d8f5>] radeon_bo_unref+0x25/0x50 [radeon]
Jul 28 17:22:57 hive kernel: [<ffffffffa00b204c>] radeon_gem_object_free+0x2c/0x30 [radeon]
Jul 28 17:22:57 hive kernel: [<ffffffffa0019858>] drm_gem_object_free_unlocked+0x78/0x90 [drm]
Jul 28 17:22:57 hive kernel: [<ffffffffa00197e0>] ? drm_gem_object_free_unlocked+0x0/0x90 [drm]
Jul 28 17:22:57 hive kernel: [<ffffffff811ccb47>] kref_put+0x37/0x70
Jul 28 17:22:57 hive kernel: [<ffffffffa0019dc8>] drm_gem_close_ioctl+0xa8/0xd0 [drm]
Jul 28 17:22:57 hive kernel: [<ffffffffa0017a5c>] drm_ioctl+0x38c/0x470 [drm]
Jul 28 17:22:57 hive kernel: [<ffffffffa0019d20>] ? drm_gem_close_ioctl+0x0/0xd0 [drm]
Jul 28 17:22:57 hive kernel: [<ffffffff810e18f5>] ? __free_pages+0x25/0x30
Jul 28 17:22:57 hive kernel: [<ffffffff81110913>] ? __free_slab+0xb3/0x160
Jul 28 17:22:57 hive kernel: [<ffffffff810fbf3e>] ? remove_vma+0x4e/0x70
Jul 28 17:22:57 hive kernel: [<ffffffff811318cc>] vfs_ioctl+0x3c/0xd0
Jul 28 17:22:57 hive kernel: [<ffffffff81131ecc>] do_vfs_ioctl+0x7c/0x540
Jul 28 17:22:57 hive kernel: [<ffffffff810fbf3e>] ? remove_vma+0x4e/0x70
Jul 28 17:22:57 hive kernel: [<ffffffff810fd3a9>] ? do_munmap+0x2c9/0x330
Jul 28 17:22:57 hive kernel: [<ffffffff81132411>] sys_ioctl+0x81/0xa0
Jul 28 17:22:57 hive kernel: [<ffffffff81009ec2>] system_call_fastpath+0x16/0x1b
Jul 28 17:22:57 hive kernel: Code: 62 48 8b bb 98 00 00 00 48 85 ff 74 05 e8 d9 f3 ff ff 49 8b 44 24 bc f0 ff 88 c0 00 00 00 49 8b 4$
Jul 28 17:22:57 hive kernel: RIP [<ffffffffa005b430>] ttm_bo_release_list+0xa0/0xf0 [ttm]
Jul 28 17:22:57 hive kernel: RSP <ffff8801981c7bd8>
Jul 28 17:22:57 hive kernel: ---[ end trace 58abbd226a198945 ]---
eiffel56
Ein kompletter Systemabsturz, und das ist einer und nicht nur n X-Freeze, kann nicht durch einen Bug einer Software im Userland, wie KDE, erzeugt werden. Die einzige Ausnahme besteht bei Prozessen die Root-Rechte haben und es drauf anlegen, denn die könnten ein böses Kernelmodul laden, haben Zugriff auf /dev/mem und so weiter.
Versuchen wir uns doch mal an einer simplen Wahrscheinlichkeitanalyse mithilfe der Daten die du noch rausfischen konntest:
Überaus hilfreich dafür ist der Call Trace. Er beinhaltet die Funktionen, die im Kernel zuletzt aufgerufen wurden. Chronologisch gelesen wird er von unten nach oben. Die oberste ist also die Funktion die zuletzt aktiv war, in der also der Fehler auftauchte, und die wurde von der darunter aufgerufen, welche von der darunter aufgerufen wurde und so weiter.
Wie man an dem Call Trace sehen kann stürzte das System in der Funktion ttm_bo_release_list ab. Die ist Teil von DRM, welches im Prinzip dafür sorgt dass mehrere Anwendungen hardwarebeschleunigtes 3D machen können.
Leider ist mal wieder nicht beschrieben was TTM ist(leider typisch für den gesamten Kram rund um freie Grafikbeschleunigung und X: Es werden neue Techniken und Kürzel erfunden oder bestehende verwendet, die aber nirgends dokumentiert sind). Zumindest habe ich auf die Schnelle nichts gefunden. Was aber aus dem Source ersichtlich ist ist dass der TTM-Kram nichts spezifisches für deine Grafikkarte ist, sondern für alle Treiber geteilt wird. Das ist wichtig, weil das die Chance verringert dass der Fehler da lag, weil ein Fehler da potenziell schon Benutzern und Entwicklern anderer Treiber, die den Code auch benutzen, aufgefallen sein könnte.
Die nächste Funktion ist kref_put. Ich weiß nicht wie sehr du mit der Programmierung vertraut bist, aber ich erklärs kurz trotzdem:
Wenn Daten in einem Programm von mehreren, eigentlich voneinander unabhängigen Teilen benötigt werden stellt sich die Frage wann man die Daten entladen kann. Irgendwie müssen sich die Teile gegenseitig signalisieren ob sie die Daten noch benötigen oder nicht. Um das zu lösen benutzt man eine Abart von intelligenten Zeigern, nämlich Referenzzählende Zeiger. Simpel gesagt sind das Variablen die einen Referenzzähler haben. Am Anfang steht der auf 1, und immer wenn ein Teil die Variable benutzt wird der Zähler um eins erhöht. Und genau umgekehrt: Wenn sie nicht mehr gebraucht wird wird sie um 1 verringert. Erreicht der Referenzzähler 0 werden die Daten entladen.
Für die Analyse wichtig ist daran nur dass diese Implementierung für Referenzzählende Zeiger im gesamten Kernel benutzt wird. Es ist also noch sehr viel unwahrscheinlicher dass hier ein Bug vorliegt. Es wäre aufgefallen, ziemlich sicher. Die werden überall verwendet.
Die nächsten Einträge drehen sich um die DRI-Implementierung für Radeon-Karten(radeon_bo_unref und radeon_gem_object_free). Obwohl diese 2 Funktionen relativ triviale Aufgaben übernehmen, nämlich Daten löschen, ist es sehr wahrscheinlich dass der Bug irgendwo im Radeon-Treiber liegt, aber nicht in den beiden Funktionen. Das ist damit zu begründen dass weiter unten im Trace weiterhin Funktionen auftauchen die alle für den gesamten Kernel geteilt werden, es also bei denen wieder unwahrscheinlicher wird dass sie einen Bug enthalten. Die Funktion radeon_gem_object_free wurde also wahrscheinlich mit gültigen Parametern aufgerufen.
Auch wenn wahrscheinlich weder radeon_gem_object_free noch radeon_bo_unref den Bug enthalten, liegt der Fehler vermutlich im Radeon-Treiber. Man kann davon ausgehen dass zu einem früheren Zeitpunkt Daten bzw. Datenstrukturen, die Zeiger auf die eigentlichen Daten enthalten, nicht richtig aufgesetzt oder aktualisiert wurden. Es ist wahrscheinlich dass die Funktion radeon_bo_unref versucht Daten zu löschen, die eigentlich schon längst nicht mehr da sind. Und sowas führt nunmal zu einer Zugriffsverletzung, wie sie uns vom Kernel in der ersten Zeile gemeldet wird.
Wir können uns jetzt, mit etwas Hilfe vom Sourcecode, den Hergang rekonstruiren:
Als Folge eines Syscalls(unterster Eintrag, ein Syscall ist die Art- und Weise wie Userland-Programme meistens mit dem Kernel kommunizieren) wird die Funktion radeon_gem_object_free durch DRM gewrappt aufgerufen. Es sollen also Daten entladen werden. radeon_gem_object_free ist wiederrum ein Wrapper, der ultimativ kref_put aufruft, der den Referenzzähler um eins verringert. Da er jetzt 0 erreicht hat wird ttm_bo_release aufgerufen, das als Funktion registriert wurde um die Daten dieses Typs zu entladen. Diese ruft dann ttm_bo_release_list auf, da es selbst keine Listen entladen kann, ttm_bo_release_list entlädt dann die Daten und Peng, Zugriffverletzung. Sollten alle Funktionen auf diesem Weg sauber implementiert sein, und das ist wahrscheinlich da Daten entladen jetzt nicht so schwarze Magie ist und Entwickler sowas schon sehr oft gebaut haben, wurden irgendwann vorher schonmal die Daten entladen die jetzt das Ziel der Aktion sein sollten, aber das wurde nicht registriert. So wird es jetzt nochmal gemacht, der Code weiß ja nicht dass die Daten schon längst weg sind, und das führt dann zu dem Absturz.
Vielleicht lief der Kernel zu dem Zeitpunkt noch halbwegs rund, vermutlich tat er das weil er ja das Log noch auf die Festplatte schreiben konnte, aber zumindest dein X war genug verwirrt um stecken zu bleiben. Abgesehen davon dass spätestens zu dem Zeitpunkt der Speicher hinreichend außer Kontrolle war um ein stabiles Weiterarbeiten nicht garantieren zu können. Ich weiß nicht ob daraufhin ein Kernel Panic folgte, der Kernel hätte genug Informationen haben können um das zu verhindern, aber meistens passiert es dann doch. Einfach nur aus reiner Vorsicht. Man will nicht mit verwurschteltem Speicher weiterarbeiten.
Wir wissen jetzt also dass der Fehler vermutlich irgendwo im ganzen Radeontreiber-Konstrukt liegt. Es könnte natürlich auch ein Hardwarefehler sein, aber das ignorieren wir erstmal.
Um jetzt die genaue Ursache zu finden, also herauszufinden wo Daten entladen wurden ohne dem Rest darüber bescheid zu geben, bräuchte man Erfahrung, einen Debugger, viel Zeit und eine Methode um genau deinen Bug mit Absicht auszulösen. Sollte das jetzt das erste Mal aufgetreten sein, und auch nie wieder passieren, wäre zumindest die Zeit die man dafür aufwänden müsste irgendwo anders besser aufgehoben.
Fest steht zumindest dass der Absturz nicht durch eine Funktion im Call Trace ausgelöst wurde, sondern die Verhaltensweise derer nur die Folge eines Fehler irgendwo anders ist, die dann leider zu dem Absturz führte.
Natürlich könnte auch alles ganz anders sein. Aber diese Schlussfolgerung ist eine der wahrscheinlichsten. Es kann auch durchaus sein dass ich was wichtiges nicht oder nicht genug beachtet hab. Für genaue Ergebnisse müsste man viel Zeit aufwenden.