Разработка ядра Linux (Второе издание)

Лав Роберт

Демон

syslogd

добавляет полученные сообщения в конец файла журнала, по умолчанию —

/var/log/messages

. Имя соответствующего файла можно настроить в конфигурационном файле

/etc/syslog.conf

.

Изменить уровень вывода сообщений на консоль (console loglevel) можно при старте демона

klogd

с помощью флага

– с

.

Замечание относительно функции

printk

и разработки ядра

Когда впервые начинают разрабатывать код ядра, то скорее всего очень часто приходится заменять функцию

printf

на

функцию

printk

. Это нормально, потому что нельзя не принимать во внимание многолетний опыт по написанию пользовательских программ и использовании функции

printf

. Следует надеяться, что повторение таких ошибок не будет продолжаться долго, потому что повторяющиеся ошибки компоновщика начнут быстро надоедать.

Однажды вдруг окажется, что вы поймали себя на том, что начали использовать функцию

printk

вместо функции

printf

в пользовательских программах. Когда для вас этот день наконец наступит, то можно сказать, что вы стали настоящим хакером и специалистом по разработке кода ядра.

Сообщения

Oops

Сообщения oops — обычный для ядра способ сообщить пользователю, что произошло что-то нехорошее. Так как ядро управляет всей системой, то оно не может само себя исправить, или завершить, как это возможно для программ пространства пользователя, когда они делают что-то не так. Вместо этого, ядро выводит сообщение

oops

. Такое сообщение включает вывод информации об ошибке на консоль, вывод дампа содержимого всех регистров и вывод обратной трассировки вызовов функций (back trace). Сбои в работе ядра трудно обработать, поэтому ядро должно "пролезть'' через многие дыры, чтобы вывести сообщение

oops

и выполнить за собой все необходимые действия по очистке. Часто после выдачи сообщения

oops

ядро находится в несогласованном состоянии. Например, в момент возникновения ситуации, в которой выдается сообщение

oops

, ядро может находится в процессе обработки важных данных. В этот момент может удерживаться блокировка, или выполняться сеанс взаимодействия с оборудованием. Ядро должно аккуратно отойти от текущего состояния и попытаться восстановить контроль над системой. Во многих случаях это невозможно. Если ситуация, в которой выдается сообщение

oops

, возникает в контексте прерывания, то ядро не может продолжать работу и переходит в состояние паники. Состояние паники проявляется в полной остановке системы. Если

oops

возникает в холостой задаче (idle task, идентификатор

pid

равен нулю), или при выполнении процесса

init

(идентификатор

pid

равен единице), то ядро также переходит в состояние паники, потому что ядро не может продолжать выполнение без этих важных процессов. Однако, если

oops

возникает при выполнении любого другого процесса, то ядро завершает этот процесс и продолжает работу.

Сообщение

oops

может выдаваться по многим причинам, включая недопустимый доступ к памяти (memory access violation) и выполнение недопустимой машинной команды. Как разработчику ядра, вам придется иметь дело с сообщениями

oops

и далее, несомненно, быть причиной их появления.

Ниже показано сообщение

oops

для машины аппаратной платформы PPC, которое возникло и обработчике таймера для сетевого интерфейсного адаптера tulip.

Oops: Exception in kernel mode, sig: 4

Unable to handle kernel NULL pointer dereference at virtual address 00000001

NIP: C013A7F0 LR: C013A7F0 SP:C0685E00 REGS: c0905d10 TRAP: 0700

Not tainted

MSR: 00089037 EE: 1 PR: 0 FP: 0 ME: 1 IR/DR: 11

TASK=c0712530[0] swapper Last syscall: 120

GPR00: C013A7C0 C0295E00 C0231530 0000002F 00000001 C0380CB8 C0291B80 C02D0000

GPR08: 000012AD 00000000 00000000 C0292AA0 4020A088 00000000 00000000 00000000

GPR16: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000

GPR24: 00000000 00000005 00000000 00001032 C3F7C000 00000032 FFFFFFFF C3F7C1C0

Call trace:

[c013ab30] tulip_timer+0x128/0x1c4

[c0020744] run_timer_softirq+0x10c/0x164

[c001b864] do_softirq+0x88/0x104

[c0007e80] timer_interrupt+0x284/0x298

[c00033c4] ret_from_except+0x0/0x34

[c0007b84] default_idle+0x20/0x60

[c0007bf8] cpu_idle+0x34/0x38

[c0003ae8] rest_init+0x24/0x34

У

пользователей ПК может вызвать удивление количество регистров процессора (32 — огромное число!). Сообщение

oops

для аппаратной платформы x86, которые возможно вам более знакомы, имеют несколько более простой вид. Тем не менее, важная информация идентична для всех аппаратных платформ: содержимое всех регистров и обратная трассировка.

Обратная трассировка показывает точную последовательность вызовов функций, которая привела к проблеме. В данном случае можно точно определить, что случилось: машина выполняла холостое задание — холостой цикл: вызов функции

cpu_idle

, из которой циклически вызывается функция

default_idle

. Поступило прерывание от системного таймера, в котором вызываются обработчики таймеров ядра. Среди них вызывается обработчик таймера — функция

tulip_timer

, в которой выполнено разыменование указателя со значением

NULL

. Можно даже воспользоваться значением смещения (числа вроде 0х128/0х1с4, которые указаны справа от имени функции) для точного нахождения команды, в которой возникла ошибка.

Содержимое регистров точно также полезно, хотя и используется не так часто. Вместе с дизассемблированным кодом функции содержимое регистров может помочь восстановить точную последовательность событий, которая привела к проблеме. Если значение в некотором регистре не соответствует ожидаемому, то это может пролить некоторый свет на корень проблемы. В данном случае можно проверить, какие регистры содержат значение

NULL

(все разряды нулевые) и определить, какая из переменных функции содержит не то значение. В ситуациях, похожих на данную, скорее всего причина — конкуренция за ресурс (race) и скорее всего между таймером и другой частью сетевого адаптера. Отладка состояний конкуренции за ресурсы — всегда серьезная задача.

Утилита

ksymoops

Только что рассмотренное сообщение

oops

имеет так называемый декодированный вид, потому что адреса памяти транслированы в имена функций, которые им соответствуют. Не декодированный вид предыдущего сообщения выглядит следующим образом.

NIP: C013A7F0 LR: C013A7F0 SP: C0685E00 REGS: c0905d10 TRAP: 0700

Not tainted

MSR: 00089037 EE: 1 PR: 0 FP: 0 ME 1 IR/DR: 11

TASK = c0712530 [0] 'swapper' Last syscall: 120