Debuggowanie jądra

Co to właściwie jest debuggowanie?

Debuggowanie - proces usuwania blędów niewychwytywalnych przez kompilator z programów.

Debuggowanie jądra a debuggowanie programu użytkowego

Podstawową barierą która utrudnia znacząco debuggowanie jądra jest to że jądro systemu nie ma środowiska uruchomieniowego jakie mają zwyczajne aplikacje. Często aby sprawdzić kawałek kodu jądra potrzebne jest jego skompilowanie co jest czynnikiem bardzo spowalniającym cały proces wyszukiwania i usuwania błędów. Kompilacja jądra może trwać od kilku minut do kilku godzin, wiec każdą zmianę w kodzie trzeba gruntownie przeanalizowac. Dużo wiekszy nacisk, niż ma to miejsce w tworzeniu programów działających w trybie użytkownika, trzeba kłaść na dokładne zrozumienie napisanego kodu. Jądro systemu jest najbliżej "sprzętu", tzn. nie ma żadnego programu pod którym jest uruchomione. Wydawałoby się że wyklucza to możliwość użycia programu debuggującego. Udało się jednak obejść tę niedogodność stosując maszynę wirtualną UML, czy też debugger wbudowany jakim jest kdb.

Strona ta prezentuje kilka technik oraz narzędzi służących do debuggowania począwszy od tych prostszych, bardziej prymitywnych takich jak używanie funkcji printk(), po te bardziej zaawansowane takie jak kdb, kgdb czy też odpluskwianie przy użyciu UMLa.

Funkcja printk()

Funkcja ta umożliwia debuggowanie jądra poprzez wypisywanie komunikatów będących jej parametrami. W kodzie jądra często możemy napotkać na jej wywołania, np.:

preempt_disable();
build_all_zonelists();
page_alloc_init();
printk(KERN_NOTICE "Kernel command line: %s\n", saved_command_line);
parse_early_param();

Jak widać możemy umieszczać pola typu %s czy %d. Przydaje się to szczególnie np. gdy chcemy wypisać wartość jakiejś zmiennej.

Teraz należałoby wyjaśnić czym jest ten tajemniczy KERN_NOTICE w przykładzie powyżej i czemu nie następuje po nim przecinek. Odpowiedź na te pytania kryje plik kernel.h:

#define	KERN_EMERG	"<0>"	/* system is unusable			*/
#define	KERN_ALERT	"<1>"	/* action must be taken immediately	*/
#define	KERN_CRIT	"<2>"	/* critical conditions			*/
#define	KERN_ERR	"<3>"	/* error conditions			*/
#define	KERN_WARNING	"<4>"	/* warning conditions			*/
#define	KERN_NOTICE	"<5>"	/* normal but significant condition	*/
#define	KERN_INFO	"<6>"	/* informational			*/
#define	KERN_DEBUG	"<7>"	/* debug-level messages			*/

Napis KERN_NOTICE odpowiada stringowi "<5>" który jest konkatenowany z główną informacją jaką niesie wywołanie printk(). Stąd bierze się brak przecinka. Czyli liczba ujeta w nawiasy kątowe jest doklejana na początek informacji, co wyznacza jej priorytet. Gdy chcemy zapisać informację że zaszedł jakiś poważny błąd wywołujemy printk() z KERN_CRIT. Jeśli chemy tylko poinformować o czymś używamy KERN_INFO.

Aby przekonać się jak działa funkcja printk w praktyce można dopisać linijkę z wywołaniem w pewnym miejscu w kodzie jądra. Niech to będzie na przykład funkcja sysrq_handle_showregs() z pliku drivers/char/sysrq.c. Funkcja ta jest odpowiedzialna za reakcję na wciśnięcie kombinacji klawiszy Alt+SysRq+P. Po dopisaniu wywołania funkcja ta wygląda nastepująco:

static void sysrq_handle_showregs(int key, struct pt_regs *pt_regs,
				  struct tty_struct *tty)
{
	printk(KERN_EMERG "Wcisnieto klawisze Alt+SysRq+P\n");
	if (pt_regs)
		show_regs(pt_regs);
}

Oczywiście priorytet jaki został nadany naszej informacji jest niezbyt odpowiedni, lecz pozostawimy go takim aby efekt wywołania był bardziej zauważalny.

