[archlinux.org.ru] Способы нестандартной отладки/трассировки

Статьи и публикации
Ответить
indeviral
Аватара пользователя
Сообщения: 176
Зарегистрирован: 15.08.2022

#

Восстановленная статья с ресурса archlinux.org.ru
Автор: vasek


Способы нестандартной отладки/трассировки Х-ов, unit-ов systemd, udev, модулей

Иногда возникают ситуации, в которых при решении проблем не хватает информации, точнее логов journal и Xorg не достаточно, а как получить дополнительно не понятно.
Отдельной подборки материалов на данную тематику, где бы все это было в одном месте, нет … да, в принципе, и нагуглить это не просто.
Вот и решил описать некоторые способы добычи этой информации.

1. Начало

Начнем с самого простого udev, который имеет конфигурационный файл /etc/udev/udev.conf, в котором есть одна строчка
#udev_log=info
которая и определяет уровень логирования udev - по дефолту стоит уровень info. Если мы хотим больше информации, то следует изменить эту строчку на следующую
udev_log=debug
В результате этого уровень логирования journal возрастет, чтобы не утонуть в логах их можно фильтровать, например, так:
journalctl -b | grep -i udev #или по другому. 
Не забываем после отладки вернуть все на место.

2. Отладка unit systemd

2.1 Стандартный простой способ

Имеется стандартный простой способ для увеличения логирования отдельного системного unit,
находящегося в директории /usr/lib/systemd/system/ - необходимо добавить опцию -d (от слова debug) в строке запуска юнита.
Например, для /usr/lib/systemd/system/bluetooth.service имеем
cat /usr/lib/systemd/system/bluetooth.service | grep ExecStart 
ExecStart=/usr/lib/bluetooth/bluetoothd
а чтобы увеличить логирование добавим опцию **-d** и строка примет вид
ExecStart=/usr/lib/bluetooth/bluetoothd -d
и не забываем
systemctl daemon-reload # при необходимости и restart сервиса
Отмечу, что иногда это не срабатывает, да и порой не дает нужной информации. В этом случае лучше использовать более тяжелый инструмент, который описан далее.

2.2. Применение strace

Для этого способа используем следующий запуск unit, например, имеем
cat /usr/lib/systemd/system/systemd-vconsole-setup.service | grep ExecStart
ExecStart=/usr/lib/systemd/systemd-vconsole-setup
и после изменения строка примет вид
ExecStart=/usr/bin/strace -f -tt -o /run/%N.strace /lib/systemd/systemd-vconsole-setup
используемые опции strace в зависимости от ситуации, а имя лога на Ваш вкус.
И не забываем systemctl daemon-reload (при необходимости и restart сервиса)

PS- Разумеется можно редактировать тот же сервис в другой стандартной директории /etc/systemd/system/ и не забываем потом вернуть все обратно ...

3. Xorg

Xorg - здесь имеется несколько способов - и простые и сложные. Простые приводят к простому увеличению логирования от которого мало толку,
а потому их не описываю. Приведу не стандартный способ трассировки с использованием strace.
Если используется DM, то лучше его временно отключить и использовать .xinitrc (то есть startx).
Загружаемся в текстовую консоль (Х-ы не запускаем), меняем файл **/etc/X11/xinit/xserverrc**, например, приводим к виду (изменив на нужное)
cat /etc/X11/xinit/xserverrc
#!/bin/sh
#exec /usr/bin/X -nolisten tcp "$@"
exec /usr/bin/strace -f -T -o /home/vasek/strace_X.log /usr/bin/X -nolisten tcp "$@"
PS - делаем отладку по усмотрению, в зависимости от ситуации … например, в данном случае используется опция -**T**,
которая позволяет посмотреть как долго выполняется каждый системный вызов. Название лога на Ваше усмотрение.

Сохраняем и стартуем Х-ы - не пугаемся, время загрузки увеличится, **НО сразу после загрузки убиваем (выходим) Х-ы** и приводим файл /etc/X11/xinit/xserverrc к нормальному виду,
точнее возвращаем все на место (Х-ы нужно убить, так как они запущены через strace, убить которй не получится - вообщем проще убить Х-ы и вернуться в текстовую консоль)
cat /etc/X11/xinit/xserverrc
#!/bin/sh
exec /usr/bin/X -nolisten tcp "$@"
Можно просто не нужную строку закоментировать, а нужную раскоментировать.
Снова загружаем Х-ы и анализируем **файл strace_X.log**, в котором в конце каждой строки будет указано время выполнения системного вызова, типа такого
9218  openat(AT_FDCWD, "/proc/9232/cmdline", O_RDONLY) = 27 <0.000027>
9218  read(27, "tilix\0", 4097)         = 6 <0.000019>
9218  close(27)                         = 0 <0.000015>
… ну и ищем строки с большим временем … (здесь же будут и проги автозапуска, например, здесь показан tilix)
Повторюсь, использование опций strace зависит от обстоятельств расследования.

При желании вместо strace можно использовать более мощный комбайн - sysdig, но работать с ним сложнее.

4. Драйвера/модули

