Трассировщик ввода-вывода в ядре 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"
Вывод в лог будет выглядеть примерно так:
[ 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_*(0×9242e200, 0×100) = ffffc900007dc200
[ 178.186279] mmiotrace: ioremap_*(0×9242e800, 0×800) = ffffc900007de800
[ 178.195682] idma64 idma64.9: Found Intel integrated DMA 64-bit
[ 178.207663] mmiotrace: ioremap_*(0×9242e000, 0×200) = ffffc900007fa000
[ 178.217141] dw-apb-uart.9: ttyS1 at MMIO 0×9242e000 (irq = 5, base_baud = 115200) is a 16550A
Перенаправим вывод в файл:
cat /sys/kernel/debug/tracing/trace_pipe >/tmp/t &
Файл уже не нулевой длины будет, давайте взглянем на его содержимое:
VERSION 20070824
UNMAP 178.157353 -1 0×0 0
UNMAP 178.165484 -1 0×0 0
UNMAP 178.176279 -1 0×0 0
MAP 178.186036 1 0×9242e200 0xffffc900007dc200 0×100 0×0 0
R 4 178.186064 1 0×9242e2fc 0×11 0×0 0
W 4 178.186067 1 0×9242e204 0×7 0×0 0
W 4 178.186069 1 0×9242e240 0×9242e000 0×0 0
W 4 178.186071 1 0×9242e244 0×0 0×0 0
R 4 178.186125 1 0×9242e200 0×3d090240 0×0 0
R 4 178.186160 1 0×9242e210 0×800 0×0 0
R 4 178.186164 1 0×9242e214 0×800 0×0 0
MAP 178.195481 2 0×9242e800 0xffffc900007de800 0×800 0×0 0
W 4 178.195510 2 0×9242eb98 0×0 0×0 0
W 4 178.195512 2 0×9242eb10 0×300 0×0 0
W 4 178.195515 2 0×9242eb18 0×300 0×0 0
W 4 178.195517 2 0×9242eb20 0×300 0×0 0
W 4 178.195519 2 0×9242eb28 0×300 0×0 0
W 4 178.195521 2 0×9242eb30 0×300 0×0 0
R 4 178.195525 2 0×9242eb98 0×0 0×0 0
MAP 178.216881 3 0×9242e000 0xffffc900007fa000 0×200 0×0 0
R 4 178.216924 1 0×9242e200 0×3d090240 0×0 0
W 4 178.216926 1 0×9242e200 0×3d090241 0×0 0
R 4 178.216931 1 0×9242e200 0×3d090241 0×0 0
W 4 178.216933 1 0×9242e200 0xbd090241 0×0 0
R 4 178.216940 3 0×9242e0f8 0×3331342a 0×0 0
R 4 178.216943 3 0×9242e0f4 0×43f32 0×0 0
W 4 178.229863 3 0×9242e010 0×0 0×0 0
Формат описан в документации, и в принципе интуитивно понятен. Нас интересуют строки MAP[ping], R[ead], W[rite], которые соотвественно определяют адреса окон ввода-вывода, данные чтения из регистра и записи. Поскольку не очень удобно отслеживать только числа, я написал простой парсер, преобразующий адреса в имена регистров.
R 178.216940 UCV 0×3331342a
R 178.216943 CPR 0×00043f32
W 178.229863 MCR 0×00
Так читать значительно удобнее (не относящиеся напрямую к UART регистры, как-то DMA и расширения, удалены из вывода, на самом деле они присутствуют в виде адресов для дальнейшей обработки)!
Для проверки запустим простую команду stty -F /dev/ttyS1 921600.
W 335.706380 FCR 0×01
W 335.706391 FCR 0×07
W 335.706393 FCR 0×00
R 335.706397 LSR 0×60
R 335.706401 RX 0×00
R 335.706405 IIR 0×01
R 335.706408 MSR 0×00
R 335.706413 LSR 0×60
R 335.706417 LSR 0×60
W 335.706419 IER 0×02
R 335.706422 LCR 0×00
R 335.706426 IIR 0×02
W 335.706428 IER 0×00
W 335.706431 IER 0×02
R 335.706435 LCR 0×00
R 335.706440 IIR 0×02
W 335.706442 IER 0×00
W 335.706535 LCR 0×03
W 335.706541 MCR 0×08
W 335.706543 IER 0×02
R 335.706547 LSR 0×60
R 335.706550 IIR 0×02
W 335.706552 IER 0×00
R 335.706561 IIR 0×01
R 335.706565 LSR 0×60
R 335.706568 RX 0×00
R 335.706572 IIR 0×01
R 335.706575 MSR 0×00
W 335.706754 IER 0×05
W 335.706757 LCR 0×93
W 335.706760 DLL 0×0c
W 335.706762 DLM 0×00
W 335.706764 LCR 0×13
W 335.706766 FCR 0×01
W 335.706768 FCR 0×81
W 335.706771 MCR 0×08
W 335.706778 MCR 0×0b
R 335.706850 LSR 0×60
W 335.706918 IER 0×05
W 335.706920 LCR 0×93
W 335.706923 DLL 0×01
W 335.706925 DLM 0×00
W 335.706927 LCR 0×13
W 335.706929 FCR 0×01
W 335.706931 FCR 0×81
W 335.706934 MCR 0×0b
R 335.707047 LSR 0×60
W 335.707071 IER 0×00
R 335.707078 LSR 0×60
W 335.707080 MCR 0×08
W 335.707083 IER 0×00
W 335.707189 MCR 0×00
R 335.707196 LCR 0×13
W 335.707198 LCR 0×13
W 335.707200 FCR 0×01
W 335.707203 FCR 0×07
W 335.707205 FCR 0×00
R 335.707221 RX 0×00
R 335.707268 IIR 0×01
Так мы наглядно увидели как программируется UART 8250 в ядре Linux. Соответственно можно применять в отладке драйвера устройств, когда не совсем понятно по какому пути идёт алгоритм, так как зависит от вычитанных данных из устройства.
Если не получается
Чуть более детально всё описано в документации, к которой имеет смысл обратиться. Так же обратите внимание, что в силу своей реализации трассировщик может не работать. Так, в частности, я обнаружил регрессию в новых ядрах.