Po uruchomieniu systemu z nowym jądrem, możemy sprawdzić co się stanie po wciśnięciu kombinacji klawiszy Alt+SysRq+P.

Efekt? Na każdej istniejącej konsoli pojawił się następujący napis:

Nov 19 01:14:57 localhost kernel: SysRq : show regs
Nov 19 01:14:57 localhost kernel: Wcisnieto klawisze Alt+SysRq+P

Najwyższa pora aby wyjaśnić czemu ów napis został wyświetlony. Kluczem do zrozumienia tego mechanizmu jest poznanie dwóch demonów systemowych: syslogd i klogd.

Demony syslogd i klogd

daemon - proces dzialający w tle, którego nie widzi użytkownik, wykonujący czynności usługowe na rzecz systemu i klientów (źr. Wikipedia)

Syslogd jest narzędziem służącym do rejestrowania zdarzeń systemowych, zbiera on komunikaty zwane logami dostarczane przez system i zapisuje na dysku, wysyla na konsolę lub na inny komputer. Klogd natomiast zajmuje sie jedynie jądrem systemu, to przez niego przechodzą wszelkie komunikaty jakie wypisujemy przy użyciu funkcji printk(). Do jego obowiązków należy między innymi przesyłnie odpowiednio spriorytetyzowanych do syslogda. Syslogd dokonuje sortowania komunikatów mu dostarczonych na podstawie ich źródła oraz priorytetu i w zależności od tych dwóch czynników wysyła w odpowiednie miejsce. O tym gdzie wysłać odpowiedni komunikat decyduje plik konfiguracyjny syslog.conf. Oto fragment tego pliku:

# Kernel logging
kern.=debug;kern.=info;kern.=notice                             -/var/log/kernel/info
kern.=warn                                                      -/var/log/kernel/warnings
kern.err                                                        /var/log/kernel/errors

Plik ten składa sie z szeregu wpisów. Natomiast w skład każdego wpisu wchodzi źródło, priorytet oraz miejsce przeznaczenia pliku dziennika. Źródłami są m.in.: cron, daemons, kernel, news i mail.

W pliku syslog.conf znajduje się też taki wpis:

# Everybody gets emergency messages
*.emerg                                                         *

Mówi on o tym, że komunikaty o najwyższym priorytecie mają być wysyłane wszędzie gdzie się da. Stąd właśnie wynika reakcja systemu na wciśnięcie kombinacji klawiszy Alt+SysRq+P.

Jeśli chcemy aby np. komunikaty od jądra o priorytecie "err" trafiały na czwartą konsolę to w pliku syslog.conf dopisujemy następującą linijkę:

kern.=err                                                        /dev/tty4

Standardowym miejscem przechowywania plików z logami jest katalog var/log/. W katalogu tym jest wiele podkatalogów odpowiadających poszczególnym funkcjonalnością systemu. Przyjrzyjmy sie bliżej fragmentowi jednego z plików z katalogu var/log:

Oct 23 20:23:40 localhost kernel: hub 3-0:1.0: USB hub found
Oct 23 20:23:40 localhost kernel: hub 3-0:1.0: 8 ports detected
Oct 23 20:23:40 localhost kernel: usb 1-2: USB disconnect, address 2
Oct 23 20:23:40 localhost kernel: usbcore: registered new driver hiddev
Oct 23 20:23:40 localhost kernel: ohci_hcd 0000:00:13.0: wakeup
Oct 23 20:23:40 localhost kernel: usbcore: registered new driver usbhid
Oct 23 20:23:40 localhost kernel: drivers/usb/input/hid-core.c: v2.6:USB HID core driver

Każdy taki wpis składa się z daty, nazwy komputera, nazwy programu i właściwej treści komunikatu. Doklejaniem trzech pierwszych elementów do treści komunikatu zajmuje się właśnie syslogd.

Reasumując demony syslogd i klodg w połączeniu z funkcją printk() dają nam pomocne narzędzie w debuggowaniu jądra. Ustawiając wywołania funkcji printk() w strategicznych miejscach kodu jądra możemy wyciągnąc wiele cennych informacji. Dodatkowo za pomocą funkcji printk() możemy sprawdzać wartości zmiennych.