И в конце привожу, как можно получить информацию в случае проблем с драйверами/модулями - обычно возникает при выходе из suspend/hibernate … иногда и при загрузке.
Способ заключается в передаче параметра ядра **initcall_debug** при загрузке, в результате чего в dmesg будет сохранена информация каждого initcall,
который используется для инициализации статически связанных драйверов ядра и подсистем, и будет возможность получить информацию о времени загрузки этих драйверов/модулей.
Вообщем, прописываем параметр initcall_debug, лучше прямо при загрузке, перейдя в консоль Grub (нажимаем e в меню Grub) и загружаемся.
В логах будут строки о загрузке модулей, они разбросаны, искать их тяжело, но для одного модуля, например, ath3k можно посмотреть так
dmesg | grep ath3k
[   12.594842] calling  ath3k_driver_init+0x0/0x1000 [ath3k] @ 326
[   13.101284] usbcore: registered new interface driver ath3k
[   13.101298] initcall ath3k_driver_init+0x0/0x1000 [ath3k] returned 0 after 23011 usecs
В последней строчке видим returned 0 (то есть успешно) и затрачено времени 23011 микросекунд.
Но в одной статье приведена интересная команда для вытаскивания этой информации из dmesg
dmesg -s 128000 | grep "initcall" | sed "s/\(.*\)after\(.*\)/\2 \1/g" | sort -n
и получим отсортированный вывод с одной строчкой для каждого модуля, типа такого
0 usecs [    0.971675] initcall vga_arb_device_init+0x0/0x25e returned 0
0 usecs [    0.971686] initcall cn_init+0x0/0xe0 returned 0
0 usecs [    0.971697] initcall pm860x_i2c_init+0x0/0x30 returned 0
………….
13 usecs [   11.832572] initcall init_soundcore+0x0/0x1000 [soundcore] returned 0
14 usecs [    1.175133] initcall pid_namespaces_init+0x0/0x40 returned 0
14 usecs [    1.289965] initcall dw_pci_driver_init+0x0/0x1a returned 0
14 usecs [    1.344490] initcall clk_debug_init+0x0/0x116 returned 0
14 usecs [    1.509541] initcall serio_init+0x0/0x1000 [serio] returned 0
15 usecs [    1.177037] initcall zs_init+0x0/0x77 returned 0
... и так далее …  
Один нюанс - использование initcall_debug увеличивает количество сообщений, генерируемых ядром во время загрузки системы.
Рекомендуют увеличить размер буфера журнала printk, чтобы избежать переполнения буфера журнала.
Правда я с таким не сталкивался.

Дополнение

Уточнение в части информативности Xorg - конечно, не совсем удобно редактировать файл /etc/X11/xinit/xserverrc, чтобы прописать запуск strace,
а затем убивать Х-ы …. намного удобнее ничего этого не делать, а просто из текстовой консоли запустить sysdig, а затем startx …,
то есть загружаемся в текстовую консоль и далее ...
# sysdig -w ~/sysdig.log
стартуем Х-ы, после загрузки убиваем sysdig, для чего сначала узнаем PID sysdig, а потом к этому PID применяем kill ...
$ pidof sysdig
28360
# kill 28360
Проверяем
$ pidof sysdig
… пусто …
Для чего убивать sysdig - утилита запущена и собирает информацию - если процесс не убить, то лог sysdig будет постоянно увеличиваться в размерах и может забить весь диск.
Посмотрим на созданный лог и его объем
$ du -m ~/sysdig.log
**18** /home/vasek/sysdig.log
И видим, что файл довольно большой, 18М (это всего то за несколько секунд), но в нем записаны все процессы/события за данный промежуток времени.
Анализируя данный файл можно получить любую информацию, но для этого нужно знать как это делать, то есть нужно изучать sysdig.
В принципе sysdig можно успешно использовать и в работающей системе, чтобы найти возможные проблемы. https://habr.com/ru/company/selectel/blog/222839/ для начального ознакомления с sysdig

Ошибки в тексте-неповторимый стиль автора©

vasek
Сообщения: 358
Зарегистрирован: 31.08.2022

#

В части пункта 2
2. Отладка unit systemd
2.1 Стандартный простой способ

Вообще то добавление опции -d не всегда работает, да и редко кто это использует …
А, главное, заметил только сейчас, что почему то не указал другие способы увеличения логирования systemd … а поэтому решили переписать этот пункт.
Новая редакция пункта 2
2. Отладка systemd
2.1. Изменение уровня логирования
2.1.1. На глобальном уровне.
2.1.1.1. При загрузке системы (возможны 2 способа - через конфиг или через параметр ядра)
Через конфиг: отредактировать файл /etc/systemd/system.conf
Заменить строку #LogLevel=info на LogLevel=debug
Через параметр ядра: загрузиться с параметром systemd.log_level=debug
2.1.1.2. В загруженной системе, используя команду sudo systemd-analyze set-log-level debug
Пример.
Смотрим какой уровень логирования установлен: systemctl log-level (по дефолту - info)
Установим debug: sudo systemd-analyze set-log-level debug
Проверяем :
systemctl log-level
debug

2.1.2. На локальном уровне, для конкретного юнита (срабатывает не всегда)
Добавить опцию d (от слова debug) в строке запуска юнита, например, для bluetooth.service
ExecStart=/usr/lib/systemd/system/bluetooth.service -d
и выполнить
systemctl daemon-reload
systemctl restart bluetooth

Для более детального анализа приходиться использовать более тяжелые инструменты, описанные далее.

2.2. Применение strace
… и далее по тексту ...

Ошибки не исчезают с опытом - они просто умнеют

Ответить