Мало кто знает, что в ядре Linux есть необычные и весьма полезные инструменты для отладки и тестирования. В этой небольшой статье я хочу поделиться описанием трассировщика ввода-вывода.

Введение

Трассировщик ввода-вывода был разработан в своё время для тестирования надёжности драйверов (https://landley.net/kdocs/ols/2003/ols2003-pages-524-530.pdf), а позднее развился в проект реверс инжинирига протокола программирования видеоплат nVidia для проекта Nouveau. Однако помимо этой цели в процессе развития появился удобный инструмент не столько тестирования, сколько отладки драйверов.

Преимущества данного метода очевидны — отладочная печать медленная, более того вносящая нежелательные задержки времени исполнения, что часто может приводить к неверной работе программы (уверен, что вы сталкивались с таким, что debug версия работает, а release — нет, или наоборот). Недостатки тоже есть, как то:

• вероятность потери событий при определённых условиях (см. ниже)
• невозможность отладки шин, для которых окно всегда присутствует, например, ISA
• трассировщик поддерживается лишь для архитектур x86, x86_64

Как это работает

Доступ к регистрам железа достигается путём выделения в адресном пространстве окна, все операции записи или чтения в котором транслируются в соответствующие команды на шине. Трассировшик внедрён в функцию __ioremap() и будет вызван соответственно в любой момент, когда драйвер запросит выделение окна.

В итоге событие запроса окна и все последующие обращения к этому окну будут записаны во внутреннем логе трассировщика, так как любое обращение будет вызывать исключение Page Fault, и ядро вынуждено его обрабатывать. Перед записью запрос декодируется таким образом, чтобы выделить операцию (чтение или запись), длину операнда и его значение.

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

Пример использования

Вначале необходимо в файле кофигурации ядра включить необходимый модуль с помощью опции:

CONFIG_MMIOTRACE=y

По умолчанию трассировщик не активен. Для его активации необходимо выполнить следующие команды в консоли:

# Монтируем debugfs
mount -t debugfs debugfs /sys/kernel/debug
# Активируем трассировщик
echo mmiotrace > /sys/kernel/debug/tracing/current_tracer
# Перенаправляем лог в файл
cat /sys/kernel/debug/tracing/trace_pipe > mylog.txt &
# Здесь мы загружаем драйвер, ввод-вывод которого хочется отследить
...
# Останавливаем трассировщик
echo nop > /sys/kernel/debug/tracing/current_tracer

Практическое пособие

За основу возьмём драйвер High Speed UART на SoC от Intel. Выполним такие команды:

mount -t debugfs none /sys/kernel/debug/

echo mmiotrace > /sys/kernel/debug/tracing/current_tracer
echo 1 > /sys/kernel/debug/tracing/tracing_on

echo "0000:00:18.1" > "/sys/bus/pci/drivers/intel-lpss/unbind"
echo "0000:00:18.1" > "/sys/bus/pci/drivers/intel-lpss/bind"

Последние две команды нужны, чтобы вызвать заново ->probe() драйвера.

Вывод в лог будет выглядеть примерно так:

[ 178.024544] in mmio_trace_init
[ 178.065507] mmiotrace: Disabling non-boot CPUs…
[ 178.080558] Cannot set affinity for irq 169
[ 178.086384] smpboot: CPU 1 is now offline
[ 178.100507] mmiotrace: CPU1 is down.
[ 178.110047] smpboot: CPU 2 is now offline
[ 178.119028] mmiotrace: CPU2 is down.
[ 178.127165] smpboot: CPU 3 is now offline
[ 178.134891] mmiotrace: CPU3 is down.
[ 178.138912] mmiotrace: enabled.
[ 178.147690] in mmio_trace_start
[ 178.151974] mmiotrace: Unmapping ffffc900007ae000.
[ 178.160092] mmiotrace: Unmapping ffffc900007ac000.
[ 178.170893] mmiotrace: Unmapping ffffc900007aa000.
[ 178.178683] mmiotrace: ioremap_*(0x9242e200, 0x100) = ffffc900007dc200
[ 178.186279] mmiotrace: ioremap_*(0x9242e800, 0x800) = ffffc900007de800
[ 178.195682] idma64 idma64.9: Found Intel integrated DMA 64-bit
[ 178.207663] mmiotrace: ioremap_*(0x9242e000, 0x200) = ffffc900007fa000
[ 178.217141] dw-apb-uart.9: ttyS1 at MMIO 0x9242e000 (irq = 5, base_baud = 115200) is a 16550A

Перенаправим вывод в файл:

cat /sys/kernel/debug/tracing/trace_pipe >/tmp/t &

Файл уже ненулевой длины будет, давайте взглянем на его содержимое:

VERSION 20070824
UNMAP 178.157353 -1 0x0 0
UNMAP 178.165484 -1 0x0 0
UNMAP 178.176279 -1 0x0 0
MAP 178.186036 1 0x9242e200 0xffffc900007dc200 0x100 0x0 0
R 4 178.186064 1 0x9242e2fc 0x11 0x0 0
W 4 178.186067 1 0x9242e204 0x7 0x0 0
W 4 178.186069 1 0x9242e240 0x9242e000 0x0 0
W 4 178.186071 1 0x9242e244 0x0 0x0 0
R 4 178.186125 1 0x9242e200 0x3d090240 0x0 0
R 4 178.186160 1 0x9242e210 0x800 0x0 0
R 4 178.186164 1 0x9242e214 0x800 0x0 0
MAP 178.195481 2 0x9242e800 0xffffc900007de800 0x800 0x0 0
W 4 178.195510 2 0x9242eb98 0x0 0x0 0
W 4 178.195512 2 0x9242eb10 0x300 0x0 0
W 4 178.195515 2 0x9242eb18 0x300 0x0 0
W 4 178.195517 2 0x9242eb20 0x300 0x0 0
W 4 178.195519 2 0x9242eb28 0x300 0x0 0
W 4 178.195521 2 0x9242eb30 0x300 0x0 0
R 4 178.195525 2 0x9242eb98 0x0 0x0 0
MAP 178.216881 3 0x9242e000 0xffffc900007fa000 0x200 0x0 0
R 4 178.216924 1 0x9242e200 0x3d090240 0x0 0
W 4 178.216926 1 0x9242e200 0x3d090241 0x0 0
R 4 178.216931 1 0x9242e200 0x3d090241 0x0 0
W 4 178.216933 1 0x9242e200 0xbd090241 0x0 0
R 4 178.216940 3 0x9242e0f8 0x3331342a 0x0 0
R 4 178.216943 3 0x9242e0f4 0x43f32 0x0 0
W 4 178.229863 3 0x9242e010 0x0 0x0 0

Формат описан в документации, и в принципе интуитивно понятен. Нас интересуют строки MAP[ping], R[ead], W[rite], которые соотвественно определяют адреса окон ввода-вывода, данные чтения из регистра и записи. Поскольку не очень удобно отслеживать только числа, я написал простой парсер, преобразующий адреса в имена регистров.

R 178.216940 UCV 0x3331342a
R 178.216943 CPR 0x00043f32
W 178.229863 MCR 0x00

Так читать значительно удобнее (не относящиеся напрямую к UART регистры, как-то DMA и расширения, удалены из вывода, на самом деле они присутствуют в виде адресов для дальнейшей обработки)!

Для проверки запустим простую команду stty -F /dev/ttyS1 921600.

W 335.706380 FCR 0x01
W 335.706391 FCR 0x07
W 335.706393 FCR 0x00
R 335.706397 LSR 0x60
R 335.706401 RX 0x00
R 335.706405 IIR 0x01
R 335.706408 MSR 0x00
R 335.706413 LSR 0x60
R 335.706417 LSR 0x60
W 335.706419 IER 0x02
R 335.706422 LCR 0x00
R 335.706426 IIR 0x02
W 335.706428 IER 0x00
W 335.706431 IER 0x02
R 335.706435 LCR 0x00
R 335.706440 IIR 0x02
W 335.706442 IER 0x00
W 335.706535 LCR 0x03
W 335.706541 MCR 0x08
W 335.706543 IER 0x02
R 335.706547 LSR 0x60
R 335.706550 IIR 0x02
W 335.706552 IER 0x00
R 335.706561 IIR 0x01
R 335.706565 LSR 0x60
R 335.706568 RX 0x00
R 335.706572 IIR 0x01
R 335.706575 MSR 0x00
W 335.706754 IER 0x05
W 335.706757 LCR 0x93
W 335.706760 DLL 0x0c
W 335.706762 DLM 0x00
W 335.706764 LCR 0x13
W 335.706766 FCR 0x01
W 335.706768 FCR 0x81
W 335.706771 MCR 0x08
W 335.706778 MCR 0x0b
R 335.706850 LSR 0x60
W 335.706918 IER 0x05
W 335.706920 LCR 0x93
W 335.706923 DLL 0x01
W 335.706925 DLM 0x00
W 335.706927 LCR 0x13
W 335.706929 FCR 0x01
W 335.706931 FCR 0x81
W 335.706934 MCR 0x0b
R 335.707047 LSR 0x60
W 335.707071 IER 0x00
R 335.707078 LSR 0x60
W 335.707080 MCR 0x08
W 335.707083 IER 0x00
W 335.707189 MCR 0x00
R 335.707196 LCR 0x13
W 335.707198 LCR 0x13
W 335.707200 FCR 0x01
W 335.707203 FCR 0x07
W 335.707205 FCR 0x00
R 335.707221 RX 0x00
R 335.707268 IIR 0x01

Так мы наглядно увидели как программируется UART 8250 в ядре Linux. Соответственно можно применять в отладке драйвера, когда не совсем понятно по какому пути идёт алгоритм, так как зависит от вычитанных данных из устройства.

Если не получается

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