Kolejnymi narzędziami które warto tutaj omówić są programy:

strace i ltrace

strace - wypisuje wywołania systemowe, sygnały jakie otrzymuje śledzony proces
ltrace - wypisuje wywołania bibliotek ładowanych dynamicznie, sygnaly, również wywołania systemowe

Gdy wpiszemy w konsoli:

strace echo "Ala ma kota"

Oto co dostaniemy w wyniku:

execve("/bin/echo", ["echo", "Ala ma kota"], [/* 67 vars */]) = 0
brk(0)                                  = 0x804d000
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb7f39000
access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)
open("/etc/ld.so.cache", O_RDONLY)      = 4
fstat64(4, {st_mode=S_IFREG|0644, st_size=80178, ...}) = 0
mmap2(NULL, 80178, PROT_READ, MAP_PRIVATE, 4, 0) = 0xb7f25000
.
.....
.
write(1, "Ala ma kota\n", 12Ala ma kota)= 12
close(1)                                = 0
munmap(0xb7f27000, 4096)                = 0
exit_group(0)                           = ?
Process 6404 detached

W każdej linii tego co wyrzucił strace jest wypisane jedno wywolanie systemowe. Wywołania te są wypisane w kolejości chronologicznej. W nawiasach mamy ponadto argumenty takiego wywołania oraz, po znaku równości, wynik jaki zwróciło wywołanie.

Warto zwrócić uwagę na następującą linijkę:

access("/etc/ld.so.preload", R_OK)      = -1 ENOENT (No such file or directory)

Jak widać gdy wywołanie zakończy się błędem to strace wypisze nam typ błędu (w tym wypadku jest to ENOENT) oraz informację na jego temat.

Podobnie działa program ltrace. Wpiszmy:

ltrace echo "Ala ma kota"

Ltrace wyrzuci nam:

__libc_start_main(0x8048c40, 2, 0xbfe37b44, 0x804a570, 0x804a560 
getenv("POSIXLY_CORRECT")                                                          = NULL
setlocale(6, "")                                                                   = "pl_PL.UTF-8"
bindtextdomain("coreutils", "/usr/share/locale")                                   = "/usr/share/locale"
textdomain("coreutils")                                                            = "coreutils"
__cxa_atexit(0x80490d5, 0, 0, 0xb7ee2ff4, 0xbfe37aa8)                              = 0
getopt_long(2, 0xbfe37b44, "+", 0x804ac80, NULL)                                   = -1
fputs_unlocked(0xbfe386ca, 0xb7ee34c0, 0x804aa03, 0x804ab13, 0x804ab0e)            = 1
putchar_unlocked(10, 0xb7ee34c0, 0x804aa03, 0x804ab13, 0x804ab0eAla ma kota)       = 10
exit(0 
ferror_unlocked(0xb7ee34c0, 0xb7efb6c0, 1, 1, 0)                                   = 0
__fpending(0xb7ee34c0, 0xb7efb6c0, 1, 1, 0)                                        = 0
fclose(0xb7ee34c0)                                                                 = 0
+++ exited (status 0) +++

Tym razem wynikiem są poszczególne wywołania bibliotek ładowanych dynamicznie jakie polecenie echo wykonuje.

No dobrze, ale jak to się ma do debuggowania jądra?

Otóż sam strace i ltrace niewiele mogą w tej kwestii zdziałać, lecz w połączeniu z maszyną wirtualną UML stają się silnym narzędziem za pomocą którego możemy oglądać wykonanie jądra.

Podsumowanie

Wyżej wymienione techniki stanowią podstawę jeśli chodzi o znajdowanie i usuwanie błędów w jądrze. W niektórych zastosowaniach zdecydowanie wystarczają (np. przy dokonywaniu drobnych poprawek, pisaniu mało skomplikowanego kodu), jednak gdy zachodzi konieczność napisania czegoś większego mogą okazać się zbyt słabe. Dlatego warto zapoznać sie jeszcze z narzędziami takimi jak kdb, kgdb oraz maszyną wirtualną UML. Są to narzędzia zdecydowanie mocniejsze, oferujące więcej możliwości od wyżej opisanych.